Netbackup Tape drive path go down as 2 policies are activated from same NDMP client

[Netuk]

Hi,

We have a ploblem of IBM Tape drive path ( from netbackup side) go down when 2 policies activated from same NDMP client. We use NetApp filer as NDMP clients and tape drives are directly zoned to NetApp filers and using 3-way NDMP backups. Recently upgraded to Windows 2012 R2 and Netbackup 7.6.0.4.

Any help appreciated.

[Marianne]

Please share all text in Details tab of failed jobs. This will indication of where to start looking. Is job running successful when only 1 job is started?

[Netuk]

Thanks Marianne..

Yes .. it runs successfully only in one drive other drive path has gone down. Even cannot bring up. the backup stops with error 196 after backup window closed.

6/13/2015 9:19:58 AM - awaiting resource veritas-hcart-robot-tld-0-<netapp_client1> Reason: Drives are in use, Media Server: veritas,

Unfortunately we face multiple issues. We get multiple error codes as error 86, 99.

Due to the criticality of the error I have created a support call with netbackup support and they are looking at the issue.Netbackup support has instructed to get Tape library vendor (IBM) to get involved and stating that it can be an issue with tape drives, because tape drive cleaning has done many times a day.Windows event viewer showed tape drive error code as well.

Following are the other errors we got.

####

6/11/2015 7:02:54 PM - Info nbjm(pid=3648) starting backup job (jobid=230) for client <netapp_client1>, policy PRD_SRM2, schedule Daily_Full  
6/11/2015 7:02:54 PM - Info nbjm(pid=3648) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=230, request id:{C7C97E77-7313-41EF-8A59-5A89C5545983})  
6/11/2015 7:02:54 PM - requesting resource veritas-hcart-robot-tld-0-<netapp_client1>
6/11/2015 7:02:54 PM - requesting resource veritas.NBU_CLIENT.MAXJOBS.<netapp_client1>
6/11/2015 7:02:54 PM - requesting resource veritas.NBU_POLICY.MAXJOBS.PRD_SRM2
6/11/2015 7:02:54 PM - granted resource veritas.NBU_CLIENT.MAXJOBS.<netapp_client1>
6/11/2015 7:02:54 PM - granted resource veritas.NBU_POLICY.MAXJOBS.PRD_SRM2
6/11/2015 7:02:54 PM - granted resource H878L4
6/11/2015 7:02:54 PM - granted resource IBM.ULT3580-TD4.000
6/11/2015 7:02:54 PM - granted resource veritas-hcart-robot-tld-0-<netapp_client1>
6/11/2015 7:02:59 PM - estimated 3899114690 Kbytes needed
6/11/2015 7:02:59 PM - Info nbjm(pid=3648) started backup (backupid=<netapp_client1>_1434029576) job for client <netapp_client1>, policy PRD_SRM2, schedule Daily_Full on storage unit veritas-hcart-robot-tld-0-<netapp_client1>
6/11/2015 7:03:04 PM - started process bpbrm (2564)
6/11/2015 7:03:04 PM - Info bpbrm(pid=2564) <netapp_client1> is the host to backup data from     
6/11/2015 7:03:08 PM - Info bpbrm(pid=2564) reading file list for client        
6/11/2015 7:03:08 PM - connecting
6/11/2015 7:03:13 PM - Info bpbrm(pid=2564) starting ndmpagent on client         
6/11/2015 7:03:13 PM - Info ndmpagent(pid=5924) Backup started           
6/11/2015 7:03:13 PM - connected; connect time: 0:00:05
6/11/2015 7:03:13 PM - Info bptm(pid=5204) start            
6/11/2015 7:03:37 PM - Info bptm(pid=5204) using 30 data buffers         
6/11/2015 7:03:37 PM - Info bptm(pid=5204) using 65536 data buffer size        
6/11/2015 7:03:42 PM - Info bptm(pid=5204) start backup           
6/11/2015 7:03:42 PM - Info bptm(pid=5204) Waiting for mount of media id H878L4 (copy 1) on server veritas.
6/11/2015 7:03:42 PM - mounting H878L4
6/11/2015 7:04:49 PM - Info bptm(pid=5204) media id H878L4 mounted on drive index 0, drivepath nrst1a, drivename IBM.ULT3580-TD4.000, copy 1
6/11/2015 7:04:49 PM - mounted; mount time: 0:01:07
6/11/2015 7:04:49 PM - Info ndmpagent(pid=5924) <netapp_client1>: SCSI: TAPE READ: short read for nrst1a     
6/11/2015 7:04:54 PM - positioning H878L4 to file 8
6/11/2015 7:05:23 PM - positioned H878L4; position time: 0:00:29
6/11/2015 7:05:23 PM - begin writing
6/11/2015 7:05:30 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Using Full Volume Dump       
6/11/2015 7:05:35 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Date of this level 0 dump: Thu Jun 11 01:04:29 2015.
6/11/2015 7:05:40 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Date of last level 0 dump: the epoch.   
6/11/2015 7:05:44 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Dumping /vol/srm2/.snapshot/latest to NDMP connection      
6/11/2015 7:05:49 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: mapping (Pass I)[regular files]       
6/11/2015 7:07:18 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: mapping (Pass II)[directories]        
6/11/2015 7:07:23 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: estimated 3603226481 KB.        
6/11/2015 7:07:27 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: dumping (Pass III) [directories]       
6/11/2015 7:07:32 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: dumping (Pass IV) [regular files]      
6/11/2015 7:12:18 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Thu Jun 11 19:07:45 2015 : We have written 15066492 KB.
6/11/2015 7:17:18 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Thu Jun 11 19:12:45 2015 : We have written 28587722 KB.
6/11/2015 7:22:20 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Thu Jun 11 19:17:46 2015 : We have written 38089733 KB.
6/11/2015 7:29:13 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Media error on tape write.      
6/11/2015 7:29:17 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: Thu Jun 11 19:24:40 2015 : We have written 39608773 KB.
6/11/2015 7:29:22 PM - Info ndmpagent(pid=5924) <netapp_client1>: DUMP: DUMP IS ABORTED        
6/11/2015 7:29:27 PM - Error ndmpagent(pid=5924) <netapp_client1>: DATA: Backup terminated: EVENT: BAD_MEDIA (for /vol/srm2/.snapshot/latest)     
6/11/2015 7:29:31 PM - Error ndmpagent(pid=5924) NDMP backup failed, path = /vol/srm2/.snapshot/latest       
6/11/2015 7:29:36 PM - Error bptm(pid=5204) none of the NDMP backups for client <netapp_client1> completed successfully   
6/11/2015 7:29:41 PM - Error bptm(pid=5204) io_ioctl_ndmp (MTBSF) failed on media id H878L4, drive index 0, return code 7 (NDMP_IO_ERR) (bptm.c.8897)
6/11/2015 7:29:47 PM - Info bptm(pid=5204) EXITING with status 99 <----------        
6/11/2015 7:29:47 PM - Info ndmpagent(pid=0) done. status: 99: NDMP backup failure       
6/11/2015 7:29:47 PM - end writing; write time: 0:24:24
NDMP backup failure(99)
6/11/2015 8:01:26 PM - job 230 was restarted as job 232

########

/12/2015 5:54:48 AM - Info nbjm(pid=3648) starting backup job (jobid=242) for client <netapp_client2>, policy PRD_SRM, schedule Daily_Full  
6/12/2015 5:54:48 AM - Info nbjm(pid=3648) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=242, request id:{AC15245E-1BE8-4967-94C2-A592B9FDAA61})  
6/12/2015 5:54:48 AM - requesting resource veritas-hcart-robot-tld-0-<netapp_client2>
6/12/2015 5:54:48 AM - requesting resource veritas.NBU_CLIENT.MAXJOBS.<netapp_client2>
6/12/2015 5:54:48 AM - requesting resource veritas.NBU_POLICY.MAXJOBS.PRD_SRM
6/12/2015 5:54:48 AM - granted resource veritas.NBU_CLIENT.MAXJOBS.<netapp_client2>
6/12/2015 5:54:48 AM - granted resource veritas.NBU_POLICY.MAXJOBS.PRD_SRM
6/12/2015 5:54:48 AM - granted resource L621L4
6/12/2015 5:54:48 AM - granted resource IBM.ULT3580-TD4.001
6/12/2015 5:54:48 AM - granted resource veritas-hcart-robot-tld-0-<netapp_client2>
6/12/2015 5:54:52 AM - estimated 3807366578 Kbytes needed
6/12/2015 5:54:52 AM - Info nbjm(pid=3648) started backup (backupid=<netapp_client2>_1434068690) job for client <netapp_client2>, policy PRD_SRM, schedule Daily_Full on storage unit veritas-hcart-robot-tld-0-<netapp_client2>
6/12/2015 5:54:57 AM - started process bpbrm (3844)
6/12/2015 5:54:57 AM - Info bpbrm(pid=3844) <netapp_client2> is the host to backup data from     
6/12/2015 5:55:02 AM - Info bpbrm(pid=3844) reading file list for client        
6/12/2015 5:55:02 AM - connecting
6/12/2015 5:55:06 AM - Info bpbrm(pid=3844) starting ndmpagent on client         
6/12/2015 5:55:06 AM - Info ndmpagent(pid=3744) Backup started           
6/12/2015 5:55:06 AM - connected; connect time: 0:00:04
6/12/2015 5:55:06 AM - Info bptm(pid=5224) start            
6/12/2015 5:55:30 AM - Info bptm(pid=5224) using 30 data buffers         
6/12/2015 5:55:30 AM - Info bptm(pid=5224) using 65536 data buffer size        
6/12/2015 5:55:35 AM - Info bptm(pid=5224) start backup           
6/12/2015 5:55:35 AM - Info bptm(pid=5224) Waiting for mount of media id L621L4 (copy 1) on server veritas.
6/12/2015 5:55:35 AM - mounting L621L4
6/12/2015 5:56:48 AM - Info bptm(pid=5224) media id L621L4 mounted on drive index 1, drivepath nrst0a, drivename IBM.ULT3580-TD4.001, copy 1
6/12/2015 5:56:48 AM - mounted; mount time: 0:01:13
6/12/2015 5:56:49 AM - Info ndmpagent(pid=3744) <netapp_client2>: SCSI: TAPE READ: short read for nrst0a     
6/12/2015 5:56:53 AM - positioning L621L4 to file 4
6/12/2015 6:01:54 AM - Error bptm(pid=5224) io_ioctl_ndmp (MTFSF) failed on media id L621L4, drive index 1, return code 18 (NDMP_XDR_DECODE_ERR) (bptm.c.7157)
6/12/2015 6:01:54 AM - Error ndmpagent(pid=3744) eof is set, connection 0000000000EB0DE0        
6/12/2015 6:01:58 AM - Error ndmpagent(pid=3744) connection 0xeb11c0 ndmp_message_process_one_failed, status = NDMP_ILLEGAL_STATE_ERR       
6/12/2015 6:02:03 AM - Error ndmpagent(pid=3744) eof is set - connection 0xeb11c0       
6/12/2015 6:02:08 AM - Error ndmpagent(pid=3744) NDMP backup failed, path = UNKNOWN       
6/12/2015 6:02:12 AM - Error ndmpagent(pid=3744) Attempting to create tape connections when already created     
6/12/2015 6:02:17 AM - Info bptm(pid=5224) EXITING with status 86 <----------        
6/12/2015 6:02:17 AM - Info ndmpagent(pid=0) done. status: 86: media position error       
6/12/2015 6:02:17 AM - end writing
media position error(86)

#######

Thanks for the understanding ,

I will keep you posted once Netbackup support resolves the issue.

[Marianne]

I cannot see how Symantec /NetBackup can solve device and NDMP errors. You will need to log calls with filer support and tape vendor as well.

[Netuk]

Thanks Marianne,

made support calls with NetApp and IBM as well. Will keep posted with the results.