Snapshot fails

[ricardo_luna1]

HI

I have problems whith 1  snapshot ARO-NVR-SRV03

Master server: AIX 6.1 NB 7.5.0.6

media server: Windows 2008 R2 NB 7.5.0.6

11:36:57.795 [2532.3644] <2> onlfi_vfms_logf: INF - vmwareLogger: ParseDatacenterPath: Path=\(DC)TMX(DC)\vm\ARO-NVR-SRV03

11:36:57.810 [2532.3644] <2> onlfi_vfms_logf: INF - vmwareLogger: ParseDatacenterPath: Path=\(DC)TMX(DC)\vm\ARO-NVR-SRV03, DC path=/TMX/, Container path =/TMX/vm/, Obj type=VirtualMachine

11:36:57.810 [2532.3644] <2> onlfi_vfms_logf: INF - vmwareLogger: RetrieveDcMorAndObjMorFromPath: Path=/vminstuuid/5024db05-4cce-4258-5ee0-8d1e56591909, ObjName=, <MOR=vm-91757>, err=0

11:36:57.810 [2532.3644] <2> onlfi_vfms_logf: INF - vmwareLogger: getObjectProperty: for Mor=<vm-91757><VirtualMachine> Property=summary.runtime.consolidationNeeded

11:36:57.810 [2532.3644] <2> onlfi_vfms_logf: INF - checkConsolidate: vmcGetObjPropertyByType for consolidationNeeded returned 0
11:36:57.810 [2532.3644] <2> onlfi_vfms_logf: INF - checkConsolidate: vmcGetObjPropertyByType for managedBy returned false
11:36:57.826 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLib: config options: libdir 'C:\Program Files\Common Files\VERITAS\VxMS\Shared\VDDK', tmpDir 'C:\Windows\TEMP\vmware-SYSTEM'.

11:36:57.826 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLib: Attempting to locate advanced transport module in "C:\Program Files\Common Files\VERITAS\VxMS\Shared\VDDK\plugins".

11:36:57.936 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLib: Advanced transport plugin was successfully loaded into vixDiskLib.

11:36:57.936 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLib: Enabling advanced transport modes.

11:36:57.936 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLib: Transport modes available: file:nbdssl:nbd:san.

11:36:57.936 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VMware VixDiskLib (5.0) Release build-614080

11:36:58.139 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: POLL Using the WSAPoll API Implementation for PollDefault

11:36:58.139 [2532.3644] <2> onlfi_vfms_logf: INF - unlockVM: Calling VixDiskLib_EndAccess
11:36:58.139 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVimResolveHostName: Resolving IP address for hostname vcenter.

11:36:58.139 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVimResolveHostName: Resolved to 172.30.109.36.

11:36:58.139 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: HOSTINFO 23524057137731 @ 14318180Hz -> 0 @ 1000000000Hz

11:36:58.139 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: HOSTINFO ((x * 2343484437) >> 25) + -1642950230758528

11:36:58.171 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVim: VixDiskLibVimLogin

11:36:58.171 [2532.6652] <2> onlfi_vfms_logf: INF - vddkLog: VThreadBase detected multiple threads.

11:36:59.581 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVim: TicketFindVMByMoRef: vmxPath = -vm-91757- 

11:36:59.612 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVim: VixDiskLibVimLoadVM

11:37:00.051 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVim: VixDiskLibVimLoadAuthMgr

11:37:00.051 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVim: VixDiskLibVimLoadVMCb

11:37:00.396 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVim: VixDiskLibVimLogout 

11:37:00.506 [2532.1032] <2> send_keep_alive: INF - sending keep alive
11:37:00.600 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLibVim: VixDiskLibVimLogout 

11:37:00.600 [2532.3644] <2> onlfi_vfms_logf: INF - unlockVM: VixDiskLib_EndAccess returned:0 [The operation was successful]
11:37:00.600 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: VixDiskLib: VixDiskLib_Exit called. Unmatched Init calls so far: 1.

11:37:00.600 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: diskLibPlugin: 2015-10-14T11:37:00.600-03:00 [03644 trivia 'Default'] Starting to shut down worker thread pool.

11:37:01.618 [2532.3644] <2> onlfi_vfms_logf: INF - vddkLog: diskLibPlugin: 2015-10-14T11:37:01.618-03:00 [03644 trivia 'Default'] Worker thread pool is shut down.

11:37:01.618 [2532.3644] <2> onlfi_vfms_logf: INF - do_thaw: unlockVM returned 0
11:37:01.618 [2532.3644] <2> onlfi_vfms_logf: INF - vmwareLogger: LogoutAPI: Caller's ThreadId = 3644, Login key=524e2057-3118-28da-dfd5-a98ff83ec1ad, returned 0

11:37:01.791 [2532.3644] <2> onlfi_vfms_logf: INF - vmwareLogger: ~VmwareClient: soap memory release done

11:37:01.791 [2532.3644] <2> onlfi_vfms_logf: INF - vmwareLogger: ~VmwareClient: Lists release done

11:37:01.838 [2532.3644] <2> onlfi_vfms_logf: INF - dovSphereDisconnect: disconnect for vcenter completed with flags 0 and status 0
11:37:01.838 [2532.3644] <2> onlfi_vfms_logf: INF - dovSphereDisconnect: disconnect for vcenter completed with flags 0 and status 0
11:37:01.838 [2532.3644] <4> onlfi_thaw: INF - do_thaw return value: 0
11:37:01.838 [2532.3644] <4> delete_mount_point: INF - Failed to delete mount point C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ARO-NVR-SRV03_1444833252.1.0.NBU_DATA.xml; errno=22: Invalid argument
11:37:01.853 [2532.3644] <2> fis_delete_id: INF - removing C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ARO-NVR-SRV03_1444833252.1.0
11:37:01.853 [2532.3644] <2> fis_delete_id: INF - removing C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ARO-NVR-SRV03_1444833252.1.0.NBU_DATA.xml
11:37:01.853 [2532.3644] <2> fis_delete_id: INF - removing C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ARO-NVR-SRV03_1444833252.1.0.VM_ObjInfoXML.xml
11:37:01.853 [2532.3644] <2> delete_bpfis_state_from_master: Deleting bpfis state file id ARO-NVR-SRV03_1444833252 for copy no 1 and client ar-nols136 from master nols103
11:37:01.853 [2532.3644] <2> insert_if_not_dup: [vnet_addrinfo.c:5724] ignoring IPv6 link local 0 0x0
11:37:01.853 [2532.3644] <2> vnet_sortaddrs: [vnet_addrinfo.c:3954] sorted addrs: 1 0x1
11:37:01.853 [2532.3644] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4828] using interface  ANY
11:37:01.853 [2532.3644] <2> vnet_sortaddrs: [vnet_addrinfo.c:3954] sorted addrs: 1 0x1
11:37:01.853 [2532.3644] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4828] using interface  ANY
11:37:01.853 [2532.3644] <2> vnet_sortaddrs: [vnet_addrinfo.c:3954] sorted addrs: 1 0x1
11:37:01.853 [2532.3644] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4828] using interface  ANY
11:37:01.853 [2532.3644] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1
11:37:01.869 [2532.3644] <2> vnet_pbxConnect: pbxConnectEx Succeeded
11:37:01.869 [2532.3644] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bprd CONNECT FROM 192.168.215.140.65515 TO 192.168.215.103.1556 fd = 820
11:37:01.869 [2532.3644] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 192.168.215.140.65515 TO 192.168.215.103.1556 fd = 820
11:37:01.869 [2532.3644] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO nols103 192.168.215.103 bprd VIA pbx
11:37:01.869 [2532.3644] <2> logconnections: BPRD CONNECT FROM 192.168.215.140.65515 TO 192.168.215.103.1556 fd = 820
11:37:01.869 [2532.3644] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
11:37:01.869 [2532.3644] <2> delete_bpfis_state_from_master: bpfis state file id ARO-NVR-SRV03_1444833252 for copy no 1 and client ar-nols136 has been removed from master nols103.
11:37:01.869 [2532.3644] <2> ol_cleanup: INF - removing C:\Program Files\Veritas\NetBackup\temp\NOL_CONTROLACCESO_HTV_W8_FS_08+d5228+1.std_filelist
11:37:01.869 [2532.3644] <2> ol_cleanup: INF - removing all log files
11:37:01.869 [2532.3644] <2> bpfis Exit: Failed to delete snapreplicapair file [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ARO-NVR-SRV03_1444833252.1.0.snapreplicapair] return value[-1]                     error [2] [No such file or directory]
11:37:01.869 [2532.3644] <2> vnet_sortaddrs: [vnet_addrinfo.c:3954] sorted addrs: 1 0x1
11:37:01.869 [2532.3644] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4828] using interface  ANY
11:37:01.869 [2532.3644] <2> vnet_sortaddrs: [vnet_addrinfo.c:3954] sorted addrs: 1 0x1
11:37:01.869 [2532.3644] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4828] using interface  ANY
11:37:01.869 [2532.3644] <2> vnet_sortaddrs: [vnet_addrinfo.c:3954] sorted addrs: 1 0x1
11:37:01.869 [2532.3644] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4828] using interface  ANY
11:37:01.869 [2532.3644] <2> async_connect: [vnet_connect.c:1477] connect in progress 1 0x1
11:37:01.885 [2532.3644] <2> vnet_pbxConnect: pbxConnectEx Succeeded
11:37:01.885 [2532.3644] <2> do_pbx_service: [vnet_connect.c:2116] via PBX bprd CONNECT FROM 192.168.215.140.65516 TO 192.168.215.103.1556 fd = 8
11:37:01.885 [2532.3644] <2> async_connect: [vnet_connect.c:1644] connect async CONNECT FROM 192.168.215.140.65516 TO 192.168.215.103.1556 fd = 8
11:37:01.885 [2532.3644] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO nols103 192.168.215.103 bprd VIA pbx
11:37:01.885 [2532.3644] <2> logconnections: BPRD CONNECT FROM 192.168.215.140.65516 TO 192.168.215.103.1556 fd = 8
11:37:01.885 [2532.3644] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
11:37:01.885 [2532.3644] <2> bprd_read_text_file: Starting to read data
11:37:01.900 [2532.3644] <2> bprd_read_text_file: Read 815 lines and wrote to file C:\Windows\TEMP\ltemp-02532444833421869644000000003-a03644
11:37:01.900 [2532.3644] <4> keep_alive_and_snap_control: Entering with request <SNAPSHOT_UNLOCK>, timeout <0>, status <0>.
11:37:01.900 [2532.3644] <4> keep_alive_and_snap_control: Starting keep alive thread.
11:37:01.900 [2532.3644] <4> unlockSnapshot: Delete reference: status [0]
11:37:01.900 [2532.3644] <2> writeSnapshotLockFile:    Writing type[2] refcount[0]
11:37:01.900 [2532.3644] <2> writeSnapshotLockFile:    Writing Flags [0] [0]
11:37:01.900 [2532.3644] <2> writeSnapshotLockFile:   Writing Last addReffernt Time [Wed Dec 31 21:00:00 1969
]
11:37:01.900 [2532.3644] <2> writeSnapshotLockFile:   Writing Last Hostname []
11:37:01.900 [2532.3644] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\ARO-NVR-SRV03_1444833252_copy1.lock]
11:37:01.900 [2532.3644] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\ARO-NVR-SRV03_1444833252_copy1.lock]
11:37:01.900 [2532.3644] <2> unlockSnapshot:    file[C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\ARO-NVR-SRV03_1444833252_copy1.lock] : zero reference count 
11:37:01.900 [2532.3644] <4> unlockSnapshot: Released snapshot lock: status [0] 
11:37:01.900 [2532.3644] <4> keep_alive_and_snap_control: Exiting.
11:37:01.900 [2532.3644] <4> bpfis Exit: Deleting snapshot lock files from client for id [ARO-NVR-SRV03_1444833252] and copy_number [1]
11:37:01.900 [2532.3644] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\ARO-NVR-SRV03_1444833252_copy1.lock]
11:37:01.900 [2532.3644] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\ARO-NVR-SRV03_1444833252_copy1.lock]
11:37:01.900 [2532.3644] <2> deleteSnapshotLockFile:    file[C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\ARO-NVR-SRV03_1444833252_copy1.lock] deleted: status[0]
11:37:01.900 [2532.3644] <4> bpfis Exit: INF - EXIT STATUS 0: the requested operation was successfully completed
11:37:01.900 [2532.3644] <2> stop_keep_alive_thread: INF - Stop keep_alive thread 
11:37:03.922 [2532.3644] <2> bpfis Exit: INF - Close of stdout complete

[RiaanBadenhorst]

Hi,

There are no errors in this log. Pleae post the job log to see what's happening.

[Michael_G_Ander · Accepted solution]

Can you do a snapshot with quiesce file system through the vsphere client ?

Check the VM's system logs for errors/warnings around the time of the snapshot.

In my experience most snapshot errors is caused by a problem inside the VM OS.

[Elango_G1]

Hi,

Need more details, Could you please provide the detailed status of the failed job?

I can found the basic troubleshooting guide from veritas portal for snapshot failures commonly,

https://www.veritas.com/support/en_US/article.TECH75214

May trying checking the space allocated for snapshot in the concern drives as per the above document.