Hi Everyone,
I desperately need your help! I'm fairly new to NBU and was given a task to solve something right away.
We have NBU 7.5 that weekly backs up Hyper-V hosts, but ends up on status code 156. In bpfis log, it exits with error 1542, as shown below:
02:00:16.133 [6580.6696] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe create -nbu -owner NBU -id EWKAPPPRD3.TP.EDU.SG_1363024802 -bpstart_to 900 -bpend_to 900 -backup_copy 0 -ru root -pt 41 -vm_type 2 -vm_client EWKAPPPRD3.TP.EDU.SG -clnt ewkwebapprd2 -st CINC -rg root -fim Hyper-V_v2:Virtual_machine_backup=2,nameuse=0,file_system_optimization=0,allow_offline_backup=1,csv_timeout=0,vmgrt=0,prov_type=0,snap_attr=0,nameuse=0 -class Prod_Windows_HyperV_Ewkwebapprd2 -sched Daily_Incremental_0200 -fso -S backup-server -jobid 605578
02:00:16.133 [6580.6696] <2> bpfis main: received FIM as [151] Hyper-V_v2:Virtual_machine_backup=2,nameuse=0,file_system_optimization=0,allow_offline_backup=1,csv_timeout=0,vmgrt=0,prov_type=0,snap_attr=0,nameuse=0
02:00:16.133 [6580.6696] <4> bpfis: Starting keep alive thread.
02:00:16.133 [6580.6696] <4> bpfis: INF - BACKUP START 6580
02:00:16.133 [6580.6696] <2> bpfis main: receive filelist:<NEW_STREAM>
02:00:16.133 [6580.6696] <2> bpfis main: receive filelist:<ALL_LOCAL_DRIVES>
02:00:16.352 [6580.6696] <2> bpfis main: receive filelist:<CONTINUE>
02:00:16.367 [6580.6696] <8> file_to_cache_item: [vnet_addrinfo.c:6555] fopen() failed ERRNO=2 FILE=C:\Program Files\Veritas\NetBackup\var\host_cache\124\fcfa2524+veritas_pbx,1,400,2,1,0+backup-server.txt
02:00:16.367 [6580.6696] <8> file_to_cache_item: [vnet_addrinfo.c:6555] fopen() failed ERRNO=2 FILE=C:\Program Files\Veritas\NetBackup\var\host_cache\0e1\8683f0e1+0,1,a,0,1,0+192.168.10.55.txt
02:00:16.383 [6580.6696] <8> file_to_cache_item: [vnet_addrinfo.c:6555] fopen() failed ERRNO=2 FILE=C:\Program Files\Veritas\NetBackup\var\host_cache\124\fcfa2524+vnetd,1,400,2,1,0+backup-server.txt
02:00:16.383 [6580.6696] <8> file_to_cache_item: [vnet_addrinfo.c:6555] fopen() failed ERRNO=2 FILE=C:\Program Files\Veritas\NetBackup\var\host_cache\124\fcfa2524+bprd,1,400,2,1,0+backup-server.txt
02:00:16.399 [6580.6696] <2> vnet_pbxConnect: pbxConnectEx Succeeded
02:00:16.399 [6580.6696] <2> logconnections: BPRD CONNECT FROM 192.168.10.83.64435 TO 192.168.10.55.1556 fd = 968
02:00:16.399 [6580.6696] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
02:00:16.742 [6580.6696] <2> vnet_pbxConnect: pbxConnectEx Succeeded
02:00:16.742 [6580.6696] <2> logconnections: BPRD CONNECT FROM 192.168.10.83.64436 TO 192.168.10.55.1556 fd = 988
02:00:16.742 [6580.6696] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
02:00:17.147 [6580.6696] <8> bpfis: WRN - VfMS error 10; see following messages:
02:00:17.147 [6580.6696] <8> bpfis: WRN - Non-fatal method error was reported
02:00:17.147 [6580.6696] <8> bpfis: WRN - vfm_configure_fi_one: method: FlashSnap, type: FIM, function: FlashSnap_init
02:00:17.147 [6580.6696] <8> bpfis: WRN - VfMS method error 3; see following message:
02:00:17.147 [6580.6696] <8> bpfis: WRN - FlashSnap_init: Veritas Volume Manager not installed.
02:00:17.147 [6580.6696] <8> bpfis: WRN - VfMS error 10; see following messages:
02:00:17.147 [6580.6696] <8> bpfis: WRN - Non-fatal method error was reported
02:00:17.147 [6580.6696] <8> bpfis: WRN - vfm_configure_fi_one: method: vxvm, type: FIM, function: vxvm_init
02:00:17.147 [6580.6696] <8> bpfis: WRN - VfMS method error 3; see following message:
02:00:17.147 [6580.6696] <8> bpfis: WRN - vxvm_init: Veritas Volume Manager not installed.
02:00:17.179 [6580.6696] <4> bpfis: INF - FIS_ID=EWKAPPPRD3.TP.EDU.SG_1363024802
02:00:17.179 [6580.6696] <4> bpfis: Failed to open flush NetBackup Change Journal databases mutex
02:00:17.179 [6580.6696] <4> bpfis: INF - Preparing freeze of ALL_LOCAL_DRIVES using snapshot method Hyper-V_v2.
02:00:17.179 [6580.6696] <4> bpfis: INF - Created mount point C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_ALL_LOCAL_DRIVES_6580_1
02:00:17.194 [6580.6696] <2> vnet_pbxConnect: pbxConnectEx Succeeded
02:00:17.194 [6580.6696] <2> logconnections: BPRD CONNECT FROM 192.168.10.83.64437 TO 192.168.10.55.1556 fd = 996
02:00:17.194 [6580.6696] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
02:31:15.720 [6580.6696] <32> bpfis: FTL - VfMS error 11; see following messages:
02:31:15.720 [6580.6696] <32> bpfis: FTL - Fatal method error was reported
02:31:15.720 [6580.6696] <32> bpfis: FTL - vfm_freeze_commit: method: Hyper-V_v2, type: FIM, function: Hyper-V_v2_make
02:31:15.720 [6580.6696] <32> bpfis: FTL - VfMS method error 38; see following message:
02:31:15.720 [6580.6696] <32> bpfis: FTL - snapshot services: snapshot creation failed: unknown error.
02:31:15.720 [6580.6696] <2> vnet_pbxConnect: pbxConnectEx Succeeded
02:31:15.720 [6580.6696] <2> logconnections: BPRD CONNECT FROM 192.168.10.83.65089 TO 192.168.10.55.1556 fd = 1788
02:31:15.720 [6580.6696] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
02:31:15.814 [6580.6696] <32> bpfis: FTL - VfMS error 11; see following messages:
02:31:15.814 [6580.6696] <32> bpfis: FTL - Fatal method error was reported
02:31:15.814 [6580.6696] <32> bpfis: FTL - vfm_freeze_commit: method: Hyper-V_v2, type: FIM, function: Hyper-V_v2_make
02:31:15.814 [6580.6696] <32> bpfis: FTL - VfMS method error 38; see following message:
02:31:15.814 [6580.6696] <32> bpfis: FTL - snapshot services: snapshot creation failed: unknown error.
02:31:15.814 [6580.6696] <4> bpfis: INF - Thawing ALL_LOCAL_DRIVES using snapshot method Hyper-V_v2.
02:31:15.814 [6580.6696] <4> bpfis: INF - do_thaw return value: 0
02:31:15.814 [6580.6696] <4> bpfis: INF - Deleted mount point C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_ALL_LOCAL_DRIVES_6580_1
02:31:15.814 [6580.6696] <16> bpfis: FTL - snapshot creation failed, status 156
02:31:15.814 [6580.6696] <4> bpfis: INF - Thawing ALL_LOCAL_DRIVES using snapshot method Hyper-V_v2.
02:31:15.814 [6580.6696] <8> bpfis: WRN - ALL_LOCAL_DRIVES is not frozen
02:31:15.814 [6580.6696] <8> bpfis: WRN - snapshot delete returned status 20
02:31:15.814 [6580.6696] <4> bpfis: INF - EXIT STATUS 156: snapshot error encountered
02:31:26.999 [6580.6696] <8> bpfis: WRN - set backup status returned status 156
02:31:27.109 [6580.6696] <32> bpfis: FTL - VfMS error 11; see following messages:
02:31:27.109 [6580.6696] <32> bpfis: FTL - Fatal method error was reported
02:31:27.109 [6580.6696] <32> bpfis: FTL - vfm_fi_terminate: method: VxFI, type: FIM, function: VxFI_detach
02:31:27.109 [6580.6696] <32> bpfis: FTL - VfMS method error 0; see following message:
02:31:27.109 [6580.6696] <32> bpfis: FTL - snapshot services: snapshot detach failed 1 times: invalid argument(s).
02:31:27.109 [6580.6696] <4> bpfis: Starting keep alive thread.
02:31:27.561 [2972.7904] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe delete -nbu -id EWKAPPPRD3.TP.EDU.SG_1363024802 -bpstart_to 900 -bpend_to 900 -clnt ewkwebapprd2 -pt 41 -st CINC -status 156 -S backup-server -jobid 605578 -copy 1 -fim Hyper-V_v2:Virtual_machine_backup=2,nameuse=0,file_system_optimization=0,allow_offline_backup=1,csv_timeout=0,vmgrt=0,prov_type=0,snap_attr=0
02:31:27.561 [2972.7904] <2> bpfis main: received FIM as [141] Hyper-V_v2:Virtual_machine_backup=2,nameuse=0,file_system_optimization=0,allow_offline_backup=1,csv_timeout=0,vmgrt=0,prov_type=0,snap_attr=0
02:31:27.561 [2972.7904] <4> bpfis: Starting keep alive thread.
02:31:27.561 [2972.7904] <4> bpfis: Acquiring snapshot lock:retry count [0]
02:31:27.561 [2972.7904] <2> getFileName: FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\EWKAPPPRD3.TP.EDU.SG_1363024802_copy1.lock]
02:31:27.561 [2972.7904] <2> getFileName: FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\EWKAPPPRD3.TP.EDU.SG_1363024802_copy1.lock]
02:31:27.592 [2972.7904] <2> vnet_pbxConnect: pbxConnectEx Succeeded
02:31:27.592 [2972.7904] <2> logconnections: BPRD CONNECT FROM 192.168.10.83.65099 TO 192.168.10.55.1556 fd = 920
02:31:27.592 [2972.7904] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
02:31:28.840 [2972.7904] <2> vnet_pbxConnect: pbxConnectEx Succeeded
02:31:28.840 [2972.7904] <2> logconnections: BPRD CONNECT FROM 192.168.10.83.65102 TO 192.168.10.55.1556 fd = 944
02:31:28.840 [2972.7904] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
02:31:28.918 [2972.7904] <4> bpfis: INF - BACKUP START 2972
02:31:28.918 [2972.7904] <32> bpfis: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.EWKAPPPRD3.TP.EDU.SG_1363024802.1.0
02:31:28.918 [2972.7904] <4> bpfis main: Overriding original online_util() status <12> with <1542>.
02:31:28.918 [2972.7904] <4> bpfis: INF - Attempt to send status to the bpfis create process
02:31:29.932 [2972.7904] <4> bpfis: Starting keep alive thread.
02:31:29.932 [2972.7904] <2> deleteReference: reference not found in the list
02:31:29.932 [2972.7904] <4> bpfis: Delete reference: status [-4]
02:31:29.932 [2972.7904] <2> writeSnapshotLockFile: Writing type[2] refcount[0]
02:31:29.932 [2972.7904] <2> writeSnapshotLockFile: Writing Flags [0] [0]
02:31:29.932 [2972.7904] <2> writeSnapshotLockFile: Writing Last addReffernt Time [Thu Jan 01 08:00:00 1970
]
02:31:29.932 [2972.7904] <2> writeSnapshotLockFile: Writing Last Hostname []
02:31:29.932 [2972.7904] <2> getFileName: FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\EWKAPPPRD3.TP.EDU.SG_1363024802_copy1.lock]
02:31:29.932 [2972.7904] <2> getFileName: FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\EWKAPPPRD3.TP.EDU.SG_1363024802_copy1.lock]
02:31:29.932 [2972.7904] <2> unlockSnapshot: file[C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\EWKAPPPRD3.TP.EDU.SG_1363024802_copy1.lock] : zero reference count
02:31:29.932 [2972.7904] <4> bpfis: Released snapshot lock: status [0]
02:31:29.932 [2972.7904] <4> bpfis Exit: Deleting snapshot lock files from client for id [EWKAPPPRD3.TP.EDU.SG_1363024802] and copy_number [1]
02:31:29.932 [2972.7904] <2> getFileName: FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\EWKAPPPRD3.TP.EDU.SG_1363024802_copy1.lock]
02:31:29.932 [2972.7904] <2> getFileName: FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\EWKAPPPRD3.TP.EDU.SG_1363024802_copy1.lock]
02:31:29.932 [2972.7904] <2> deleteSnapshotLockFile: file[C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\EWKAPPPRD3.TP.EDU.SG_1363024802_copy1.lock] deleted: status[0]
02:31:29.932 [2972.7904] <4> bpfis: INF - EXIT STATUS 1542: An existing snapshot is no longer valid and cannot be mounted for subsequent operations
It was working fine before. No change in the policy nor in the environment. I read some posts here and tried a few suggestions as well:
- we've got enough disk space
- VSS service restarted properly
- bpfis query shows no snapshots
- deleted all shadows left(vssadmin list shadows)
- vssadmin list writers:
C:\Users\Administrator>vssadmin list writers
vssadmin 1.1 - Volume Shadow Copy Service administrative command-line tool
(C) Copyright 2001-2005 Microsoft Corp.
Writer name: 'Task Scheduler Writer'
Writer Id: {d61d61c8-d73a-4eee-8cdd-f6f9786b7124}
Writer Instance Id: {1bddd48e-5052-49db-9b07-b96f96727e6b}
State: [1] Stable
Last error: No error
Writer name: 'VSS Metadata Store Writer'
Writer Id: {75dfb225-e2e4-4d39-9ac9-ffaff65ddf06}
Writer Instance Id: {088e7a7d-09a8-4cc6-a609-ad90e75ddc93}
State: [1] Stable
Last error: No error
Writer name: 'Performance Counters Writer'
Writer Id: {0bada1de-01a9-4625-8278-69e735f39dd2}
Writer Instance Id: {f0086dda-9efc-47c5-8eb6-a944c3d09381}
State: [1] Stable
Last error: No error
Writer name: 'Microsoft Hyper-V VSS Writer'
Writer Id: {66841cd4-6ded-4f4b-8f17-fd23f8ddc3de}
Writer Instance Id: {352af924-8389-45c8-9d36-3045f1b7d5a8}
State: [1] Stable
Last error: Retryable error
Writer name: 'ASR Writer'
Writer Id: {be000cbe-11fe-4426-9c58-531aa6355fc4}
Writer Instance Id: {5bd67cd5-a01d-4c7e-aef0-56962ab25380}
State: [1] Stable
Last error: No error
Writer name: 'System Writer'
Writer Id: {e8132975-6f93-4464-a53e-1050253ae220}
Writer Instance Id: {2ac298d9-c250-4d5e-a583-cabcefecaac4}
State: [1] Stable
Last error: No error
Writer name: 'Shadow Copy Optimization Writer'
Writer Id: {4dc3bdd4-ab48-4d07-adb0-3bee2926fd7f}
Writer Instance Id: {59e517d7-c5b9-444c-b027-b8897d6826c2}
State: [1] Stable
Last error: No error
Writer name: 'Registry Writer'
Writer Id: {afbab4a2-367d-4d15-a586-71dbb18f8485}
Writer Instance Id: {bce2213e-4ae8-4cd2-8a52-4f9d431bd751}
State: [1] Stable
Last error: No error
Writer name: 'COM+ REGDB Writer'
Writer Id: {542da469-d3e1-473c-9f4f-7847f01fc64f}
Writer Instance Id: {98e54a7d-d19b-44c1-8537-b8ba6e4ba4b3}
State: [1] Stable
Last error: No error
Writer name: 'BITS Writer'
Writer Id: {4969d978-be47-48b0-b100-f328f07ac1e0}
Writer Instance Id: {54789da8-fcbc-47a4-a60d-d50e83072140}
State: [1] Stable
Last error: No error
Writer name: 'WMI Writer'
Writer Id: {a6ad56c2-b509-4e6c-bb19-49d8f43532f0}
Writer Instance Id: {fe6ef4de-70cf-4edb-a95c-0fc1a6b40c72}
State: [1] Stable
Last error: No error
Please help/advice! Thank you in advance!
