Off-Host-Backup failing after update to 7.6.0.4

[MirkoG]

Hi all,

I have a strange issue. Our Equallogic Off-Host-Backup is failing. I think this was after the update to Netbackup 7.6.0.4 from 7.6.0.2 but I'm not sure.

It worked perfectly fine for years and all other Backup Jobs are still running perfect. The Backup is starting and at the Equallogic I could see the created snapshot. This Snapshot remains offline and the Backup fail with the following error.

------------------------------------------------------------------

19.02.2015 13:50:29 - Info nbjm(pid=9792) starting backup job (jobid=10598) for client fs-de004, policy TestVSS, schedule Manual  
19.02.2015 13:50:29 - Info nbjm(pid=9792) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=10598, request id:{85E01F85-E73B-4FFB-9D7B-4CE8BEA60F80})  
19.02.2015 13:50:29 - requesting resource bs-tmf001-hcart2-robot-tld-0
19.02.2015 13:50:29 - requesting resource bs-tmf001.tmf.viasyshc.eu.NBU_CLIENT.MAXJOBS.fs-de004
19.02.2015 13:50:29 - requesting resource bs-tmf001.tmf.viasyshc.eu.NBU_POLICY.MAXJOBS.TestVSS
19.02.2015 13:50:29 - granted resource bs-tmf001.tmf.viasyshc.eu.NBU_CLIENT.MAXJOBS.fs-de004
19.02.2015 13:50:29 - granted resource bs-tmf001.tmf.viasyshc.eu.NBU_POLICY.MAXJOBS.TestVSS
19.02.2015 13:50:29 - granted resource 004708
19.02.2015 13:50:29 - granted resource HP.ULTRIUM5-SCSI.001
19.02.2015 13:50:29 - granted resource bs-tmf001-hcart2-robot-tld-0
19.02.2015 13:50:29 - estimated 0 Kbytes needed
19.02.2015 13:50:29 - begin Parent Job
19.02.2015 13:50:29 - begin Snapshot, Start Notify Script
19.02.2015 13:50:29 - Info RUNCMD(pid=4080) started            
19.02.2015 13:50:29 - Info RUNCMD(pid=4080) exiting with status: 0         
Status 0
19.02.2015 13:50:29 - end Snapshot, Start Notify Script; elapsed time: 0:00:00
19.02.2015 13:50:29 - begin Snapshot, Step By Condition
Status 0
19.02.2015 13:50:29 - end Snapshot, Step By Condition; elapsed time: 0:00:00
19.02.2015 13:50:29 - begin Snapshot, Stream Discovery
Status 0
19.02.2015 13:50:29 - end Snapshot, Stream Discovery; elapsed time: 0:00:00
19.02.2015 13:50:29 - begin Snapshot, Read File List
Status 0
19.02.2015 13:50:29 - end Snapshot, Read File List; elapsed time: 0:00:00
19.02.2015 13:50:29 - begin Snapshot, Create Snapshot
19.02.2015 13:50:29 - started process bpbrm (3724)
19.02.2015 13:50:29 - started
19.02.2015 13:50:35 - Info bpbrm(pid=3724) fs-de004 is the host to backup data from     
19.02.2015 13:50:35 - Info bpbrm(pid=3724) reading file list for client        
19.02.2015 13:50:35 - Info bpbrm(pid=3724) start bpfis on client         
19.02.2015 13:50:37 - Info bpbrm(pid=3724) Starting create snapshot processing         
19.02.2015 13:50:37 - snapshot backup using alternate client bs-tmf001.tmf.viasyshc.eu
19.02.2015 13:50:39 - Info bpfis(pid=2412) Backup started           
19.02.2015 13:50:42 - Info bpfis(pid=5076) Backup started           
19.02.2015 13:50:43 - Critical bpbrm(pid=3724) from client fs-de004: FTL - In case of snapshot creation using vendor VSS hardware provider, snapshot devices may get leaked due to incomplete import operation. VSS framework does not allow to delete un-imported snapshot. The leaked snapshot devices can be recovered using Microsoft Vshadow utility. Please use the xml file [C:\Program Files\Veritas\NetBackup\temp\bpfis.fim.fs-de004_1424350229.1.0.xml] created on client [fs-de004.viasyshc.eu] to import and delete the snapshot manually using Vshadow utility from alternate client [bs-tmf001.tmf.viasyshc.eu]. Please refer event viewer and Hardware VSS provider logs for more details. Delete the file manually after cleanup.
19.02.2015 13:50:43 - Critical bpbrm(pid=3724) from client fs-de004: FTL - snapshot processing failed, status 4213   
19.02.2015 13:50:43 - Critical bpbrm(pid=3724) from client fs-de004: FTL - snapshot creation failed, status 4213   
19.02.2015 13:50:43 - Info bpfis(pid=5076) done. status: 4213          
19.02.2015 13:50:43 - end Snapshot, Create Snapshot; elapsed time: 0:00:14
19.02.2015 13:50:43 - Info bpfis(pid=5076) done. status: 4213: Snapshot import failed       
19.02.2015 13:50:43 - end writing
Status 4213
19.02.2015 13:50:43 - end Parent Job; elapsed time: 0:00:14
19.02.2015 13:50:43 - begin Snapshot, Stop On Error
Status 0
19.02.2015 13:50:43 - end Snapshot, Stop On Error; elapsed time: 0:00:00
19.02.2015 13:50:43 - begin Snapshot, Delete Snapshot
19.02.2015 13:50:43 - started process bpbrm (8720)
19.02.2015 13:50:51 - Info bpbrm(pid=8720) Starting delete snapshot processing         
19.02.2015 13:50:55 - Info bpfis(pid=4188) Backup started           
19.02.2015 13:50:55 - Critical bpbrm(pid=8720) from client fs-de004: cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.fs-de004_1424350229.1.0      
19.02.2015 13:50:55 - Info bpfis(pid=4188) done. status: 4207          
19.02.2015 13:50:55 - end Snapshot, Delete Snapshot; elapsed time: 0:00:12
19.02.2015 13:50:55 - Info bpfis(pid=4188) done. status: 4207: Could not fetch snapshot metadata or state files  
19.02.2015 13:50:55 - end writing
Status 4207
19.02.2015 13:50:55 - end Parent Job; elapsed time: 0:00:26
19.02.2015 13:50:55 - begin Snapshot, End Notify Script
19.02.2015 13:50:55 - Info RUNCMD(pid=8124) started            
19.02.2015 13:50:55 - Info RUNCMD(pid=8124) exiting with status: 0         
Status 0
19.02.2015 13:50:55 - end Snapshot, End Notify Script; elapsed time: 0:00:00
Status 4213
19.02.2015 13:50:55 - end operation
Snapshot import failed(4213)

------------------------------------------------------------------

I've created a bpfis folder at the client and this is show'n there in the log file

----

14:11:04.598 [3140.1640] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe create -nbu -owner NBU -rhost bs-tmf001.tmf.viasyshc.eu -id fs-de004_1424351454 -bpstart_to 300 -bpend_to 300 -backup_copy 0 -ru root -pt 13 -clnt fs-de004 -rg other -fim VSS:prov_type=3,snap_attr=0,max_snapshots=1 -class TestVSS -sched Manual -fso -S bs-tmf001.tmf.viasyshc.eu -jobid 10599 -nbu_version 123731972 -application_consistent 1 
14:11:04.598 [3140.1640] <2> bpfis main: received FIM as [43] VSS:prov_type=3,snap_attr=0,max_snapshots=1
14:11:04.598 [3140.1640] <2> bpfis main: VSS provider type: 3
14:11:04.598 [3140.1640] <4> bpfis: Starting keep alive thread.
14:11:04.613 [3140.1640] <4> bpfis: INF - BACKUP START 3140
14:11:04.613 [3140.1640] <2> bpfis main: receive filelist:<NEW_STREAM> 
14:11:04.613 [3140.1640] <2> check_special_names: got path entry as :<NEW_STREAM> 
14:11:04.613 [3140.1640] <2> check_special_names: after conversion returning :<NEW_STREAM> 
14:11:04.613 [3140.1640] <2> bpfis main: receive filelist:<I:\> 
14:11:04.613 [3140.1640] <2> check_special_names: got path entry as :<I:\> 
14:11:04.613 [3140.1640] <2> check_special_names: after conversion returning :<I:\> 
14:11:04.816 [3140.1640] <2> bpfis main: receive filelist:<CONTINUE> 
14:11:04.816 [3140.1640] <2> check_special_names: got path entry as :<CONTINUE> 
14:11:04.816 [3140.1640] <2> check_special_names: after conversion returning :<CONTINUE> 
14:11:04.863 [3140.1640] <2> vnet_pbxConnect: pbxConnectEx Succeeded
14:11:04.863 [3140.1640] <2> logconnections: BPRD CONNECT FROM 10.240.98.166.50514 TO 10.240.99.26.1556 fd = 572
14:11:05.066 [3140.1640] <8> bpfis: WRN - VfMS error 10; see following messages:
14:11:05.066 [3140.1640] <8> bpfis: WRN - Non-fatal method error was reported
14:11:05.066 [3140.1640] <8> bpfis: WRN - 
14:11:05.066 [3140.1640] <8> bpfis: WRN - VfMS method error 0; see following message:
14:11:05.066 [3140.1640] <8> bpfis: WRN - 
14:11:05.066 [3140.1640] <8> bpfis: WRN - VfMS error 10; see following messages:
14:11:05.066 [3140.1640] <8> bpfis: WRN - Non-fatal method error was reported
14:11:05.066 [3140.1640] <8> bpfis: WRN - 
14:11:05.066 [3140.1640] <8> bpfis: WRN - VfMS method error 0; see following message:
14:11:05.066 [3140.1640] <8> bpfis: WRN - 
14:11:05.066 [3140.1640] <4> bpfis: INF - FIS_ID=fs-de004_1424351454
14:11:05.066 [3140.1640] <8> bpfis: WRN - Terminal Services export: The specified module could not be found. 
14:11:06.283 [3140.1640] <4> bpfis: parameter client_type 13, fis_accl 0, fis_accl_cksv -1, SNAPSHOT_IS_HERE 0 
14:11:06.283 [3140.1640] <8> bpfis: Failed to open flush NetBackup Change Journal databases mutex
14:11:06.283 [3140.1640] <4> bpfis main: read_registry_dw_value for VSS_CONCURRENT_OPERATIONS: return status 2, return value 0
14:11:06.283 [3140.1640] <4> bpfis main: VSS Snapshot create Mutex lock acquired
14:11:06.283 [3140.1640] <4> bpfis: INF - Preparing freeze of I:\ using snapshot method VSS.
14:11:06.283 [3140.1640] <4> bpfis: INF - Created mount point C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_I__3140_1
14:11:08.591 [3140.1640] <4> bpfis: INF - EXECUTE_W_STAT_CMD bs-tmf001.tmf.viasyshc.eu root 334 /usr/openv/netbackup/bin/bpfis bpfis create -nbu -dptgt -id fs-de004_1424351454 -rhost fs-de004.viasyshc.eu -clnt bs-tmf001.tmf.viasyshc.eu -S bs-tmf001.tmf.viasyshc.eu -nbu_version 123731972 -vnet_ipc 50515 -exclude C:\Program��Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.fs-de004_1424351454.1.0.exclude -pt 13 -jobid 10599
14:11:08.591 [3140.1640] <4> bpfis: INF - END CMD_INPUT
14:11:09.090 [3140.1640] <4> bpfis: Callback made to bpbrm.
14:11:09.714 [3140.1640] <32> bpfis: FTL - In case of snapshot creation using vendor VSS hardware provider, snapshot devices may get leaked due to incomplete import operation. VSS framework does not allow to delete un-imported snapshot. The leaked snapshot devices can be recovered using Microsoft Vshadow utility. Please use the xml file [C:\Program Files\Veritas\NetBackup\temp\bpfis.fim.fs-de004_1424351454.1.0.xml] created on client [fs-de004.viasyshc.eu] to import and delete the snapshot manually using Vshadow utility from alternate client [bs-tmf001.tmf.viasyshc.eu]. Please refer event viewer and Hardware VSS provider logs for more details. Delete the file manually after cleanup.
14:11:09.714 [3140.1640] <4> try_vss_unlockmutex: VSS Snapshot Mutex Unlock
14:11:09.714 [3140.1640] <16> bpfis: FTL - snapshot creation failed, status 4213
14:11:09.714 [3140.1640] <4> bpfis: INF - Thawing I:\ using snapshot method VSS.
14:11:09.714 [3140.1640] <4> bpfis: INF - do_thaw return value: 0
14:11:09.714 [3140.1640] <4> bpfis: INF - Deleted mount point C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_I__3140_1
14:11:09.714 [3140.1640] <4> bpfis: Starting keep alive thread.
14:11:09.792 [3140.1640] <4> bpfis: INF - EXIT STATUS 4213: Snapshot import failed
14:11:19.246 [4008.2668] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe delete -nbu -id fs-de004_1424351454 -bpstart_to 300 -bpend_to 300 -clnt fs-de004 -jobgrpid 10599 -jobid 10599 -copy 1 -S bs-tmf001.tmf.viasyshc.eu -fim VSS:prov_type=3,snap_attr=0,max_snapshots=1 -rhost bs-tmf001.tmf.viasyshc.eu 
14:11:19.246 [4008.2668] <2> bpfis main: received FIM as [43] VSS:prov_type=3,snap_attr=0,max_snapshots=1
14:11:19.246 [4008.2668] <4> bpfis: Starting keep alive thread.
14:11:19.277 [4008.2668] <2> vnet_pbxConnect: pbxConnectEx Succeeded
14:11:19.277 [4008.2668] <2> logconnections: BPRD CONNECT FROM 10.240.98.166.50525 TO 10.240.99.26.1556 fd = 556
14:11:20.868 [4008.2668] <4> bpfis: INF - BACKUP START 4008
14:11:20.868 [4008.2668] <4> bpfis main: read_registry_dw_value for VSS_CONCURRENT_OPERATIONS: return status 2, return value 0
14:11:20.868 [4008.2668] <4> bpfis main: VSS Snapshot Mutex lock acquired
14:11:20.868 [4008.2668] <32> bpfis: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.fs-de004_1424351454.1.0
14:11:20.868 [4008.2668] <4> bpfis: Starting keep alive thread.
14:11:20.868 [4008.2668] <4> bpfis: INF - EXIT STATUS 4207: Could not fetch snapshot metadata or state files
14:11:20.868 [4008.2668] <4> try_vss_unlockmutex: VSS Snapshot Mutex Unlock

------------------------------------------------------------------

Could anybody give me some advice where to search for the reason of this issue or to solve it?

[Marianne]

Check NBU Service logon accounts on client and media server. 
It is possible that these got changed with the patch installation.

Another thing - I have learned that when using Snapshot Client with offhost backup, the NBU version and patch levels on client and offhost client/media server must be identical.
I have seen failures where media server was upgraded and client was not.

[MirkoG]

Thank you, I will check the logon accounts and keep you posted.

First the versions were different but I've updated the client today also and they both have now the identical verison. 

[MirkoG]

The logon accounts at the server and the client are set to Local System account

[MirkoG · Accepted solution]

I've finally found the solution.

To solve this issue I had to enter the iSCSI IP address of the Storage at Quick Connect of the iSCSI Initiatior and perform a Quick Connect. After this I saw the created Snapshots, which couldn't be backuped.

So even if the connection to the Storage was established I had to do also a Quick Connect. Don't know why. So it was not related to the update of Netbackup. This week I had to reinstall the backup server and even this didn't solve the issue.

Now the off-host backups are running fine.