VMware backup jobs fail with Status 50 or Status 6 and 23 after upgrading to NetBackup 8.0 (NetBackup Appliance 3.0)

Problem

After upgrading to NetBackup 8.0 for the Linux VMware VM backup host, all VMware VM backup jobs failed with error code 50. In the Job Details, an error similar to below may be seen:

Mar 10, 2017 3:54:21 PM - begin writing
Mar 10, 2017 3:54:23 PM - Error bptm (pid=324861) media manager terminated by parent process
Mar 10, 2017 3:54:29 PM - Info msdpserver (pid=324861) StorageServer=PureDisk:msdpserver; Report=PDDO Stats for (msdpserver): scanned: 3 KB, CR sent: 0 KB, CR sent over FC: 0 KB, dedup: 100.0%, cache disabled
Mar 10, 2017 3:54:30 PM - Critical bpbrm (pid=324830) unexpected termination of client vmhost
Mar 10, 2017 3:54:30 PM - Info bpbkar (pid=0) done. status: 50: client process aborted
Mar 10, 2017 3:54:30 PM - end writing; write time: 0:00:09
client process aborted  (50)

In /usr/openv/netbackup/logs/bpbkar debug log, the related backup process stopped at "stage_one_virtual: virtual machine XML file", then no further messages are displayed:

15:54:18.893 [324850.324850] <2> bprd_read_text_file: Starting to read data
15:54:19.070 [324850.324850] <2> bprd_read_text_file: Read 3 lines and wrote to file /tmp/ltemp-24850489132458893745000000000-4PTsBU
15:54:19.071 [324850.324850] <2> get_virtual_server_cred: SRV001: credentials found. (../flashmap.cpp:3922)
15:54:19.071 [324850.324850] <4> stage_one_virtual: INF - Snapshot mapping type: ON
15:54:19.072 [324850.324850] <4> stage_one_virtual: INF - Snapshot BLIB type: OFF
15:54:19.072 [324850.324850] <2> get_virtual_file_paths_array: virtual file name = [Pool] hostname/hostname-000001.vmdk (../flashmap.cpp:3816)
15:54:19.072 [324850.324850] <2> get_virtual_file_paths_array: virtual snapshot file name = <vix>[Pool] hostname/hostname-000001.vmdk (../flashmap.cpp:3835)
15:54:19.072 [324850.324850] <2> get_virtual_file_paths_array: virtual snapshot disk key = 2000, universal name = 6000C295-2a8a-dbac-d0fd-929894acfc8b (../flashmap.cpp:3846)
15:54:19.073 [324850.324850] <2> stage_one_virtual: virtual machine XML file: /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.vmhost_1489132437.1.0.VM_ObjInfoXML.xml (../flashmap.cpp:4583)

The backup jobs were successful before the upgrade.

In a similar case status 6 and status 23 were observed in the Job Details:

Apr 27, 2017 7:50:07 AM - Error bpbrm (pid=90292) from client xxxx: ERR - Error opening the snapshot disks using given transport mode: san:nbd Status 23
Apr 27, 2017 7:50:07 AM - Critical bpbrm (pid=90292) from client xxxx: FTL - cleanup() failed, status 6
Apr 27, 2017 7:50:10 AM - Error bptm (pid=90626) media manager terminated by parent process
Apr 27, 2017 7:50:17 AM - Critical bpbrm (pid=90292) unexpected termination of client xxxx
Apr 27, 2017 7:50:17 AM - Info bpbkar (pid=0) done. status: 6: the backup failed to back up the requested files
Apr 27, 2017 7:50:17 AM - end writing; write time: 0:00:12
the backup failed to back up the requested files  (6)

Error Message

status: 50: client process aborted

OR

Error opening the snapshot disks using given transport mode: san:nbd Status 23

AND

status: 6: the backup failed to back up the requested files

VxMS provider log file shows the following sequence:

01/05/2017 16:41:25 : openLeafSnapshotDisks:VixGuest.cpp:422 <DEBUG> : Calling connectToHost(SnapMoRef: snapshot-8644, TransportMode: nbd) 
01/05/2017 16:41:25 : connectToHost:VixGuest.cpp:928 <TRACE> : in 
01/05/2017 16:41:25 : connectToHost:VixGuest.cpp:952 <INFO> : TransportMode requested: nbd 
01/05/2017 16:41:25 : vdListTransportModes:VixInterface.cpp:1277 <TRACE> : in 
01/05/2017 16:41:25 : vdListTransportModes:VixInterface.cpp:1277 <TRACE> : out 
01/05/2017 16:41:25 : connectToHost:VixGuest.cpp:957 <INFO> : Transport Modes available on this host: file:san:hotadd:nbdssl:nbd 
01/05/2017 16:41:25 : vdCleanup:VixInterface.cpp:1286 <TRACE> : in 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_Cleanup: Remove previous mount points and clean up . 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_Connect: Establish connection. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_Connect: Use remote connection. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: Allocate connection. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: Prepare remote connect. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: A thumbprint is required for SSL certificate validation. vixDiskLib.c line 2447 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: Clean up connection. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_Connect: Failed to allocate connection. Error 3 (One of the parameters was invalid) at 3925. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_Cleanup: Error occured during establishing connection. Error 3 (One of the parameters was invalid) at 3830. 
01/05/2017 16:41:25 : vdCleanup:VixInterface.cpp:1332 <ERROR> : Error 3 in cleanup 
01/05/2017 16:41:25 : vdCleanup:VixInterface.cpp:1286 <TRACE> : out 
01/05/2017 16:41:25 : connectToHost:VixGuest.cpp:992 <ERROR> : vdCleanup() Error 3 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1120 <TRACE> : in 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1177 <DEBUG> : Calling VixDiskLib_ConnectEx() 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1178 <DEBUG> : vmxSpec: moref=vm-229 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1179 <DEBUG> : serverName: vCenterApp01 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1180 <DEBUG> : thumbPrint: 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1181 <DEBUG> : credType: 1 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1182 <DEBUG> : userName: ccq\nbubackup 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1183 <DEBUG> : port: 902 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_ConnectEx: Establish connection using nbd. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_Connect: Establish connection. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_Connect: Use remote connection. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: Allocate connection. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: Prepare remote connect. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: A thumbprint is required for SSL certificate validation. vixDiskLib.c line 2447 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: Clean up connection. 
01/05/2017 16:41:25 : g_vixInterfaceLogger:libvix.cpp:1775 <DEBUG> : [VFM_ESINFO] VixDiskLib: VixDiskLib_Connect: Failed to allocate connection. Error 3 (One of the parameters was invalid) at 3925. 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1214 <DEBUG> : Done with VixDiskLib_Connect(): 0 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1224 <INFO> : VixDiskLib_Connect failed. 
01/05/2017 16:41:25 : vdConnect:VixInterface.cpp:1120 <TRACE> : out 
01/05/2017 16:41:25 : connectToHost:VixGuest.cpp:999 <ERROR> : vdConnect() Error = 3. 
01/05/2017 16:41:25 : connectToHost:VixGuest.cpp:928 <TRACE> : out 
01/05/2017 16:41:25 : openLeafSnapshotDisks:VixGuest.cpp:429 <DEBUG> : connectToHost() failed. Calling closeLeafSnapshotDisks()

Cause

The issue seems to occur when upgrading from an older version of NetBackup to NetBackup 8.0 (NetBackup Appliance 3.0) on a Linux platform.

While upgrading the NetBackup installer is not clearing the binaries that are not required in /usr/openv/lib/map folder:

/usr/openv/lib/map:
total 1868
-r-xr-xr-x 1 root bin   56432 Nov 10 15:37 libdisk.so*
-r-xr-xr-x 1 root bin   51526 Nov 10 15:37 libdiskST.so*
-r-xr-xr-x 1 root bin   56667 Nov 10 15:37 libemcpower.so*
-r-xr-xr-x 1 root bin   56521 Nov 10 15:37 libemcpowerST.so*
-r-xr-xr-x 1 root bin   74174 Nov 10 15:37 libgfsp.so*
-r-xr-xr-x 1 root bin   73930 Nov 10 15:37 libgfspST.so*
-r-xr-xr-x 1 root bin  443714 Nov 10 15:37 libhv_vmware.so*
-r-xr-xr-x 1 root bin   56432 Nov 10 15:37 librawp.so*
-r-xr-xr-x 1 root bin   51526 Nov 10 15:37 librawpST.so*
-r-xr-xr-x 1 root bin  480415 Feb 13  2015 libvix.so*
-r-xr-xr-x 1 root bin  480137 Feb 13  2015 libvixST.so*
drwxr-xr-x 2 root root   4096 Feb  2  2013 logs/
drwxr-xr-x 2 root bin    4096 Mar  9 17:01 rvp/

Solution

To fix the issue, please move the following 2 files from /usr/openv/lib/map to a temporary folder:

-r-xr-xr-x 1 root bin  480415 Feb 13  2015 libvix.so*
-r-xr-xr-x 1 root bin  480137 Feb 13  2015 libvixST.so*

Then try to run VM backup job again and it should be successful.

Note:

• Renaming these 2 libraries will not fix the problem. They need to be removed from /usr/openv/lib/map
• NetBackup service/daemon restart is not required.