io_ioctl_ndmp (mtbsf

[Scumbag_Trader]

I've been having trouble with NDMP backups since I added two fiber NDMP storage units to master/media server. Before I was just sending info to the robot as a media manager storage type but it would not use the fiber lines connected to the drives. Now I am recieving the following errors when using the NDMP storage units:

02/19/2013 20:31:15 - Info nbjm (pid=3364) starting backup job (jobid=135242) for client ntap1, policy NDMP-ntap1-bigdata, schedule Daily
02/19/2013 20:31:15 - Info nbjm (pid=3364) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=135242, request id:{996CE280-7B05-11E2-92BB-C3FC9C756DC2})
02/19/2013 20:31:15 - requesting resource netapp
02/19/2013 20:31:15 - requesting resource jawa.NBU_CLIENT.MAXJOBS.ntap1
02/19/2013 20:31:15 - requesting resource jawa.NBU_POLICY.MAXJOBS.NDMP-ntap1-bigdata
02/19/2013 20:31:15 - awaiting resource netapp. Waiting for resources.
          Reason: Drives are in use, Media server: jawa,
          Robot Type(Number): TLD(0), Media ID: N/A, Drive Name: N/A,
          Volume Pool: NetBackup, Storage Unit: netapp, Drive Scan Host: N/A,
          Disk Pool: N/A, Disk Volume: N/A
02/19/2013 20:35:51 - Info bpbrm (pid=18568) ntap1 is the host to backup data from
02/19/2013 20:35:51 - Info bpbrm (pid=18568) reading file list from client
02/19/2013 20:35:51 - Info bpbrm (pid=18568) starting ndmpagent on client
02/19/2013 20:35:51 - granted resource  jawa.NBU_CLIENT.MAXJOBS.ntap1
02/19/2013 20:35:51 - granted resource  jawa.NBU_POLICY.MAXJOBS.NDMP-ntap1-bigdata
02/19/2013 20:35:51 - granted resource  8873L5
02/19/2013 20:35:51 - granted resource  IBM.ULTRIUM-HH5.002
02/19/2013 20:35:51 - granted resource  netapp
02/19/2013 20:35:51 - estimated 192254598 kbytes needed
02/19/2013 20:35:51 - Info nbjm (pid=3364) started backup (backupid=ntap1_1361327751) job for client ntap1, policy NDMP-ntap1-bigdata, schedule Daily on storage unit netapp
02/19/2013 20:35:51 - started process bpbrm (pid=18568)
02/19/2013 20:35:51 - connecting
02/19/2013 20:35:51 - connected; connect time: 0:00:00
02/19/2013 20:35:52 - Info ndmpagent (pid=18577) Backup started
02/19/2013 20:35:52 - Info bpbrm (pid=18568) bptm pid: 18578
02/19/2013 20:35:52 - Info bptm (pid=18578) start
02/19/2013 20:35:52 - Info bptm (pid=18578) using 30 data buffers
02/19/2013 20:35:52 - Info bptm (pid=18578) using 65536 data buffer size
02/19/2013 20:35:52 - Info bptm (pid=18578) start backup
02/19/2013 20:35:52 - Info bptm (pid=18578) media id 8873L5 mounted on drive index 2, drivepath nrst5a, drivename IBM.ULTRIUM-HH5.002, copy 1
02/19/2013 20:35:52 - mounted 8873L5
02/19/2013 20:35:52 - positioning 8873L5 to file 43
02/19/2013 20:35:54 - positioned 8873L5; position time: 0:00:02
02/19/2013 20:35:54 - begin writing
02/19/2013 20:35:55 - Info ndmpagent (pid=18577) ntap1: DUMP: creating "/vol/bigdata/../snapshot_for_backup.29" snapshot.
02/19/2013 20:35:59 - Info ndmpagent (pid=18577) ntap1: DUMP: Using subtree dump
02/19/2013 20:36:08 - Info ndmpagent (pid=18577) ntap1: DUMP: Date of this level 9 dump: Tue Feb 19 20:35:55 2013.
02/19/2013 20:36:08 - Info ndmpagent (pid=18577) ntap1: DUMP: Date of last level 8 dump: Mon Dec 24 06:01:34 2012.
02/19/2013 20:36:08 - Info ndmpagent (pid=18577) ntap1: DUMP: Dumping /vol/bigdata/tickData/futures to NDMP connection
02/19/2013 20:36:08 - Info ndmpagent (pid=18577) ntap1: DUMP: mapping (Pass I)[regular files]
02/19/2013 20:36:16 - Info ndmpagent (pid=18577) ntap1: DUMP: mapping (Pass II)[directories]
02/19/2013 20:36:16 - Info ndmpagent (pid=18577) ntap1: DUMP: estimated 221786988 KB.
02/19/2013 20:36:16 - Info ndmpagent (pid=18577) ntap1: DUMP: dumping (Pass III) [directories]
02/19/2013 20:36:17 - Info ndmpagent (pid=18577) 0 entries sent to bpdbm
02/19/2013 20:36:17 - Info ndmpagent (pid=18577) 5000 entries sent to bpdbm
02/19/2013 20:36:17 - Info ndmpagent (pid=18577) 10000 entries sent to bpdbm
02/19/2013 20:36:18 - Info ndmpagent (pid=18577) 15000 entries sent to bpdbm
02/19/2013 20:36:18 - Info ndmpagent (pid=18577) 20000 entries sent to bpdbm
02/19/2013 20:36:19 - Info ndmpagent (pid=18577) 25000 entries sent to bpdbm
02/19/2013 20:36:19 - Info ndmpagent (pid=18577) 30000 entries sent to bpdbm
02/19/2013 20:36:19 - Info ndmpagent (pid=18577) 35000 entries sent to bpdbm
02/19/2013 20:36:20 - Info ndmpagent (pid=18577) 40000 entries sent to bpdbm
02/19/2013 20:36:20 - Info ndmpagent (pid=18577) 45000 entries sent to bpdbm
02/19/2013 20:36:21 - Info ndmpagent (pid=18577) 50000 entries sent to bpdbm
02/19/2013 20:36:21 - Info ndmpagent (pid=18577) 55000 entries sent to bpdbm
02/19/2013 20:36:21 - Info ndmpagent (pid=18577) 60000 entries sent to bpdbm
02/19/2013 20:36:21 - Info ndmpagent (pid=18577) 65000 entries sent to bpdbm
02/19/2013 20:36:22 - Info ndmpagent (pid=18577) ntap1: DUMP: dumping (Pass IV) [regular files]
02/19/2013 20:41:15 - Info ndmpagent (pid=18577) ntap1: DUMP: Tue Feb 19 20:41:15 2013 : We have written 10951806 KB.
02/19/2013 20:46:32 - Info ndmpagent (pid=18577) ntap1: DUMP: Tape write failed.
02/19/2013 20:46:32 - Info ndmpagent (pid=18577) ntap1: DUMP: Tue Feb 19 20:46:32 2013 : We have written 23412996 KB.
02/19/2013 20:46:32 - Info ndmpagent (pid=18577) ntap1: DUMP: DUMP IS ABORTED
02/19/2013 20:46:34 - Info ndmpagent (pid=18577) ntap1: DUMP: Deleting "/vol/bigdata/../snapshot_for_backup.29" snapshot.
02/19/2013 20:46:41 - Info ndmpagent (pid=18577) ntap1: Connection or IO Error.
02/19/2013 20:46:41 - Info ndmpagent (pid=18577) ntap1: MoveletOutput: Internal Error.
02/19/2013 20:46:41 - Error ndmpagent (pid=18577) NDMP backup failed, path = /vol/bigdata/tickData/futures
02/19/2013 20:46:41 - Error bptm (pid=18578) none of the NDMP backups for client ntap1 completed successfully
02/19/2013 20:46:41 - Error bptm (pid=18578) io_ioctl_ndmp (MTBSF) failed on media id 8873L5, drive index 2, return code 11 (NDMP_WRITE_PROTECT_ERR) (bptm.c.8757)
02/19/2013 20:46:46 - Info bptm (pid=18578) EXITING with status 99 <----------
02/19/2013 20:46:46 - Info ndmpagent (pid=0) done. status: 99: NDMP backup failure
02/19/2013 20:46:46 - end writing; write time: 0:10:52
NDMP backup failure  (99)

I have used tpautoconf to check my connections and vmoprcmd to check my drives. After several failed backups I sometimes have to bring them back up. I have noticed that small jobs usually finish with no problem but big ones go down before they can finish. The fragment size to my drives is 1,048,575 MB if that helps. Any suggestions would be appreciated

[CRZ]

Just an educated guess:

02/19/2013 20:35:54 - begin writing

...

02/19/2013 20:36:21 - Info ndmpagent (pid=18577) 65000 entries sent to bpdbm
02/19/2013 20:36:22 - Info ndmpagent (pid=18577) ntap1: DUMP: dumping (Pass IV) [regular files]
02/19/2013 20:41:15 - Info ndmpagent (pid=18577) ntap1: DUMP: Tue Feb 19 20:41:15 2013 : We have written 10951806 KB.
02/19/2013 20:46:32 - Info ndmpagent (pid=18577) ntap1: DUMP: Tape write failed.

This stands out to me.

Do your "small jobs" complete in under 10 minutes?  Maybe even under 5 minutes?

I feel like there may be a timeout somewhere in play here, but I couldn't tell you which one, or how much it is, or which logs I would need to see to confirm or deny it.  Other than that...hope this helps!

(Is this really a "NetBackup Appliances" issue, though?  Might have more luck in "NetBackup" forum)

[V4]

post ndmpagent logs pls to analyze errors.  CRZ is correct.. issue sounds more to NBU only rather then appliance

[Marianne]

I have moved the post to the correct forum....

[RamNagalla]

Error bptm (pid=18578) io_ioctl_ndmp (MTBSF) failed on media id 8873L5, drive index 2, return code 11 (NDMP_WRITE_PROTECT_ERR) (bptm.c.8757)

is that tape 8873L5, wirte protected?

Smaller backup may be using the differt tape, which would allow to write

and lager backups going to tape which are write protected?

8873L5 tape have any valid images and data? 

try to find if this happend only with few set of tapes and make sure that they are not write protected.

http://www.symantec.com/business/support/index?page=content&id=TECH57290