Netbackup tried to delete the same snapshot twice

Question

Hello,I encounter a issue during the backup of one of my VMs which ends in partial because NBU deletes twice the generated snapshot; the first one works, the second one fails.The error reported by the vcenter would be "normal" in the sense that netbackup tries to delete the snapshot twice, the first time succeeds, the second time fails because the snapshot no longer exists. I just manually validate that I can make a snapshot and delete it on this VM without error (and without the attempt does generate two tests). The behavior is different on other VMs, netbackup does not try to delete the snapshot twiceAny advice will be apreciated&nbsp;Failed to delete snapreplicapair file [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.E00001.srv.entreprise.int_1543444207.1.0.snapreplicapair] return value[-1]&nbsp;&nbsp; &nbsp;&nbsp;&nbsp; &nbsp;&nbsp;&nbsp; &nbsp;&nbsp;&nbsp; &nbsp;&nbsp;&nbsp; &nbsp;&nbsp;&nbsp; &nbsp;error [2] [No such file or directory]23:33:34.738 [16748.15952] &lt;4&gt; keep_alive_and_snapshot_control: Starting keep alive thread.23:33:34.738 [16748.15952] &lt;2&gt; deleteReference: reference not found in the list23:33:34.738 [16748.15952] &lt;4&gt; unlockSnapshot: Delete reference: status [-4]23:33:34.738 [16748.15952] &lt;2&gt; writeSnapshotLockFile: Writing type[2] refcount[0]23:33:34.738 [16748.15952] &lt;2&gt; writeSnapshotLockFile: Writing Flags [0] [0]23:33:34.738 [16748.15952] &lt;2&gt; writeSnapshotLockFile: Writing Last addReffernt Time [Thu Jan 01 01:00:00 1970 ]23:33:34.738 [16748.15952] &lt;2&gt; writeSnapshotLockFile: Writing Last Hostname []23:33:34.848 [16748.15952] &lt;2&gt; getFileName: FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\E00001.srv.entreprise.int_1543444207_copy1.lock]23:33:34.848 [16748.15952] &lt;2&gt; unlockSnapshot: file[C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\E00001.srv.entreprise.int_1543444207_copy1.lock] : zero reference count23:33:34.848 [16748.15952] &lt;4&gt; unlockSnapshot: Released snapshot lock: status [0]23:33:34.848 [16748.15952] &lt;4&gt; do_post_processing: Deleting snapshot lock files from client for id [E00001.srv.entreprise.int_1543444207] and copy_number [1]23:33:34.848 [16748.15952] &lt;2&gt; getFileName: FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\E00001.srv.entreprise.int_1543444207_copy1.lock]23:33:34.848 [16748.15952] &lt;2&gt; deleteSnapshotLockFile: Renamed lock file from [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\E00001.srv.entreprise.int_1543444207_copy1.lock] to [\sgbc.] for deletion23:33:34.848 [16748.15952] &lt;2&gt; deleteSnapshotLockFile: File[\sgbc.] delete: status[0]Thank you

lowell_palecek · Answer

I'm not sure you're showing the relevant log snippet. This looks like a portion of the bpfis log, correct? The files in the fi_cntl folder are used for managing a snapshot across processes. They are not the snapshot itself. I don't think a failure here causes a non-zero backup status.
Please show the "logparams" and exit status lines from the log for this pid and any other pid that contains the snapshot timestamp 1543444207. (E00001.srv.entreprise.int_1543444207 is the "fis id" in the same client_timestamp as a backup id.)

bogdanl · Answer

Hello Lowell,Thank you for your reply, attached are the complete bpfis logs

lowell_palecek · Answer

There is only one deletion of this snapshot:
&gt;23:33:34.598 [16748.15952] &lt;2&gt; onlfi_vfms_logf: INF - vfm_thaw: delete snapshot ......&gt;23:33:34.738 [16748.15952] &lt;4&gt; onlfi_thaw: INF - do_thaw return value: 0
Moreover, there is no error here. Both the "bpfis create" and "bpfis delete" processes for this snapshot finished with status 0:
&gt;23:31:23.234 [7912.15840] &lt;4&gt; bpfis Exit: INF - EXIT STATUS 0: the requested operation was successfully completed&gt;23:33:35.269 [16748.15952] &lt;4&gt; bpfis Exit: INF - EXIT STATUS 0: the requested operation was successfully completed
What failure are you seeing and where are you seeing it?

bogdanl · Answer

Hello,Please see below&nbsp;8&nbsp;déc.&nbsp;2018&nbsp;19:30:55&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;WaitForTaskComplete:&nbsp;The&nbsp;object&nbsp;'vim.vm.Snapshot:snapshot-43251'&nbsp;has&nbsp;already&nbsp;been&nbsp;deleted&nbsp;or&nbsp;has&nbsp;not&nbsp;been&nbsp;completely&nbsp;created&nbsp;&lt;31&gt;8&nbsp;déc.&nbsp;2018&nbsp;19:30:55&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;WaitForTaskComplete:&nbsp;SYM_VMC_ERROR:&nbsp;&nbsp;TASK_REACHED_ERROR_STATE8&nbsp;déc.&nbsp;2018&nbsp;19:30:55&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;SYM_VMC_ERROR:&nbsp;&nbsp;TASK_REACHED_ERROR_STATE8&nbsp;déc.&nbsp;2018&nbsp;19:30:56&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;Request&nbsp;status&nbsp;12.INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;&lt;ManagedObjectNotFoundFault&nbsp;xmlns="urn:vim25"&nbsp;xsi:type="ManagedObjectNotFound"&gt;&lt;obj&nbsp;type="VirtualMachineSnapshot"&gt;&lt;/obj&gt;&lt;/ManagedObjectNotFoundFault&gt;8&nbsp;déc.&nbsp;2018&nbsp;19:30:57&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;Request&nbsp;status&nbsp;12.INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;&lt;ManagedObjectNotFoundFault&nbsp;xmlns="urn:vim25"&nbsp;xsi:type="ManagedObjectNotFound"&gt;&lt;obj&nbsp;type="VirtualMachineSnapshot"&gt;&lt;/obj&gt;&lt;/ManagedObjectNotFoundFault&gt;8&nbsp;déc.&nbsp;2018&nbsp;19:30:58&nbsp;-&nbsp;Critical&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;from&nbsp;client&nbsp;brs140_UOB_e06173:&nbsp;do_thaw:&nbsp;Unable&nbsp;to&nbsp;remove&nbsp;virtual&nbsp;machine&nbsp;snapshot,&nbsp;status=6&nbsp;(SYM_VMC_SOAP_ERROR).&nbsp;Error&nbsp;Details:&nbsp;[The&nbsp;object&nbsp;'vim.vm.Snapshot:'&nbsp;has&nbsp;already&nbsp;been&nbsp;deleted&nbsp;or&nbsp;has&nbsp;not&nbsp;been&nbsp;completely&nbsp;created].8&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;Critical&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;from&nbsp;client&nbsp;brs140_UOB_e06173:&nbsp;vfm_thaw:&nbsp;method:&nbsp;VMware_v2,&nbsp;type:&nbsp;FIM,&nbsp;function:&nbsp;VMware_v2_thaw8&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;Critical&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;from&nbsp;client&nbsp;brs140_UOB_e06173:&nbsp;snapshot&nbsp;delete&nbsp;returned&nbsp;status&nbsp;18&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;Info&nbsp;bpfis&nbsp;(pid=3724)&nbsp;done.&nbsp;status:&nbsp;18&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;Delete&nbsp;Snapshot;&nbsp;elapsed&nbsp;time&nbsp;0:02:488&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;Info&nbsp;bpfis&nbsp;(pid=3724)&nbsp;done.&nbsp;status:&nbsp;1:&nbsp;the&nbsp;requested&nbsp;operation&nbsp;was&nbsp;partially&nbsp;successful&nbsp;&nbsp;8&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;Info&nbsp;nbjm&nbsp;(pid=6212)&nbsp;starting&nbsp;backup&nbsp;job&nbsp;(jobid=96463)&nbsp;for&nbsp;client&nbsp;brs140_UOB_e06173,&nbsp;policy&nbsp;ENT_PROD_BOOTDISK,&nbsp;schedule&nbsp;Full8&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;Info&nbsp;nbjm&nbsp;(pid=6212)&nbsp;requesting&nbsp;STANDARD_RESOURCE&nbsp;resources&nbsp;from&nbsp;RB&nbsp;for&nbsp;backup&nbsp;job&nbsp;(jobid=96463,&nbsp;request&nbsp;id:{D78184C3-E36B-410E-BA8C-F2BC652899EF})8&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;requesting&nbsp;resource&nbsp;&nbsp;Disk_HEBDO8&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;requesting&nbsp;resource&nbsp;&nbsp;e00001.srv.entreprise.int.NBU_CLIENT.MAXJOBS.brs140_UOB_e061738&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;requesting&nbsp;resource&nbsp;&nbsp;e00001.srv.entreprise.int.NBU_POLICY.MAXJOBS.ENT_PROD_BOOTDISK8&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;granted&nbsp;resource&nbsp;&nbsp;e00001.srv.entreprise.int.NBU_CLIENT.MAXJOBS.brs140_UOB_e061738&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;granted&nbsp;resource&nbsp;&nbsp;e00001.srv.entreprise.int.NBU_POLICY.MAXJOBS.ENT_PROD_BOOTDISK8&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;granted&nbsp;resource ....8&nbsp;déc.&nbsp;2018&nbsp;18:55:09&nbsp;-&nbsp;granted&nbsp;resource&nbsp;&nbsp;Disk_HEBDO8&nbsp;déc.&nbsp;2018&nbsp;18:55:38&nbsp;-&nbsp;estimated&nbsp;31043986&nbsp;kbytes&nbsp;needed8&nbsp;déc.&nbsp;2018&nbsp;18:55:38&nbsp;-&nbsp;begin&nbsp;Parent&nbsp;Job8&nbsp;déc.&nbsp;2018&nbsp;18:55:38&nbsp;-&nbsp;begin&nbsp;VMware:&nbsp;Start&nbsp;Notify&nbsp;Script8&nbsp;déc.&nbsp;2018&nbsp;18:55:43&nbsp;-&nbsp;Info&nbsp;RUNCMD&nbsp;(pid=15540)&nbsp;started8&nbsp;déc.&nbsp;2018&nbsp;18:55:43&nbsp;-&nbsp;Info&nbsp;RUNCMD&nbsp;(pid=15540)&nbsp;exiting&nbsp;with&nbsp;status:&nbsp;0Operation&nbsp;Status:&nbsp;08&nbsp;déc.&nbsp;2018&nbsp;18:55:43&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;Start&nbsp;Notify&nbsp;Script;&nbsp;elapsed&nbsp;time&nbsp;0:00:058&nbsp;déc.&nbsp;2018&nbsp;18:55:43&nbsp;-&nbsp;begin&nbsp;VMware:&nbsp;Step&nbsp;By&nbsp;ConditionOperation&nbsp;Status:&nbsp;08&nbsp;déc.&nbsp;2018&nbsp;18:55:43&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;Step&nbsp;By&nbsp;Condition;&nbsp;elapsed&nbsp;time&nbsp;0:00:008&nbsp;déc.&nbsp;2018&nbsp;18:55:43&nbsp;-&nbsp;begin&nbsp;VMware:&nbsp;Read&nbsp;File&nbsp;ListOperation&nbsp;Status:&nbsp;08&nbsp;déc.&nbsp;2018&nbsp;18:55:43&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;Read&nbsp;File&nbsp;List;&nbsp;elapsed&nbsp;time&nbsp;0:00:008&nbsp;déc.&nbsp;2018&nbsp;18:55:43&nbsp;-&nbsp;begin&nbsp;VMware:&nbsp;Create&nbsp;Snapshot8&nbsp;déc.&nbsp;2018&nbsp;18:56:07&nbsp;-&nbsp;started&nbsp;process&nbsp;bpbrm&nbsp;(pid=216)8&nbsp;déc.&nbsp;2018&nbsp;18:56:07&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=216)&nbsp;brs140_UOB_e06173&nbsp;is&nbsp;the&nbsp;host&nbsp;to&nbsp;backup&nbsp;data&nbsp;from8&nbsp;déc.&nbsp;2018&nbsp;18:56:07&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=216)&nbsp;reading&nbsp;file&nbsp;list&nbsp;for&nbsp;client8&nbsp;déc.&nbsp;2018&nbsp;18:56:07&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=216)&nbsp;start&nbsp;bpfis&nbsp;on&nbsp;client8&nbsp;déc.&nbsp;2018&nbsp;18:56:08&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=216)&nbsp;Starting&nbsp;create&nbsp;snapshot&nbsp;processing8&nbsp;déc.&nbsp;2018&nbsp;18:56:08&nbsp;-&nbsp;Info&nbsp;bpfis&nbsp;(pid=5276)&nbsp;Backup&nbsp;started8&nbsp;déc.&nbsp;2018&nbsp;18:56:13&nbsp;-&nbsp;snapshot&nbsp;backup&nbsp;of&nbsp;client&nbsp;brs140_UOB_e06173&nbsp;using&nbsp;method&nbsp;VMware_v28&nbsp;déc.&nbsp;2018&nbsp;18:56:19&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=216)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;&nbsp;Creating&nbsp;snapshot&nbsp;for&nbsp;vCenter&nbsp;server&nbsp;10.209.107.25,&nbsp;ESX&nbsp;host&nbsp;epb666vesx25.brs666.bcrs.fr,&nbsp;BIOS&nbsp;UUID&nbsp;4221d6e3-3298-1346-2cb1-0f3ddaf49dca,&nbsp;Instance&nbsp;UUID&nbsp;50213860-9a8f-7c41-0c7e-8f8aa355441d,&nbsp;Display&nbsp;Name&nbsp;brs140_UOB_e06173,&nbsp;Hostname&nbsp;e06173.srv.entreprise.int&nbsp;8&nbsp;déc.&nbsp;2018&nbsp;18:56:36&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;Create&nbsp;Snapshot;&nbsp;elapsed&nbsp;time&nbsp;0:00:538&nbsp;déc.&nbsp;2018&nbsp;18:56:36&nbsp;-&nbsp;Info&nbsp;bpfis&nbsp;(pid=5276)&nbsp;done.&nbsp;status:&nbsp;08&nbsp;déc.&nbsp;2018&nbsp;18:56:36&nbsp;-&nbsp;Info&nbsp;bpfis&nbsp;(pid=5276)&nbsp;done.&nbsp;status:&nbsp;0:&nbsp;the&nbsp;requested&nbsp;operation&nbsp;was&nbsp;successfully&nbsp;completed8&nbsp;déc.&nbsp;2018&nbsp;18:56:36&nbsp;-&nbsp;end&nbsp;writingOperation&nbsp;Status:&nbsp;08&nbsp;déc.&nbsp;2018&nbsp;18:56:36&nbsp;-&nbsp;end&nbsp;Parent&nbsp;Job;&nbsp;elapsed&nbsp;time&nbsp;0:00:588&nbsp;déc.&nbsp;2018&nbsp;18:56:36&nbsp;-&nbsp;Info&nbsp;nbjm&nbsp;(pid=6212)&nbsp;snapshotid=brs140_UOB_e06173_15442917188&nbsp;déc.&nbsp;2018&nbsp;18:56:36&nbsp;-&nbsp;begin&nbsp;VMware:&nbsp;Policy&nbsp;Execution&nbsp;Manager&nbsp;PreprocessedOperation&nbsp;Status:&nbsp;08&nbsp;déc.&nbsp;2018&nbsp;19:28:12&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;Policy&nbsp;Execution&nbsp;Manager&nbsp;Preprocessed;&nbsp;elapsed&nbsp;time&nbsp;0:31:368&nbsp;déc.&nbsp;2018&nbsp;19:28:12&nbsp;-&nbsp;begin&nbsp;VMware:&nbsp;Validate&nbsp;ImageOperation&nbsp;Status:&nbsp;08&nbsp;déc.&nbsp;2018&nbsp;19:28:17&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;Validate&nbsp;Image;&nbsp;elapsed&nbsp;time&nbsp;0:00:058&nbsp;déc.&nbsp;2018&nbsp;19:28:17&nbsp;-&nbsp;begin&nbsp;VMware:&nbsp;Delete&nbsp;Snapshot8&nbsp;déc.&nbsp;2018&nbsp;19:28:41&nbsp;-&nbsp;started&nbsp;process&nbsp;bpbrm&nbsp;(pid=8320)8&nbsp;déc.&nbsp;2018&nbsp;19:28:42&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;Starting&nbsp;delete&nbsp;snapshot&nbsp;processing8&nbsp;déc.&nbsp;2018&nbsp;19:28:42&nbsp;-&nbsp;Info&nbsp;bpfis&nbsp;(pid=3724)&nbsp;Backup&nbsp;started8&nbsp;déc.&nbsp;2018&nbsp;19:29:43&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;Error&nbsp;504&nbsp;fault:&nbsp;SOAP-ENV:Server&nbsp;[no&nbsp;subcode]8&nbsp;déc.&nbsp;2018&nbsp;19:29:43&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;WaitForTaskComplete:&nbsp;SYM_VMC_ERROR:&nbsp;&nbsp;SOAP_ERROR8&nbsp;déc.&nbsp;2018&nbsp;19:29:43&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;SYM_VMC_ERROR:&nbsp;&nbsp;SOAP_ERROR8&nbsp;déc.&nbsp;2018&nbsp;19:30:34&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;Error&nbsp;504&nbsp;fault:&nbsp;SOAP-ENV:Server&nbsp;[no&nbsp;subcode]8&nbsp;déc.&nbsp;2018&nbsp;19:30:34&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;WaitForTaskComplete:&nbsp;SYM_VMC_ERROR:&nbsp;&nbsp;SOAP_ERROR8&nbsp;déc.&nbsp;2018&nbsp;19:30:34&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;SYM_VMC_ERROR:&nbsp;&nbsp;SOAP_ERROR8&nbsp;déc.&nbsp;2018&nbsp;19:30:55&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;WaitForTaskComplete:&nbsp;The&nbsp;object&nbsp;'vim.vm.Snapshot:snapshot-43251'&nbsp;has&nbsp;already&nbsp;been&nbsp;deleted&nbsp;or&nbsp;has&nbsp;not&nbsp;been&nbsp;completely&nbsp;created&nbsp;&lt;31&gt;8&nbsp;déc.&nbsp;2018&nbsp;19:30:55&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;WaitForTaskComplete:&nbsp;SYM_VMC_ERROR:&nbsp;&nbsp;TASK_REACHED_ERROR_STATE8&nbsp;déc.&nbsp;2018&nbsp;19:30:55&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;SYM_VMC_ERROR:&nbsp;&nbsp;TASK_REACHED_ERROR_STATE8&nbsp;déc.&nbsp;2018&nbsp;19:30:56&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;Request&nbsp;status&nbsp;12.INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;&lt;ManagedObjectNotFoundFault&nbsp;xmlns="urn:vim25"&nbsp;xsi:type="ManagedObjectNotFound"&gt;&lt;obj&nbsp;type="VirtualMachineSnapshot"&gt;&lt;/obj&gt;&lt;/ManagedObjectNotFoundFault&gt;8&nbsp;déc.&nbsp;2018&nbsp;19:30:57&nbsp;-&nbsp;Info&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;Request&nbsp;status&nbsp;12.INF&nbsp;-&nbsp;vmwareLogger:&nbsp;removeVirtualMachineSnapshot:&nbsp;&lt;ManagedObjectNotFoundFault&nbsp;xmlns="urn:vim25"&nbsp;xsi:type="ManagedObjectNotFound"&gt;&lt;obj&nbsp;type="VirtualMachineSnapshot"&gt;&lt;/obj&gt;&lt;/ManagedObjectNotFoundFault&gt;8&nbsp;déc.&nbsp;2018&nbsp;19:30:58&nbsp;-&nbsp;Critical&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;from&nbsp;client&nbsp;brs140_UOB_e06173:&nbsp;do_thaw:&nbsp;Unable&nbsp;to&nbsp;remove&nbsp;virtual&nbsp;machine&nbsp;snapshot,&nbsp;status=6&nbsp;(SYM_VMC_SOAP_ERROR).&nbsp;Error&nbsp;Details:&nbsp;[The&nbsp;object&nbsp;'vim.vm.Snapshot:'&nbsp;has&nbsp;already&nbsp;been&nbsp;deleted&nbsp;or&nbsp;has&nbsp;not&nbsp;been&nbsp;completely&nbsp;created].8&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;Critical&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;from&nbsp;client&nbsp;brs140_UOB_e06173:&nbsp;vfm_thaw:&nbsp;method:&nbsp;VMware_v2,&nbsp;type:&nbsp;FIM,&nbsp;function:&nbsp;VMware_v2_thaw8&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;Critical&nbsp;bpbrm&nbsp;(pid=8320)&nbsp;from&nbsp;client&nbsp;brs140_UOB_e06173:&nbsp;snapshot&nbsp;delete&nbsp;returned&nbsp;status&nbsp;18&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;Info&nbsp;bpfis&nbsp;(pid=3724)&nbsp;done.&nbsp;status:&nbsp;18&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;Delete&nbsp;Snapshot;&nbsp;elapsed&nbsp;time&nbsp;0:02:488&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;Info&nbsp;bpfis&nbsp;(pid=3724)&nbsp;done.&nbsp;status:&nbsp;1:&nbsp;the&nbsp;requested&nbsp;operation&nbsp;was&nbsp;partially&nbsp;successful8&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;end&nbsp;writingOperation&nbsp;Status:&nbsp;18&nbsp;déc.&nbsp;2018&nbsp;19:31:05&nbsp;-&nbsp;begin&nbsp;VMware:&nbsp;End&nbsp;Notify&nbsp;Script8&nbsp;déc.&nbsp;2018&nbsp;19:31:10&nbsp;-&nbsp;Info&nbsp;RUNCMD&nbsp;(pid=16100)&nbsp;started8&nbsp;déc.&nbsp;2018&nbsp;19:31:10&nbsp;-&nbsp;Info&nbsp;RUNCMD&nbsp;(pid=16100)&nbsp;exiting&nbsp;with&nbsp;status:&nbsp;0Operation&nbsp;Status:&nbsp;08&nbsp;déc.&nbsp;2018&nbsp;19:31:10&nbsp;-&nbsp;end&nbsp;VMware:&nbsp;End&nbsp;Notify&nbsp;Script;&nbsp;elapsed&nbsp;time&nbsp;0:00:05Operation&nbsp;Status:&nbsp;1The&nbsp;requested&nbsp;operation&nbsp;was&nbsp;partially&nbsp;successful&nbsp; (1)

lowell_palecek · Answer

The first bpfis logs you provided were from inside the VM. They were for MS-Windows backups of C:\ and D:\.
Your new post is the job details from a VMware backup. To investigate further would require studying verbose bpfis logs from the backup host, and also VMware logs.
Two points about the message "... has already been deleted or has not been completely created."
1. Consider the "or" case. In the message.
2. The message comes from VMware, not NetBackup. I don't know what it means.
I think you need to open a support case for the level of effort that's going to be required to sort out the issues.
FWIW, the following is your post with the missing line breaks added.
8 déc. 2018 18:55:09 - Info nbjm (pid=6212) starting backup job (jobid=96463) for client brs140_UOB_e06173, policy ENT_PROD_BOOTDISK, schedule Full8 déc. 2018 18:55:09 - Info nbjm (pid=6212) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=96463, request id:{D78184C3-E36B-410E-BA8C-F2BC652899EF})8 déc. 2018 18:55:09 - requesting resource&nbsp; Disk_HEBDO8 déc. 2018 18:55:09 - requesting resource&nbsp; e00001.srv.entreprise.int.NBU_CLIENT.MAXJOBS.brs140_UOB_e061738 déc. 2018 18:55:09 - requesting resource&nbsp; e00001.srv.entreprise.int.NBU_POLICY.MAXJOBS.ENT_PROD_BOOTDISK8 déc. 2018 18:55:09 - granted resource&nbsp; e00001.srv.entreprise.int.NBU_CLIENT.MAXJOBS.brs140_UOB_e061738 déc. 2018 18:55:09 - granted resource&nbsp; e00001.srv.entreprise.int.NBU_POLICY.MAXJOBS.ENT_PROD_BOOTDISK8 déc. 2018 18:55:09 - granted resource ....8 déc. 2018 18:55:09 - granted resource&nbsp; Disk_HEBDO8 déc. 2018 18:55:38 - estimated 31043986 kbytes needed8 déc. 2018 18:55:38 - begin Parent Job8 déc. 2018 18:55:38 - begin VMware: Start Notify Script8 déc. 2018 18:55:43 - Info RUNCMD (pid=15540) started8 déc. 2018 18:55:43 - Info RUNCMD (pid=15540) exiting with status: 0Operation Status: 08 déc. 2018 18:55:43 - end VMware: Start Notify Script; elapsed time 0:00:058 déc. 2018 18:55:43 - begin VMware: Step By ConditionOperation Status: 08 déc. 2018 18:55:43 - end VMware: Step By Condition; elapsed time 0:00:008 déc. 2018 18:55:43 - begin VMware: Read File ListOperation Status: 08 déc. 2018 18:55:43 - end VMware: Read File List; elapsed time 0:00:008 déc. 2018 18:55:43 - begin VMware: Create Snapshot8 déc. 2018 18:56:07 - started process bpbrm (pid=216)8 déc. 2018 18:56:07 - Info bpbrm (pid=216) brs140_UOB_e06173 is the host to backup data from8 déc. 2018 18:56:07 - Info bpbrm (pid=216) reading file list for client8 déc. 2018 18:56:07 - Info bpbrm (pid=216) start bpfis on client8 déc. 2018 18:56:08 - Info bpbrm (pid=216) Starting create snapshot processing8 déc. 2018 18:56:08 - Info bpfis (pid=5276) Backup started8 déc. 2018 18:56:13 - snapshot backup of client brs140_UOB_e06173 using method VMware_v28 déc. 2018 18:56:19 - Info bpbrm (pid=216) INF - vmwareLogger:&nbsp; Creating snapshot for vCenter server 10.209.107.25, ESX host epb666vesx25.brs666.bcrs.fr, BIOS UUID 4221d6e3-3298-1346-2cb1-0f3ddaf49dca, Instance UUID 50213860-9a8f-7c41-0c7e-8f8aa355441d, Display Name brs140_UOB_e06173, Hostname e06173.srv.entreprise.int 8 déc. 2018 18:56:36 - end VMware: Create Snapshot; elapsed time 0:00:538 déc. 2018 18:56:36 - Info bpfis (pid=5276) done. status: 08 déc. 2018 18:56:36 - Info bpfis (pid=5276) done. status: 0: the requested operation was successfully completed8 déc. 2018 18:56:36 - end writingOperation Status: 08 déc. 2018 18:56:36 - end Parent Job; elapsed time 0:00:588 déc. 2018 18:56:36 - Info nbjm (pid=6212) snapshotid=brs140_UOB_e06173_15442917188 déc. 2018 18:56:36 - begin VMware: Policy Execution Manager PreprocessedOperation Status: 08 déc. 2018 19:28:12 - end VMware: Policy Execution Manager Preprocessed; elapsed time 0:31:368 déc. 2018 19:28:12 - begin VMware: Validate ImageOperation Status: 08 déc. 2018 19:28:17 - end VMware: Validate Image; elapsed time 0:00:058 déc. 2018 19:28:17 - begin VMware: Delete Snapshot8 déc. 2018 19:28:41 - started process bpbrm (pid=8320)8 déc. 2018 19:28:42 - Info bpbrm (pid=8320) Starting delete snapshot processing8 déc. 2018 19:28:42 - Info bpfis (pid=3724) Backup started8 déc. 2018 19:29:43 - Info bpbrm (pid=8320) INF - vmwareLogger: Error 504 fault: SOAP-ENVSmiley Frustratederver [no subcode]8 déc. 2018 19:29:43 - Info bpbrm (pid=8320) INF - vmwareLogger: WaitForTaskComplete: SYM_VMC_ERROR:&nbsp; SOAP_ERROR8 déc. 2018 19:29:43 - Info bpbrm (pid=8320) INF - vmwareLogger: removeVirtualMachineSnapshot: SYM_VMC_ERROR:&nbsp; SOAP_ERROR8 déc. 2018 19:30:34 - Info bpbrm (pid=8320) INF - vmwareLogger: Error 504 fault: SOAP-ENVSmiley Frustratederver [no subcode]8 déc. 2018 19:30:34 - Info bpbrm (pid=8320) INF - vmwareLogger: WaitForTaskComplete: SYM_VMC_ERROR:&nbsp; SOAP_ERROR8 déc. 2018 19:30:34 - Info bpbrm (pid=8320) INF - vmwareLogger: removeVirtualMachineSnapshot: SYM_VMC_ERROR:&nbsp; SOAP_ERROR8 déc. 2018 19:30:55 - Info bpbrm (pid=8320) INF - vmwareLogger: WaitForTaskComplete: The object 'vim.vm.Snapshot:snapshot-43251' has already been deleted or has not been completely created &lt;31&gt;8 déc. 2018 19:30:55 - Info bpbrm (pid=8320) INF - vmwareLogger: WaitForTaskComplete: SYM_VMC_ERROR:&nbsp; TASK_REACHED_ERROR_STATE8 déc. 2018 19:30:55 - Info bpbrm (pid=8320) INF - vmwareLogger: removeVirtualMachineSnapshot: SYM_VMC_ERROR:&nbsp; TASK_REACHED_ERROR_STATE8 déc. 2018 19:30:56 - Info bpbrm (pid=8320) INF - vmwareLogger: removeVirtualMachineSnapshot: Request status 12.INF - vmwareLogger: removeVirtualMachineSnapshot: &lt;ManagedObjectNotFoundFault xmlns="urn:vim25" xsi:type="ManagedObjectNotFound"&gt;&lt;obj type="VirtualMachineSnapshot"&gt;&lt;/obj&gt;&lt;/ManagedObjectNotFoundFault&gt;8 déc. 2018 19:30:57 - Info bpbrm (pid=8320) INF - vmwareLogger: removeVirtualMachineSnapshot: Request status 12.INF - vmwareLogger: removeVirtualMachineSnapshot: &lt;ManagedObjectNotFoundFault xmlns="urn:vim25" xsi:type="ManagedObjectNotFound"&gt;&lt;obj type="VirtualMachineSnapshot"&gt;&lt;/obj&gt;&lt;/ManagedObjectNotFoundFault&gt;8 déc. 2018 19:30:58 - Critical bpbrm (pid=8320) from client brs140_UOB_e06173: do_thaw: Unable to remove virtual machine snapshot, status=6 (SYM_VMC_SOAP_ERROR). Error Details: [The object 'vim.vm.Snapshot:' has already been deleted or has not been completely created].8 déc. 2018 19:31:05 - Critical bpbrm (pid=8320) from client brs140_UOB_e06173: vfm_thaw: method: VMware_v2, type: FIM, function: VMware_v2_thaw8 déc. 2018 19:31:05 - Critical bpbrm (pid=8320) from client brs140_UOB_e06173: snapshot delete returned status 18 déc. 2018 19:31:05 - Info bpfis (pid=3724) done. status: 18 déc. 2018 19:31:05 - end VMware: Delete Snapshot; elapsed time 0:02:488 déc. 2018 19:31:05 - Info bpfis (pid=3724) done. status: 1: the requested operation was partially successful8 déc. 2018 19:31:05 - end writingOperation Status: 18 déc. 2018 19:31:05 - begin VMware: End Notify Script8 déc. 2018 19:31:10 - Info RUNCMD (pid=16100) started8 déc. 2018 19:31:10 - Info RUNCMD (pid=16100) exiting with status: 0Operation Status: 08 déc. 2018 19:31:10 - end VMware: End Notify Script; elapsed time 0:00:05Operation Status: 1The requested operation was partially successful&nbsp; (1)

Forum Discussion

Netbackup tried to delete the same snapshot twice

7 Replies

Related Content

VMware delete snapshot failed

NDMP Snapshots not Getting Deleted

Error Backup Snapshot Vmware

Netbackup 7.6.1.1 VMware Snapshot Jobs stuck waiting for deletion

NetBackup for VMware: Exclude deleted blocks