VMware backups are failing with status 12 "file open failed"

Problem

VMware backups using NBD transport are failing with status 12 "file open failed" due to network related errors in VDDK when attempting to connect to ESX host.  It is important to note in this scenario the backup job would initially writer some data and fail at a later stage in the job.

Error Message

Job Details:

29/06/2020 3:04:26 PM - Error bpbrm (pid=148507) from client VMTEST: ERR - Cannot open file <vix>[DATASTORE_1] VMTEST/VMTEST_1-000002.vmdk error = 25
29/06/2020 3:04:28 PM - Critical bpbrm (pid=148507) from client VMTEST: FTL - cleanup() failed, status 12

29/06/2020 3:04:59 PM - Critical bpbrm (pid=148507) unexpected termination of client VMTEST
29/06/2020 3:05:00 PM - Info bpbkar (pid=0) done. status: 12: file open failed
29/06/2020 3:05:00 PM - end writing; write time: 0:19:24
file open failed  (12)

Cause

This issue can occur if we have a network connectivity issue between the Backup host and the ESX server.

Below are some snippets from VxMS logs which explains the connectivity was fine earlier but failed at a later stage.

Successful connectivity on Port 902:
06/29/2020 12:45:48 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] NBD_ClientOpen: attempting to create connection to vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902
06/29/2020 12:45:48 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] Opening file [Datastore_1] VMTEST/VMTEST_1-000002.vmdk (vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902)
06/29/2020 12:45:48 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] DISKLIB-LINK : Opened 'vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902' (0x1e): custom, 629145600 sectors / 300 GB.
06/29/2020 12:45:48 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] DISKLIB-LIB : Opened "vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902" (flags 0x1e, type custom).

Failed to connect to Port 902:
06/29/2020 12:46:53 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] NBD_ClientOpen: attempting to create connection to vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902
06/29/2020 12:47:03 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] CnxOpenTCPSocket: Timed out connecting to server esx.domain.com:902: Operation now in progress
06/29/2020 12:47:03 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] Cnx_Connect: Error message: Failed to connect to server esx.domain.com:902
06/29/2020 12:47:03 : g_vixInterfaceLogger:libvix.cpp:1804 <DEBUG> : [VFM_ESWARN] [NFC ERROR] NfcNewAuthdConnectionEx: Failed to connect to peer. Error: Failed to connect to server esx.domain.com:902
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] CnxOpenTCPSocket: Timed out connecting to server esx.domain.com:902: Operation now in progress
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] Cnx_Connect: Error message: Failed to connect to server esx.domain.com:902
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1804 <DEBUG> : [VFM_ESWARN] [NFC ERROR] NfcNewAuthdConnectionEx: Failed to connect to peer. Error: Failed to connect to server esx.domain.com:902
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] NBD_ClientOpen: Couldn't connect to esx.domain.com:902 Failed to connect to server esx.domain.com:902
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] DISKLIB-DSCPTR: : "vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902" : Failed to open NBD extent.
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] DISKLIB-LINK : "vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902" : failed to open (NBD_ERR_NETWORK_CONNECT).
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] DISKLIB-CHAIN : "vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902" : failed to open (NBD_ERR_NETWORK_CONNECT).
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] DISKLIB-LIB : Failed to open 'vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902' with flags 0x1e NBD_ERR_NETWORK_CONNECT (2338).
06/29/2020 12:47:13 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] VixDiskLib: Failed to open disk vpxa-nfc://[Datastore_1] VMTEST/VMTEST_1-000002.vmdk@esx.domain.com:902!52 97 db 53 56 3a e4 5a-03 77 1e 44 51 06 a7 41. Error 14009 (The server refused connection) (DiskLib error 2338: NBD_ERR_NETWORK_CONNECT) at 4767.
06/29/2020 12:47:15 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] NBD_ClientOpen: attempting to create connection to vpxa-nfc://[Datastore_1] VMTEST/VMTEST_2-000002.vmdk@esx.domain.com:902
06/29/2020 12:47:25 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] CnxOpenTCPSocket: Timed out connecting to server esx.domain.com:902: Operation now in progress
06/29/2020 12:47:25 : g_vixInterfaceLogger:libvix.cpp:1800 <DEBUG> : [VFM_ESINFO] Cnx_Connect: Error message: Failed to connect to server esx.domain.com:902

Solution

During a backup we make multiple connection to the ESX host on port 902 to open each VMDK.  If some work and some fail, then running one test to test the network will likely show positive results.

Perform multiple attempts to connect to the ESX port 902 from the VMware backup host using 3rd party tools like telnet, curl, or more.  This will result in some connections working and some connections failing.
This is a network issue between the VMware backup host and ESX server that must be investigated.

Some possible issues:

Verify you don't have duplicate IPs on the network.
Verify the hostname doesn't resolve to multiple IPs.  Check the DNS/host files.