Video Screencast Help
Symantec to Separate Into Two Focused, Industry-Leading Technology Companies. Learn more.

Intermittent snapshot errors (status 156) on two Windows clients

Created: 01 Feb 2013 • Updated: 25 Jul 2013 | 4 comments
This issue has been solved. See solution.

I have a couple of Windows Server 2008 clients that are experiencing intermittent snapshot failures with similar error messages in the job detail. There doesn't seem to be much rhyme or reason to it, and both full and incremental backups are affected. Environment and job details follow.

Master: NBU 7.5.0.4 on SunOS UNIX 5.10

Media: NBU 7.5.0.4 on SunOS UNIX 5.10

Clients: Windows Server 2008 (one is a Hyper-V host, the other hosts SQL Server databases) running NBU client 7.0

Hyper-V host:

01/31/2013 21:15:50 - Info nbjm (pid=1605) starting backup job (jobid=3922967) for client bknhicodchv09, policy NHIC-HOST, schedule Full
01/31/2013 21:15:50 - Info nbjm (pid=1605) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=3922967, request id:{4C326D90-6C15-11E2-954A-1CC1DE1EF662})
01/31/2013 21:15:50 - requesting resource bkbugatti-hcart-robot-tld-0
01/31/2013 21:15:50 - requesting resource bkferrari.NBU_CLIENT.MAXJOBS.bknhicodchv09
01/31/2013 21:15:50 - requesting resource bkferrari.NBU_POLICY.MAXJOBS.NHIC-HOST
01/31/2013 21:16:36 - awaiting resource bkbugatti-hcart-robot-tld-0. Maximum job count has been reached for the storage unit.
01/31/2013 21:38:40 - awaiting resource bkbugatti-hcart-robot-tld-0. Waiting for resources.
          Reason: Drives are in use, Media server: bkbugatti,
          Robot Type(Number): TLD(0), Media ID: N/A, Drive Name: N/A,
          Volume Pool: NHIC, Storage Unit: bkbugatti-hcart-robot-tld-0, Drive Scan Host: N/A,
          Disk Pool: N/A, Disk Volume: N/A
01/31/2013 21:38:50 - awaiting resource bkbugatti-hcart-robot-tld-0. Maximum job count has been reached for the storage unit.
01/31/2013 22:12:59 - awaiting resource bkbugatti-hcart-robot-tld-0. Waiting for resources.
          Reason: Drives are in use, Media server: bkbugatti,
          Robot Type(Number): TLD(0), Media ID: N/A, Drive Name: N/A,
          Volume Pool: NHIC, Storage Unit: bkbugatti-hcart-robot-tld-0, Drive Scan Host: N/A,
          Disk Pool: N/A, Disk Volume: N/A
01/31/2013 22:17:04 - awaiting resource bkbugatti-hcart-robot-tld-0. Maximum job count has been reached for the storage unit.
01/31/2013 22:23:26 - granted resource  bkferrari.NBU_CLIENT.MAXJOBS.bknhicodchv09
01/31/2013 22:23:26 - granted resource  bkferrari.NBU_POLICY.MAXJOBS.NHIC-HOST
01/31/2013 22:23:26 - granted resource  NH4353
01/31/2013 22:23:26 - granted resource  HP.ULTRIUM4-SCSI.012
01/31/2013 22:23:26 - granted resource  bkbugatti-hcart-robot-tld-0
01/31/2013 22:23:27 - estimated 2610454975 kbytes needed
01/31/2013 22:23:27 - Info nbjm (pid=1605) started backup (backupid=bknhicodchv09_1359689006) job for client bknhicodchv09, policy NHIC-HOST, schedule Full on storage unit bkbugatti-hcart-robot-tld-0
01/31/2013 22:23:30 - started process bpbrm (pid=17584)
01/31/2013 22:23:45 - Info bpbrm (pid=17584) bknhicodchv09 is the host to backup data from
01/31/2013 22:23:45 - Info bpbrm (pid=17584) reading file list from client
01/31/2013 22:23:45 - connecting
01/31/2013 22:23:59 - Info bpbrm (pid=17584) starting bpbkar on client
01/31/2013 22:23:59 - connected; connect time: 0:00:00
01/31/2013 22:24:01 - Info bpbkar (pid=0) Backup started
01/31/2013 22:24:01 - Info bpbrm (pid=17584) bptm pid: 17627
01/31/2013 22:24:02 - Info bptm (pid=17627) start
01/31/2013 22:24:02 - Info bptm (pid=17627) using 65536 data buffer size
01/31/2013 22:24:02 - Info bptm (pid=17627) setting receive network buffer to 262144 bytes
01/31/2013 22:24:02 - Info bptm (pid=17627) using 30 data buffers
01/31/2013 22:24:02 - Info bptm (pid=17627) start backup
01/31/2013 22:24:02 - Info bptm (pid=17627) backup child process is pid 17628
01/31/2013 22:24:02 - Info bptm (pid=17627) media id NH4353 mounted on drive index 0, drivepath /dev/rmt/14cbn, drivename HP.ULTRIUM4-SCSI.012, copy 1
01/31/2013 22:24:03 - mounted NH4353
01/31/2013 22:24:03 - positioning NH4353 to file 3
01/31/2013 22:24:04 - positioned NH4353; position time: 0:00:01
01/31/2013 22:24:04 - begin writing
01/31/2013 22:35:59 - Info bpbkar (pid=0) 5000 entries sent to bpdbm
01/31/2013 22:37:42 - Info bpbkar (pid=0) 10000 entries sent to bpdbm
01/31/2013 22:44:15 - Info bpbkar (pid=0) 15000 entries sent to bpdbm
01/31/2013 22:49:52 - Info bpbkar (pid=0) 20000 entries sent to bpdbm
02/01/2013 04:52:43 - Error bpbrm (pid=17584) from client bknhicodchv09: ERR - failure reading file: I:\NHICODCERMSP05\NHICODCERMSP05\Snapshots\114CC1E3-EC6A-40DA-9ECF-8A709FA3D9EF\NHICODCERMSP05-D_1AE819AB-D58C-4A68-B7D8-A9A0EA5DA992.avhd (WIN32 2: The system cannot find the file specified. )
02/01/2013 04:52:44 - Error bpbrm (pid=17584) from client bknhicodchv09: ERR - Snapshot Error while reading file: GLOBALROOT\Device\HarddiskVolumeShadowCopy113\NHICODCERMSP05\NHICODCERMSP05\Snapshots\114CC1E3-EC6A-40DA-9ECF-8A709FA3D9EF\NHICODCERMSP05-D_1AE819AB-D58C-4A68-B7D8-A9A0EA5DA992.avhd
02/01/2013 04:52:44 - Critical bpbrm (pid=17584) from client bknhicodchv09: FTL - Backup operation aborted!
02/01/2013 04:52:46 - Error bptm (pid=17627) media manager terminated by parent process
02/01/2013 04:53:49 - Error bpbrm (pid=17584) could not send server status message
02/01/2013 04:53:57 - Info bpbkar (pid=0) done. status: 156: snapshot error encountered
02/01/2013 04:53:57 - end writing; write time: 6:29:53
02/01/2013 04:54:05 - Info bpbrm (pid=25338) Starting delete snapshot processing
02/01/2013 04:54:05 - Info bpfis (pid=0) Snapshot will not be deleted
02/01/2013 04:54:19 - Error bpbrm (pid=25338) from client bknhicodchv09: ERR - Get bpfis state from bkferrari failed. status = 25
02/01/2013 04:54:19 - Info bpfis (pid=5372) Backup started
02/01/2013 04:54:19 - Critical bpbrm (pid=25338) from client bknhicodchv09: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.bknhicodchv09_1359689006.0
02/01/2013 04:54:22 - Error bpbrm (pid=25338) from client bknhicodchv09: ERR - Send bpfis state from bkferrari failed. status = 25
02/01/2013 04:54:22 - Info bpfis (pid=5372) done. status: 0
02/01/2013 04:54:22 - Info bpfis (pid=0) done. status: 0: the requested operation was successfully completed
snapshot error encountered  (156)
 

SQL Server:

01/31/2013 20:12:21 - Info nbjm (pid=1605) starting backup job (jobid=3922566) for client bknhicodcsqlp02, policy NHIC-SQL, schedule Diff
01/31/2013 20:12:21 - Info nbjm (pid=1605) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=3922566, request id:{6E16A6A0-6C0C-11E2-827D-1CC1DE1EF662})
01/31/2013 20:12:21 - requesting resource bkbugatti-hcart-robot-tld-0
01/31/2013 20:12:21 - requesting resource bkferrari.NBU_CLIENT.MAXJOBS.bknhicodcsqlp02
01/31/2013 20:12:21 - requesting resource bkferrari.NBU_POLICY.MAXJOBS.NHIC-SQL
01/31/2013 20:12:34 - awaiting resource bkbugatti-hcart-robot-tld-0. Maximum job count has been reached for the storage unit.
01/31/2013 20:16:37 - awaiting resource bkbugatti-hcart-robot-tld-0. Waiting for resources.
          Reason: Drives are in use, Media server: bkbugatti,
          Robot Type(Number): TLD(0), Media ID: N/A, Drive Name: N/A,
          Volume Pool: NHIC, Storage Unit: bkbugatti-hcart-robot-tld-0, Drive Scan Host: N/A,
          Disk Pool: N/A, Disk Volume: N/A
01/31/2013 20:21:55 - granted resource  bkferrari.NBU_CLIENT.MAXJOBS.bknhicodcsqlp02
01/31/2013 20:21:55 - granted resource  bkferrari.NBU_POLICY.MAXJOBS.NHIC-SQL
01/31/2013 20:21:55 - granted resource  NH4231
01/31/2013 20:21:55 - granted resource  HP.ULTRIUM4-SCSI.015
01/31/2013 20:21:55 - granted resource  bkbugatti-hcart-robot-tld-0
01/31/2013 20:21:55 - estimated 438429218 kbytes needed
01/31/2013 20:21:55 - Info nbjm (pid=1605) started backup (backupid=bknhicodcsqlp02_1359681715) job for client bknhicodcsqlp02, policy NHIC-SQL, schedule Diff on storage unit bkbugatti-hcart-robot-tld-0
01/31/2013 20:22:00 - started process bpbrm (pid=9324)
01/31/2013 20:22:17 - Info bpbrm (pid=9324) bknhicodcsqlp02 is the host to backup data from
01/31/2013 20:22:17 - Info bpbrm (pid=9324) reading file list from client
01/31/2013 20:22:17 - connecting
01/31/2013 20:22:32 - Info bpbrm (pid=9324) starting bpbkar on client
01/31/2013 20:22:32 - connected; connect time: 0:00:00
01/31/2013 20:22:34 - Info bpbkar (pid=0) Backup started
01/31/2013 20:22:34 - Info bpbrm (pid=9324) bptm pid: 9353
01/31/2013 20:22:34 - Info bptm (pid=9353) start
01/31/2013 20:22:35 - Info bptm (pid=9353) using 65536 data buffer size
01/31/2013 20:22:35 - Info bptm (pid=9353) setting receive network buffer to 262144 bytes
01/31/2013 20:22:35 - Info bptm (pid=9353) using 30 data buffers
01/31/2013 20:22:35 - Info bptm (pid=9353) start backup
01/31/2013 20:22:35 - Info bptm (pid=9353) backup child process is pid 9354
01/31/2013 20:22:35 - Info bptm (pid=9353) Waiting for mount of media id NH4231 (copy 1) on server bkbugatti.
01/31/2013 20:22:35 - mounting NH4231
01/31/2013 20:23:41 - Info bptm (pid=9353) media id NH4231 mounted on drive index 3, drivepath /dev/rmt/23cbn, drivename HP.ULTRIUM4-SCSI.015, copy 1
01/31/2013 20:23:41 - mounted NH4231; mount time: 0:01:06
01/31/2013 20:23:41 - positioning NH4231 to file 13
01/31/2013 20:25:45 - positioned NH4231; position time: 0:02:04
01/31/2013 20:25:45 - begin writing
01/31/2013 20:51:19 - Info bpbkar (pid=0) 5000 entries sent to bpdbm
01/31/2013 20:56:25 - Error bpbrm (pid=9324) from client bknhicodcsqlp02: ERR - failure reading file: D:\MSSQL10_50.MSSQLSERVER\MSSQL\Backup\MonarchES\MonarchES_backup_2013_01_31_190335_8986465.bak (WIN32 2: The system cannot find the file specified. )
01/31/2013 20:56:26 - Error bpbrm (pid=9324) from client bknhicodcsqlp02: ERR - Snapshot Error while reading file: GLOBALROOT\Device\HarddiskVolumeShadowCopy90\MSSQL10_50.MSSQLSERVER\MSSQL\Backup\MonarchES\MonarchES_backup_2013_01_31_190335_8986465.bak
01/31/2013 20:56:27 - Critical bpbrm (pid=9324) from client bknhicodcsqlp02: FTL - Backup operation aborted!
01/31/2013 20:56:29 - Error bptm (pid=9353) media manager terminated by parent process
01/31/2013 20:57:56 - Error bpbrm (pid=9324) could not send server status message
01/31/2013 20:58:04 - Info bpbkar (pid=0) done. status: 156: snapshot error encountered
01/31/2013 20:58:04 - end writing; write time: 0:32:19
01/31/2013 20:58:17 - Info bpbrm (pid=11488) Starting delete snapshot processing
01/31/2013 20:58:17 - Info bpfis (pid=0) Snapshot will not be deleted
01/31/2013 20:58:33 - Error bpbrm (pid=11488) from client bknhicodcsqlp02: ERR - Get bpfis state from bkferrari failed. status = 25
01/31/2013 20:58:33 - Info bpfis (pid=5288) Backup started
01/31/2013 20:58:33 - Critical bpbrm (pid=11488) from client bknhicodcsqlp02: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.bknhicodcsqlp02_1359681715.0
01/31/2013 20:58:35 - Error bpbrm (pid=11488) from client bknhicodcsqlp02: ERR - Send bpfis state from bkferrari failed. status = 25
01/31/2013 20:58:35 - Info bpfis (pid=5288) done. status: 0
01/31/2013 20:58:35 - Info bpfis (pid=0) done. status: 0: the requested operation was successfully completed
snapshot error encountered  (156)

Any suggestions?

Thanks,

Wayne

Discussion Filed Under:

Comments 4 CommentsJump to latest comment

RamNagalla's picture

hi,

are those clients in Cluster?

do they have the shared Drives?

if yes.consider below tech note

http://www.symantec.com/business/support/index?pag...

RamNagalla's picture

hi,

please follow the below documnets to determinte the if the issue with netbackup or with VSS

http://www.symantec.com/business/support/index?pag...

WayneLackey's picture

Thanks to everyone for their suggestions. For the Hyper-V host, it turns out the shadow copy area was not of sufficient capacity to allow the snapshot to complete successfully. Once the shadow copy was increased, the snapshot was created successfully, in turn allowing the backup to complete.

The other server was decommissioned, and is no longer an issue.

Wayne

SOLUTION