VMware backups failing RC69 after NB upgrade to 10.0.1.1
Hello,
yesterday I did upgrade of Media Server from version 10.0.0.1 to 10.0.1.1. All was done based on official NetBackup Tech Notes and upgrade finished successfully.
However, suddenly stopped working only VMware backups which are now failing with error 69 - Invalid filelist specification.
Strange is that no all machines are affected, but 90% of them is which is the problem.
Log of snapshot part from WebUI:
Feb 08, 2023 7:54:27 AM - snapshot backup of client XXXXXXX using method VMware_v2
Feb 08, 2023 7:54:28 AM - Info bpbrm (pid=4592) INF - vmwareLogger: Creating snapshot for vCenter server XXXXXXX , ESX host XXXXXXX , BIOS UUID XXXXXXX , Instance UUID XXXXXXX , Display Name BBEPRN01, Hostname XXXXXXX
Feb 08, 2023 7:54:29 AM - Info bpbrm (pid=4592) INF - vmwareLogger: Connection state of virtual machine: connected.
Feb 08, 2023 7:54:42 AM - Info bpbrm (pid=4592) INF - vmwareLogger: httpsgetStrm: HTTP Err: err = <500>
Feb 08, 2023 7:54:44 AM - Info bpbrm (pid=4592) INF - virtLogger: Failed to backup VMware NVRAM settings.INF - REMAP FILE BACKUP NEW_STREAM
Feb 08, 2023 7:54:44 AM - end Application Snapshot: Create Snapshot; elapsed time 0:00:24
Feb 08, 2023 7:54:44 AM - Info bpfis (pid=7016) done. status: 0
Feb 08, 2023 7:54:44 AM - Info bpfis (pid=7016) done. status: 0: the requested operation was successfully completed
Feb 08, 2023 7:54:44 AM - end writing
Operation Status: 0
Feb 08, 2023 7:54:44 AM - end Child Job; elapsed time 0:00:24
Feb 08, 2023 7:54:44 AM - Info nbjm (pid=4356) snapshotid=XXXXXXX
Feb 08, 2023 7:54:44 AM - begin Application Snapshot: Stop On Error
Operation Status: 0
Feb 08, 2023 7:54:44 AM - end Application Snapshot: Stop On Error; elapsed time 0:00:00
Feb 08, 2023 7:54:44 AM - begin Application Snapshot: Cleanup Resources
Feb 08, 2023 7:54:44 AM - requesting resource XXXXXXX
invalid filelist specification(69)
Can be this the issue? What does it mean to REMAP FILE BACKUP NEW_STREAM"?
"Feb 08, 2023 7:54:44 AM - Info bpbrm (pid=4592) INF - virtLogger: Failed to backup VMware NVRAM settings.INF - REMAP FILE BACKUP NEW_STREAM"
Successfully backed-up VMware machines also contains following information but there is nothing about "REMAP FILE BACKUP NEW_STREAM" which is the difference:
Feb 07, 2023 6:35:13 PM - Info bpbrm (pid=6676) INF - vmwareLogger: httpsgetStrm: HTTP Err: err = <500>
Feb 07, 2023 6:35:16 PM - Info bpbrm (pid=6676) INF - virtLogger: Failed to backup VMware NVRAM settings.
bpfis errors:
08:37:24.089 [8328.6996] <4> bpfis: Starting keep alive thread.
08:37:24.089 [8328.6996] <4> bpfis: INF - BACKUP START 8328
08:37:24.089 [8328.6996] <2> bpfis main: receive filelist:<NEW_STREAM>
08:37:24.089 [8328.6996] <2> bpfis main: dynamic_stream_count:<0>
08:37:24.089 [8328.6996] <2> check_special_names: got path entry as :<NEW_STREAM>
08:37:24.089 [8328.6996] <2> check_special_names: after conversion returning :<NEW_STREAM>
08:37:24.089 [8328.6996] <2> path_exists: name NEW_STREAM
08:37:24.089 [8328.6996] <2> path_exists: name NEW_STREAM has UTF-8 chars.
08:37:24.089 [8328.6996] <2> path_exists: failed to get attribute for NEW_STREAM
08:37:24.089 [8328.6996] <2> path_exists: name NEW_STREAM doesn't exist.
08:37:24.089 [8328.6996] <2> bpfis main: receive filelist:<ALL_LOCAL_DRIVES>
08:37:24.089 [8328.6996] <2> bpfis main: dynamic_stream_count:<0>
08:37:24.089 [8328.6996] <2> check_special_names: got path entry as :<ALL_LOCAL_DRIVES>
08:37:24.089 [8328.6996] <2> check_special_names: after conversion returning :<ALL_LOCAL_DRIVES>
08:37:24.089 [8328.6996] <2> path_exists: name ALL_LOCAL_DRIVES
08:37:24.089 [8328.6996] <2> path_exists: name ALL_LOCAL_DRIVES has UTF-8 chars.
08:37:24.089 [8328.6996] <2> path_exists: failed to get attribute for ALL_LOCAL_DRIVES
08:37:24.089 [8328.6996] <2> path_exists: name ALL_LOCAL_DRIVES doesn't exist.
08:37:31.539 [8328.6996] <2> getCertInfoForVirtualization: isVirtualizationHostsSecureConnectEnabled returned false, returning EC_unimplemented.
08:37:31.539 [8328.6996] <2> vSphereConnect: Unable to read bp.conf for VIRTUALIZATION_HOSTS_CONNECT_TIMEOUT
08:37:31.539 [8328.6996] <2> getVmwareCipherList: Unable to read bp.conf for VMWARE_CIPHER_LIST - using default vmware cipher list XXXXXXX
08:37:31.853 [8328.6996] <2> getCrlCheckLevelFromConfig: crlCheckFlag value read from bpconf : 1
08:37:31.853 [8328.6996] <2> getCachedCertMapInfo: fstat file mod time = [1675818584], file size [1322849927934]
08:37:31.853 [8328.6996] <2> getCachedCertMapInfo: nout = [766], memMappedCertInfo = [[{"hostID": "XXXXXXX", "serverName": "XXXXXXX", "serverAltNames": "", "issuerName": "XXXXXXX", "certType": 1, "isServerMaster": 1, "issuedBy": "/CN=broker G1/OU=root@XXXXXXX/O=vx", "crlPath": "C:\\Program Files\\VERITAS\\NetBackup\\var\\vxss\\crl\\585ff46b.crl", "securityLevel": 2, "trustVersion": "Jtk5l9UoqMbJVDV", "trustStoreActions": [{"action": "ADD", "fingerprints": ["XXXXXXX"]}], "crlNextRefreshTime": 1675847384, "crlLastRefreshTime": 1675818584, "masterHostId": "XXXXXXX", "tlsSessionResumption": {"enable": 1, "handshakeIntervalInMinutes": 60}}]]
08:37:31.853 [8328.6996] <2> getCertDataByCAtypeExEx: Private key file path is not included in the response.
08:37:31.853 [8328.6996] <2> LoginWithCertManager::getLocalToken: tokenIssueTimeSec = 1675782701
08:37:31.853 [8328.6996] <2> LoginWithCertManager::getLocalToken: tokenExpTimeSec = 1675869101
08:37:31.853 [8328.6996] <2> LoginWithCertManager::getLocalToken: tokenLastFailTimeSec = 0
08:37:31.853 [8328.6996] <2> LoginWithCertManager::isJWTRefreshRequired: tokenExpTimeSec = 1675869101, timeNow = 1675841851, (tokenExpTimeSec-timeNow) = 27250
08:37:31.853 [8328.6996] <2> LoginWithCertManager::isJWTRefreshRequired: Token-refresh IS NOT required
08:37:51.992 [7784.8580] <8> bpfis: WRN - VfMS error 10; see following messages:
08:37:51.992 [7784.8580] <8> bpfis: WRN - Non-fatal method error was reported
08:37:51.992 [7784.8580] <8> bpfis: WRN -
08:37:51.992 [7784.8580] <8> bpfis: WRN - VfMS method error 0; see following message:
08:37:51.992 [7784.8580] <8> bpfis: WRN -
08:37:52.007 [7784.8580] <4> remote_vxfs: remote_vxfs_init called
08:37:52.007 [7784.8580] <8> bpfis: WRN - VfMS error 10; see following messages:
08:37:52.007 [7784.8580] <8> bpfis: WRN - Non-fatal method error was reported
08:37:52.007 [7784.8580] <8> bpfis: WRN -
08:37:52.007 [7784.8580] <8> bpfis: WRN - VfMS method error 0; see following message:
08:37:52.007 [7784.8580] <8> bpfis: WRN -
08:38:01.936 [7784.8580] <4> bpfis: INF - Failed to delete mount point C:\Program Files\VERITAS\NetBackup\online_util\fi_cntl\bpfis.fim.XXXXXXX_1675841839.1.0.NBU_DATA.xml; errno=22: Invalid argument
08:38:01.936 [7784.8580] <2> NBAllowedList::validatePath: Match found. Allowing C:\Program Files\VERITAS\NetBackup\online_util\fi_cntl\bpfis.fim.XXXXXXX_1675841839.1.0.snapreplicapair
Thank you in advance for any suggestions.
Tom
It was - in the end - general error with not correctly configured vSphere user permissions. In our environment, there are security limitations for that user and it was working fine with previous version 10.0.0.1. Not really sure what rapidly changed from NetBackup 10.1.1 point of view but it is what it is.
For correct permissions, please follow:
https://www.veritas.com/support/en_US/article.100001960