1 NDMP job is failing with ERR - Cannot write TIR data to media, NDMP return code 20.

[abhinav_trivedi]

Hi All,

One of our NDMP job is failing with error code 84. Logs are given below but main error is (Error bptm (pid=12325) ERR - Cannot write TIR data to media, NDMP return code 20):

04/11/2013 13:23:37 - granted resource  RS8073

04/11/2013 13:23:37 - granted resource  OY---hcart-010-shared-NDMP

04/11/2013 13:23:37 - granted resource  PNIOYNBMDS02-hcart-robot-tld-0-pnievs1

04/11/2013 13:23:37 - estimated 172987322 kbytes needed

04/11/2013 13:23:37 - Info nbjm (pid=4400) started backup (backupid=pnievs1_1365683017) job for client pnievs1, policy OY-NDMP-PNIEVS1-FULL, schedule Full on storage unit PNIOYNBMDS02-hcart-robot-tld-0-pnievs1

04/11/2013 13:23:38 - Info bpbrm (pid=12319) pnievs1 is the host to backup data from

04/11/2013 13:23:38 - Info bpbrm (pid=12319) reading file list from client

04/11/2013 13:23:38 - started process bpbrm (pid=12319)

04/11/2013 13:23:38 - connecting

04/11/2013 13:23:38 - connected; connect time: 0:00:00

04/11/2013 13:23:39 - Info bpbrm (pid=12319) starting ndmpagent on client

04/11/2013 13:23:39 - Info ndmpagent (pid=12324) Backup started

04/11/2013 13:23:39 - Info bpbrm (pid=12319) bptm pid: 12325

04/11/2013 13:23:39 - Info bptm (pid=12325) start

04/11/2013 13:23:39 - Info bptm (pid=12325) using 64 data buffers

04/11/2013 13:23:39 - Info bptm (pid=12325) using 65536 data buffer size

04/11/2013 13:23:39 - Info bptm (pid=12325) start backup

04/11/2013 13:23:39 - Info bptm (pid=12325) Waiting for mount of media id RS8073 (copy 1) on server PNIOYNBMDS02.

04/11/2013 13:23:39 - mounting RS8073

04/11/2013 13:24:55 - mounted RS8073; mount time: 0:01:16

04/11/2013 13:24:56 - Info bptm (pid=12325) media id RS8073 mounted on drive index 1, drivepath /dev/mt_d4l0, drivename OY---hcart-010-shared-NDMP, copy 1

04/11/2013 13:24:59 - positioning RS8073 to file 2

04/11/2013 13:26:20 - positioned RS8073; position time: 0:01:21

04/11/2013 13:26:20 - begin writing

04/11/2013 13:26:24 - Info ndmpagent (pid=12324) pnievs1: NDMP(3784): Starting (source end) full Backup of file system /transformation-software-repository 

04/11/2013 13:26:24 - Info ndmpagent (pid=12324) pnievs1: NDMP(3784): Backup is being generated from snapshot[name "NDMP_AUTO_SNAPSHOT9188",view id(7527158),creation time(2013-04-11 12:26:22+00:00)], base snapshot[none]

04/11/2013 14:20:55 - Info ndmpagent (pid=12324) pnievs1: NDMP(3784): Backup of /transformation-software-repository complete (source end) (0 warning(s), 0 error(s))

04/11/2013 14:20:55 - Info ndmpagent (pid=12324) pnievs1: NDMP(3784): Action completed (NDMP mover terminated)

04/11/2013 14:20:55 - Info ndmpagent (pid=12324) NDMP backup successfully completed, path = /transformation-software-repository

04/11/2013 14:22:58 - Error bptm (pid=12325) ERR - Cannot write TIR data to media, NDMP return code 20.

04/11/2013 14:23:05 - Info bptm (pid=12325) EXITING with status 84 <----------

04/11/2013 14:23:05 - Info ndmpagent (pid=0) done. status: 84: media write error

04/11/2013 14:23:05 - end writing; write time: 0:56:45

04/11/2013 15:12:25 - job 1530108 was restarted as job 1530156

media write error  (84)

Important consideration is backup is completing successfully with NDMP drives with same error but completing successfully with Non NDMP drives.

[CRZ]

Are you backing up lots and lots of files (which may be creating a very large set of TIR data)?

Have you set SIZE_DATA_BUFFERS_NDMP?  If so, what is it? 

Wait...it's probably in your log excerpt:

04/11/2013 13:23:39 - Info bptm (pid=12325) using 65536 data buffer size

That's the default.  Can you set it to 131072?

Could you also add this line to /usr/openv/netbackup/db/config/ndmp.cfg if it's not already there?

NDMP_MOVER_CLIENT_DISABLE

What's that keyword do?  Read this TechNote:

Impact of NDMP_MOVER_CLIENT_DISABLE
 http://symantec.com/docs/TECH162041

[abhinav_trivedi]

Hi CRZ,

Could you please let me know the exact use of NDMP_MOVER_CLIENT_DISABLE. We do not have ndmp.cfg in the mentioned path also:

[nibackup@XYZ]/usr/openv/netbackup/db/config>ls -lrt

total 12

-rw------- 1 root root    3 Apr 27  2011 NUMBER_DATA_BUFFERS

-rw------- 1 root root    6 Sep 16  2011 SIZE_DATA_BUFFERS

drwxr-xr-x 2 root root 4096 Apr 11 11:00 shm

[nibackup@XYZ]/usr/openv/netbackup/db/config>

Do we need to create touch file of ndmp.cfg and value in this touch file is NDMP_MOVER_CLIENT_DISABLE.

For SIZE_DATA_BUFFERS_NDMP:

We are using multiplexing in our environment. Might be we will face below issue after these changes:

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

Could you please explain this aswell. Thanks for help.

[abhinav_trivedi]

We have checked ndmpagent logs and found the following:

11/04/13 16:41:21.411 [ndmp_logger_vxul] 0xb57780 .   tcp_addr[0].tcp_addr=10.194.125.32

11/04/13 16:41:21.411 [ndmp_logger_vxul] 0xb57780 .   tcp_addr[0].port=1912 (0x778)

11/04/13 16:41:21.411 [ndmp_logger_vxul] 0xb57780 **  End NDMP_MOVER_GET_STATE

11/04/13 16:41:21.411 [ndmp_logger_vxul] 0xb57780 ->  (20) 42 [0] 16:41:21 NDMP_MOVER_ABORT (0xa03) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.412 [ndmp_logger_vxul] 0x68cf80 ->  (7) 251 [0] 16:41:21 NDMP_MOVER_ABORT (0xa03) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.412 [ndmp_logger_vxul] 0x68cf80 <-  (7) 6932 [0] 16:41:21 NDMP_NOTIFY_MOVER_HALTED (0x503) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.412 [ndmp_logger_vxul] 0x68cf80 .   reason=NDMP_MOVER_HALT_ABORTED

11/04/13 16:41:21.412 [ndmp_logger_vxul] 0x68cf80 **  End NDMP_NOTIFY_MOVER_HALTED

11/04/13 16:41:21.412 [ndmp_logger_vxul] 0x68cf80 <-  (7) 6933 [251] 16:41:21 NDMP_MOVER_ABORT (0xa03) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.412 [ndmp_logger_vxul] 0x68cf80 .   error=NDMP_NO_ERR (0x0)

11/04/13 16:41:21.412 [ndmp_logger_vxul] 0x68cf80 **  End NDMP_MOVER_ABORT

11/04/13 16:41:21.413 [ndmp_logger_vxul] 0xb57780 <-  (20) 43 [0] 16:41:21 NDMP_NOTIFY_MOVER_HALTED (0x503) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.413 [ndmp_logger_vxul] 0xb57780 .   reason=NDMP_MOVER_HALT_ABORTED

11/04/13 16:41:21.413 [ndmp_logger_vxul] 0xb57780 **  End NDMP_NOTIFY_MOVER_HALTED

11/04/13 16:41:21.449 [ndmp_logger_vxul] 0xb57780 <-  (20) 44 [42] 16:41:21 NDMP_MOVER_ABORT (0xa03) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.449 [ndmp_logger_vxul] 0xb57780 .   error=NDMP_NO_ERR (0x0)

11/04/13 16:41:21.449 [ndmp_logger_vxul] 0xb57780 **  End NDMP_MOVER_ABORT

11/04/13 16:41:21.449 [ndmp_logger_vxul] 0xb57780 ->  (20) 43 [0] 16:41:21 NDMP_MOVER_STOP (0xa04) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.450 [ndmp_logger_vxul] 0x68cf80 ->  (7) 252 [0] 16:41:21 NDMP_MOVER_STOP (0xa04) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.450 [ndmp_logger_vxul] 0x68cf80 <-  (7) 6934 [252] 16:41:21 NDMP_MOVER_STOP (0xa04) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.450 [ndmp_logger_vxul] 0x68cf80 .   error=NDMP_NO_ERR (0x0)

11/04/13 16:41:21.450 [ndmp_logger_vxul] 0x68cf80 **  End NDMP_MOVER_STOP

11/04/13 16:41:21.450 [ndmp_logger_vxul] 0xb57780 <-  (20) 45 [43] 16:41:21 NDMP_MOVER_STOP (0xa04) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.450 [ndmp_logger_vxul] 0xb57780 .   error=NDMP_NO_ERR (0x0)

11/04/13 16:41:21.450 [ndmp_logger_vxul] 0xb57780 **  End NDMP_MOVER_STOP

11/04/13 16:41:21.472 [ndmp_logger_vxul] 0xb57780 ->  (20) 44 [0] 16:41:21 NDMP_TAPE_CLOSE (0x301) NDMP_NO_ERR (0x0)

11/04/13 16:41:21.472 [ndmp_logger_vxul] 0x68cf80 ->  (7) 253 [0] 16:41:21 NDMP_TAPE_CLOSE (0x301) NDMP_NO_ERR (0x0)

11/04/13 16:41:23.513 [ndmp_logger_vxul] 0x68cf80 <-  (7) 6935 [253] 16:41:23 NDMP_TAPE_CLOSE (0x301) NDMP_NO_ERR (0x0)

11/04/13 16:41:23.513 [ndmp_logger_vxul] 0x68cf80 .   error=NDMP_NO_ERR (0x0)

11/04/13 16:41:23.513 [ndmp_logger_vxul] 0x68cf80 **  End NDMP_TAPE_CLOSE

11/04/13 16:41:23.513 [ndmp_logger_vxul] 0xb57780 <-  (20) 46 [44] 16:41:23 NDMP_TAPE_CLOSE (0x301) NDMP_NO_ERR (0x0)

11/04/13 16:41:23.513 [ndmp_logger_vxul] 0xb57780 .   error=NDMP_NO_ERR (0x0)

11/04/13 16:41:23.513 [ndmp_logger_vxul] 0xb57780 **  End NDMP_TAPE_CLOSE

In bptm log:

16:41:16.171 [5865] <2> bptm: EXITING with status 0 <----------

16:41:21.398 [4103] <16> NdmpMoverSession[0]: ERROR Flush - timeout waiting for CONNECT_CLOSED

16:41:21.400 [4103] <16> NdmpMediaSession_flush_mover[0]: NDMP Flush to tape failed.

16:41:21.413 [4103] <2> NdmpMoverSession[0]: mover halted reason NDMP_MOVER_HALT_ABORTED

16:41:21.449 [4103] <2> NdmpMoverSession[0]: ndmp_mover_abort status = 0

16:41:21.451 [4103] <2> NdmpMoverSession[0]: ndmp_mover_stop status = 0

16:41:21.451 [4103] <2> NdmpMoverSession[0]: Shutdown complete

24940 -mds 0 -alocid 261295 -nh pnievs1 -nu nbaadmin -nk 61383 -np 3269bfb6ab90c470f112c8d7801b872dd16518b04d091aaba02db67a5f48187133b14d8777478376de97386d63326b139592ee7aae9e9884b3bef339aaf8cdc9 -jobid -1364280962 -jm 

16:41:29.197 [5875] <8> vnet_same_host_and_update: [vnet_addrinfo.c:2829] name2 is empty 0 0x0

16:41:29.197 [5875] <4> bptm: emmserver_name = pnioynbmst01

16:41:29.197 [5875] <4> bptm: emmserver_port = 155616:41:21.451 [4103] <2> ConnectionCache::connectAndCache: Acquiring new connection for host pnioynbmst01, query type 1

16:41:21.453 [4103] <2> vnet_pbxConnect: pbxConnectEx Succeeded

16:41:21.453 [4103] <2> logconnections: BPDBM CONNECT FROM 10.194.125.32.35068 TO 10.194.124.31.1556 fd = 24

16:41:21.453 [4103] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2

16:41:21.456 [4103] <2> db_end: Need to collect reply

16:41:21.457 [4103] <16> write_data_tir: ERR - Cannot write TIR data to media, NDMP return code 20.

16:41:21.458 [4103] <2> send_MDS_msg: DEVICE_STATUS 1 261295 pnioynbmds01 RS8073 4024940 OY---hcart-010-shared-NDMP 2000723 WRITE_ERROR 0 0

16:41:21.469 [4103] <2> log_media_error: successfully wrote to error file - 04/11/13 16:41:21 RS8073 1 WRITE_ERROR OY---hcart-010-shared-NDMP

16:41:21.469 [4103] <2> check_error_history: just tpunmount: called from bptm line 21443, EXIT_Status = 84

16:41:21.469 [4103] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_OY---hcart-010-shared-NDMP, from bptm.c.16433

16:41:23.513 [4103] <2> NdmpMediaSession_close_public_and_ndmpagent[0]: closing public session, force = 0, agent_session_index = 0

16:41:28.515 [4103] <2> drivename_write: Called with mode 1

16:41:28.515 [4103] <2> drivename_unlock: unlocked

16:41:28.515 [4103] <2> drivename_close: Called for file OY---hcart-010-shared-NDMP

16:41:28.515 [4103] <2> tpunmount: NOP: MEDIA_DONE 0 1530198 0 RS8073 4024940 0 {A64E913C-A2B6-11E2-AD5C-1EEE10464DD9}

16:41:28.515 [4103] <2> bptm: EXITING with status 84 <----------

16:41:29.197 [5875] <2> bptm: INITIATING (VERBOSE = 0): -unload -dn OY---hcart-010-shared-NDMP -dp /dev/mt_d4l0 -dk 2000723 -m RS8073 -mk 40

16:41:29.207 [5875] <8> file_to_cache_item: [vnet_addrinfo.c:6574] fopen() failed ERRNO=2 FILE=/usr/openv/var/host_cache/1ff/ffffffff+veritas_pbx,1,1,0,1,0+.txt

16:41:29.208 [5875] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)

Job detailed status:

04/11/2013 15:50:21 - Info ndmpagent (pid=4102) pnievs1: NDMP(3812): Starting (source end) full Backup of file system /transformation-software-repository 

04/11/2013 15:50:21 - Info ndmpagent (pid=4102) pnievs1: NDMP(3812): Backup is being generated from snapshot[name "NDMP_AUTO_SNAPSHOT9196",view id(7529675),creation time(2013-04-11 14:50:20+00:00)], base snapshot[none]

04/11/2013 15:50:22 - Info ndmpagent (pid=4102) 0 entries sent to bpdbm

04/11/2013 16:03:23 - Info ndmpagent (pid=4102) 5000 entries sent to bpdbm

04/11/2013 16:05:28 - Info ndmpagent (pid=4102) 10000 entries sent to bpdbm

04/11/2013 16:08:33 - Info ndmpagent (pid=4102) 15000 entries sent to bpdbm

04/11/2013 16:08:54 - Info ndmpagent (pid=4102) 20000 entries sent to bpdbm

04/11/2013 16:08:56 - Info ndmpagent (pid=4102) 25000 entries sent to bpdbm

04/11/2013 16:09:00 - Info ndmpagent (pid=4102) 30000 entries sent to bpdbm

04/11/2013 16:09:12 - Info ndmpagent (pid=4102) 35000 entries sent to bpdbm

04/11/2013 16:09:18 - Info ndmpagent (pid=4102) 40000 entries sent to bpdbm

04/11/2013 16:09:24 - Info ndmpagent (pid=4102) 45000 entries sent to bpdbm

04/11/2013 16:39:18 - Info ndmpagent (pid=4102) pnievs1: NDMP(3812): Backup of /transformation-software-repository complete (source end) (0 warning(s), 0 error(s))

04/11/2013 16:39:18 - Info ndmpagent (pid=4102) pnievs1: NDMP(3812): Action completed (NDMP mover terminated)

04/11/2013 16:39:19 - Info ndmpagent (pid=4102) NDMP backup successfully completed, path = /transformation-software-repository

04/11/2013 16:39:19 - Info ndmpagent (pid=4102) 46240 entries sent to bpdbm

04/11/2013 16:41:21 - Error bptm (pid=4103) ERR - Cannot write TIR data to media, NDMP return code 20.

04/11/2013 16:41:28 - Info bptm (pid=4103) EXITING with status 84 <----------

04/11/2013 16:41:28 - Info ndmpagent (pid=0) done. status: 84: media write error

04/11/2013 16:41:28 - end writing; write time: 0:51:11

media write error  (84)

[CRZ]

Hi CRZ,

Could you please let me know the exact use of NDMP_MOVER_CLIENT_DISABLE. We do not have ndmp.cfg in the mentioned path also:

[nibackup@XYZ]/usr/openv/netbackup/db/config>ls -lrt

total 12

-rw------- 1 root root    3 Apr 27  2011 NUMBER_DATA_BUFFERS

-rw------- 1 root root    6 Sep 16  2011 SIZE_DATA_BUFFERS

drwxr-xr-x 2 root root 4096 Apr 11 11:00 shm

[nibackup@XYZ]/usr/openv/netbackup/db/config>

Do we need to create touch file of ndmp.cfg and value in this touch file is NDMP_MOVER_CLIENT_DISABLE.

Pretty much - this command should cover it:

/usr/openv/netbackup/db/config# echo NDMP_MOVER_CLIENT_DISABLE > ndmp.cfg

For SIZE_DATA_BUFFERS_NDMP:

We are using multiplexing in our environment. Might be we will face below issue after these changes:

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

Could you please explain this aswell. Thanks for help.

According to the Tech Alert, this issue ONLY affects 7.0.1.  You didn't say which version you're at, but I believe you marked this thread as "7.5 and up" so assuming you're at 7.1 or above, this issue will not affect you.

I didn't really look at your logs, but the bottom line is if your TIR data is larger than the blocksize, it might explain your trouble.  This should work around it, but that keyword may give you a performance hit on other actions (refer to the TechNote I linked above).