snapshot error encountered (156)

Hello everyone,

I hope you are doing well!

I have the same error with NetBackup 10.1, Backup of some VMware clients is failing with a snapshot error encountered(156). I would greatly appreciate any assistance or guidance you can provide.

you can find the script of the error. attached. 

Thank you in advance for your support.

Hello Marianne, 

as per the artrical of netbackup which you share me i tried to keep Volume Shadow Copy Service on Manul mode.  but the issue is still persists.

Regards

Please ignore the references to Horizon View in this TN to understand the difference between VMware snapshot and NBU snapshot:

Hello Michal,

yea i took the snapshot from vSphere console directly and it was successfully,but while take backup from netbackup i identify that it's gives the error vmwareLogger: ChangeTracking not supported and it will processed to child job and its gives error code snapshot error encountered (156).

Regards

Can you see any errors in vCenter when the snapshot error occurs?

Is "Volume Shadow Copy" service on the VM set to Manual or Disabled?

We also see this error: 

VMware error received: The operation is not allowed in the current state. 

Please work with VM admin to find out in what 'state' this VM is. 

Found this TN : 

VMWare snapshot is failing: Status 156 - The operation is not allowed in the current state. 
http://www.veritas.com/docs/000023476 

Hello,

as I mentioned above, concentrate on VMware side:

VMware error received: The operation is not allowed in the current state.

Did you try to take a snapshot from vSphere console directly and was it successful?

Regards

Michal

12:22:18.725 [12216.13280] <2> fis_delete_id: INF - removing C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.pbad-vc_1465291165.1.0.VM_ObjInfoXML.xml
12:22:18.725 [12216.13280] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_UNLOCK>, timeout <0>, status <156>.
12:22:18.725 [12216.13280] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
12:22:18.725 [12216.13280] <4> keep_alive_and_snapshot_control: Exiting.
12:22:18.725 [12216.13280] <2> ol_cleanup: INF - removing C:\Program Files\Veritas\NetBackup\temp\VMWare-VCenter+12216+1.std_filelist
12:22:18.725 [12216.13280] <4> bpfis Exit: INF - EXIT STATUS 156: snapshot error encountered
12:22:18.725 [12216.13280] <2> stop_keep_alive_thread: INF - Stop keep_alive thread 
12:22:20.191 [16008.14480] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe delete -nbu -id pbad-vc_1465291165 -bpstart_to 500 -bpend_to 500 -clnt pbad-netbackup.pbad.sbg.com.sa -jobgrpid 882250 -jobid 882250 -fscp 1 -fscp_cksv 0 -copy 1 -rp 1209600 -rtype 0 -backupid pbad-vc_1465291165 -status 156 -S pbad-netbackup.pbad.sbg.com.sa -noserverstate -fim VMware_v2:Virtual_machine_backup=2,disable_quiesce=0,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd:hotadd:nbdssl 
12:22:20.191 [16008.14480] <2> bpfis main: received FIM as [253] VMware_v2:Virtual_machine_backup=2,disable_quiesce=0,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd:hotadd:nbdssl
12:22:20.191 [16008.14480] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_LOCK>, timeout <5>, status <0>.
12:22:20.191 [16008.14480] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
12:22:20.191 [16008.14480] <2> start_keep_alive_thread: INF - Start keep_alive thread 
12:22:20.191 [16008.14480] <4> snapshotlock: Acquiring snapshot lock:retry count [0] 
12:22:20.191 [16008.15744] <2> send_keep_alive: INF - sending keep alive
12:22:20.191 [16008.14480] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock]
12:22:20.191 [16008.14480] <2> rw_lock:   LockFileEx WRITELOCK
12:22:20.191 [16008.14480] <2> rw_lock:   Lock acquired
12:22:20.191 [16008.14480] <2> snapshotlock: Acquired snapshot lock :refcount[0]
12:22:20.191 [16008.14480] <4> keep_alive_and_snapshot_control: Exiting.
12:22:20.191 [16008.14480] <2> bpfis_state_on_master_xfer_level: bpfis state file transfer is disabled (level = 0), touch file exists: 0, -noserverstate: 1, -nbu: 1
12:22:20.191 [16008.14480] <4> bpfis main: INF - BACKUP START 16008
12:22:20.191 [16008.14480] <32> fis_rebuild_from_db: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.pbad-vc_1465291165.1.0
12:22:20.222 [16008.14480] <4> keep_alive_and_snapshot_control: Entering with request <SNAPSHOT_UNLOCK>, timeout <0>, status <4207>.
12:22:20.222 [16008.14480] <4> keep_alive_and_snapshot_control: Starting keep alive thread.
12:22:20.222 [16008.14480] <2> deleteReference:    reference not found in the list
12:22:20.222 [16008.14480] <4> unlockSnapshot: Delete reference: status [-4]
12:22:20.222 [16008.14480] <2> writeSnapshotLockFile:    Writing type[2] refcount[0]
12:22:20.222 [16008.14480] <2> writeSnapshotLockFile:    Writing Flags [0] [0]
12:22:20.222 [16008.14480] <2> writeSnapshotLockFile:   Writing Last addReffernt Time [Thu Jan 01 03:00:00 1970
]
12:22:20.222 [16008.14480] <2> writeSnapshotLockFile:   Writing Last Hostname []
12:22:20.285 [16008.14480] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock]
12:22:20.285 [16008.14480] <2> unlockSnapshot:    file[C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock] : zero reference count 
12:22:20.285 [16008.14480] <4> unlockSnapshot: Released snapshot lock: status [0] 
12:22:20.285 [16008.14480] <4> keep_alive_and_snapshot_control: Exiting.
12:22:20.285 [16008.14480] <4> do_post_processing: Deleting snapshot lock files from client for id [pbad-vc_1465291165] and copy_number [1]
12:22:20.285 [16008.14480] <2> getFileName:  FileName is [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock]
12:22:20.285 [16008.14480] <2> deleteSnapshotLockFile:   Renamed lock file from [C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\pbad-vc_1465291165_copy1.lock] to [\sfk8.] for deletion
12:22:20.285 [16008.14480] <2> deleteSnapshotLockFile:   File[\sfk8.] deleted: status[0]
12:22:20.285 [16008.14480] <4> bpfis Exit: INF - EXIT STATUS 4207: Could not fetch snapshot metadata or state files
12:22:20.285 [16008.14480] <2> bpfis Exit: INF - Close of stdout complete
12:22:20.737 [12216.13280] <2> bpfis Exit: INF - Close of stdout complete
 

The timestamps in Job Details do not correspond with bpfis log. 

We need bpfis log on the backup host for 6/7/2016  that shows PID 16008.

Hello Marianne,

please find the job details below

6/7/2016 12:19:25 PM - Info nbjm(pid=6932) starting backup job (jobid=882250) for client pbad-vc, policy VMWare-VCenter, schedule Daily  
6/7/2016 12:19:25 PM - Info nbjm(pid=6932) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=882250, request id:{B775DBED-8B46-4369-8A26-194AB983AC45})  
6/7/2016 12:19:25 PM - requesting resource Netbackup_StorageUnit
6/7/2016 12:19:25 PM - requesting resource pbad-netbackup.pbad.sbg.com.sa.NBU_CLIENT.MAXJOBS.pbad-vc
6/7/2016 12:19:25 PM - requesting resource pbad-netbackup.pbad.sbg.com.sa.NBU_POLICY.MAXJOBS.VMWare-VCenter
6/7/2016 12:19:25 PM - granted resource pbad-netbackup.pbad.sbg.com.sa.NBU_CLIENT.MAXJOBS.pbad-vc
6/7/2016 12:19:25 PM - granted resource pbad-netbackup.pbad.sbg.com.sa.NBU_POLICY.MAXJOBS.VMWare-VCenter
6/7/2016 12:19:25 PM - granted resource MediaID=@aaaaC;DiskVolume=PureDiskVolume;DiskPool=Netbackup_Disk_Pool;Path=PureDiskVolume;StorageServer=pbad-netbackup.pbad.sbg.com.sa;MediaServer=pbad-netbackup.pbad.sbg.com.sa
6/7/2016 12:19:25 PM - granted resource Netbackup_StorageUnit
6/7/2016 12:19:25 PM - started
6/7/2016 12:19:26 PM - estimated 0 Kbytes needed
6/7/2016 12:19:26 PM - begin Parent Job
6/7/2016 12:19:26 PM - begin VMware, Start Notify Script
6/7/2016 12:19:27 PM - Info RUNCMD(pid=10416) started            
6/7/2016 12:19:27 PM - Info RUNCMD(pid=10416) exiting with status: 0         
Status 0
6/7/2016 12:19:27 PM - end VMware, Start Notify Script; elapsed time: 0:00:01
6/7/2016 12:19:27 PM - begin VMware, Step By Condition
Status 0
6/7/2016 12:19:27 PM - end VMware, Step By Condition; elapsed time: 0:00:00
6/7/2016 12:19:27 PM - begin VMware, Read File List
Status 0
6/7/2016 12:19:27 PM - end VMware, Read File List; elapsed time: 0:00:00
6/7/2016 12:19:27 PM - begin VMware, Create Snapshot
6/7/2016 12:19:28 PM - Info bpbrm(pid=12864) pbad-vc is the host to backup data from     
6/7/2016 12:19:28 PM - Info bpbrm(pid=12864) reading file list for client        
6/7/2016 12:19:28 PM - Info bpbrm(pid=12864) start bpfis on client         
6/7/2016 12:19:28 PM - started process bpbrm (12864)
6/7/2016 12:19:31 PM - Info bpbrm(pid=12864) Starting create snapshot processing         
6/7/2016 12:19:32 PM - Info bpfis(pid=12216) Backup started           
6/7/2016 12:19:34 PM - snapshot backup of client pbad-vc using method VMware_v2
6/7/2016 12:19:37 PM - Info bpbrm(pid=12864) INF - vmwareLogger: ChangeTracking not supported       
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - VMware_freeze: VIXAPI freeze (VMware snapshot) failed with -1: Unrecognized error
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - VMware error received: The operation is not allowed in the current state.
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze 
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL -        
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze 
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL -        
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - snapshot processing failed, status 156   
6/7/2016 12:22:18 PM - Critical bpbrm(pid=12864) from client pbad-vc: FTL - snapshot creation failed, status 156   
6/7/2016 12:22:18 PM - Warning bpbrm(pid=12864) from client pbad-vc: WRN - ALL_LOCAL_DRIVES is not frozen    
6/7/2016 12:22:18 PM - Info bpfis(pid=12216) done. status: 156          
6/7/2016 12:22:18 PM - end VMware, Create Snapshot; elapsed time: 0:02:51
6/7/2016 12:22:18 PM - Info bpfis(pid=12216) done. status: 156: snapshot error encountered       
6/7/2016 12:22:18 PM - end writing
Status 156
6/7/2016 12:22:18 PM - end Parent Job; elapsed time: 0:02:52
6/7/2016 12:22:18 PM - begin VMware, Stop On Error
Status 0
6/7/2016 12:22:18 PM - end VMware, Stop On Error; elapsed time: 0:00:00
6/7/2016 12:22:18 PM - begin VMware, Delete Snapshot
6/7/2016 12:22:19 PM - started process bpbrm (1448)
6/7/2016 12:22:19 PM - Info bpbrm(pid=1448) Starting delete snapshot processing         
6/7/2016 12:22:20 PM - Info bpfis(pid=16008) Backup started           
6/7/2016 12:22:20 PM - Critical bpbrm(pid=1448) from client pbad-vc: cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.pbad-vc_1465291165.1.0      
6/7/2016 12:22:20 PM - Info bpfis(pid=16008) done. status: 4207          
6/7/2016 12:22:20 PM - end VMware, Delete Snapshot; elapsed time: 0:00:02
6/7/2016 12:22:20 PM - Info bpfis(pid=16008) done. status: 4207: Could not fetch snapshot metadata or state files  
6/7/2016 12:22:20 PM - end writing
Status 4207
6/7/2016 12:22:20 PM - end Parent Job; elapsed time: 0:02:54
6/7/2016 12:22:20 PM - begin VMware, End Notify Script
6/7/2016 12:22:20 PM - Info RUNCMD(pid=8480) started            
6/7/2016 12:22:20 PM - Info RUNCMD(pid=8480) exiting with status: 0         
Status 0
6/7/2016 12:22:20 PM - end VMware, End Notify Script; elapsed time: 0:00:00
Status 156
6/7/2016 12:22:20 PM - end operation
snapshot error encountered (156)