10:31:56.084 [26340.28324] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
10:31:56.084 [26340.28324] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 0
10:32:00.405 [26340.28324] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 1
10:32:01.606 [26340.28324] <2> write_backup: maximum fragment size written --- Fragmenting
10:32:01.638 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:32:01.638 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:32:01.762 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.49842 TO 135.53.7.32.13724
10:32:02.184 [26340.28324] <4> report_throughput: VBRT 1 26340 5 2 A000_F6_S6_D66 A000_F6_S8_D68 AL0908 AL2518 0 0 1 0 2048000  2048000 (bptm.c.22568)
10:32:02.215 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:32:02.215 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:32:02.230 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.49855 TO 135.53.7.32.13724
10:32:02.652 [26340.28324] <2> send_MDS_msg: MEDIADB 1 13027089 AL0908 4005641 *NULL* 6 1351825237 1352560390 1353769990 0 107069694 53 26 1 11 0 0 1024 0 1481060 0
10:32:02.667 [26340.28324] <2> send_MDS_msg: MEDIADB 1 13027090 AL2518 4007231 *NULL* 6 1352522946 1352560390 1357917190 0 49152000 24 6 4 4 0 0 1024 0 576038 0
10:32:02.698 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:32:02.698 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:32:02.808 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.49975 TO 135.53.7.32.13724
10:32:03.244 [26340.28324] <4> write_backup: successfully wrote backup id gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, copy 1, fragment 6, 2048000 Kbytes at 28189.952 Kbytes/sec
10:32:03.291 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:32:03.291 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:32:03.291 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.49975 TO 135.53.7.32.13724
10:32:03.728 [26340.28324] <4> write_backup: successfully wrote backup id gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, copy 2, fragment 6, 2048000 Kbytes at 28189.952 Kbytes/sec
10:32:03.759 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:32:03.759 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:32:03.868 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.50010 TO 135.53.7.32.13724
10:32:04.305 [26340.28324] <4> write_backup: begin writing backup id gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, copy 1, fragment 7, to media id AL0908 on drive A000_F6_S6_D66 (index 0)
10:32:04.336 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:32:04.336 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:32:04.336 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.50010 TO 135.53.7.32.13724
10:32:04.789 [26340.28324] <4> write_backup: begin writing backup id gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, copy 2, fragment 7, to media id AL2518 on drive A000_F6_S8_D68 (index 1)
10:32:04.789 [26340.28324] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:32:04.789 [26340.28324] <2> write_data: Total Kbytes transferred 12288000
10:32:04.789 [26340.28324] <2> write_data: twin_index: 1 active: 2 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:32:04.804 [26340.28324] <2> write_data: absolute block position prior to writing backup header(s) is 1673072, copy 1
10:32:04.804 [26340.28324] <2> write_data: block position check: actual 1673072, expected 1673072
10:32:04.804 [26340.28324] <2> io_write_back_header: drive index 0, gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, file num = 54, mpx_headers = 0, copy 1
10:32:04.804 [26340.28324] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
10:32:04.804 [26340.28324] <2> write_data: absolute block position prior to writing backup header(s) is 768050, copy 2
10:32:04.804 [26340.28324] <2> write_data: block position check: actual 768050, expected 768050
10:32:04.804 [26340.28324] <2> io_write_back_header: drive index 1, gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, file num = 25, mpx_headers = 0, copy 2
10:32:04.836 [26340.28324] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 2
10:32:04.836 [26340.28324] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
10:32:04.836 [26340.28324] <2> write_data: received first buffer (65536 bytes), begin writing data
10:33:09.311 [26340.28324] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
10:33:09.311 [26340.28324] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 0
10:33:10.731 [26340.28324] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 1
10:33:12.260 [26340.28324] <2> write_backup: maximum fragment size written --- Fragmenting
10:33:12.291 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:33:12.291 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:33:12.291 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.59346 TO 135.53.7.32.13724
10:33:12.728 [26340.28324] <4> report_throughput: VBRT 1 26340 5 2 A000_F6_S6_D66 A000_F6_S8_D68 AL0908 AL2518 0 0 1 0 2048000  2048000 (bptm.c.22568)
10:33:12.759 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:33:12.759 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:33:12.868 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.59347 TO 135.53.7.32.13724
10:33:13.305 [26340.28324] <2> send_MDS_msg: MEDIADB 1 13027089 AL0908 4005641 *NULL* 6 1351825237 1352560390 1353769990 0 109117694 54 27 1 11 0 0 1024 0 1481060 0
10:33:13.321 [26340.28324] <2> send_MDS_msg: MEDIADB 1 13027090 AL2518 4007231 *NULL* 6 1352522946 1352560390 1357917190 0 51200000 25 7 4 4 0 0 1024 0 576038 0
10:33:13.367 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:33:13.367 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:33:13.477 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.59348 TO 135.53.7.32.13724
10:33:13.913 [26340.28324] <4> write_backup: successfully wrote backup id gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, copy 1, fragment 7, 2048000 Kbytes at 31764.250 Kbytes/sec
10:33:13.945 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:33:13.945 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:33:13.945 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.59349 TO 135.53.7.32.13724
10:33:14.366 [26340.28324] <4> write_backup: successfully wrote backup id gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, copy 2, fragment 7, 2048000 Kbytes at 31764.250 Kbytes/sec
10:33:14.397 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:33:14.397 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:33:14.506 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.59350 TO 135.53.7.32.13724
10:33:14.943 [26340.28324] <4> write_backup: begin writing backup id gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, copy 1, fragment 8, to media id AL0908 on drive A000_F6_S6_D66 (index 0)
10:33:14.974 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:33:14.974 [26340.28324] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:33:15.083 [26340.28324] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.59351 TO 135.53.7.32.13724
10:33:15.520 [26340.28324] <4> write_backup: begin writing backup id gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, copy 2, fragment 8, to media id AL2518 on drive A000_F6_S8_D68 (index 1)
10:33:15.520 [26340.28324] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:33:15.520 [26340.28324] <2> write_data: Total Kbytes transferred 14336000
10:33:15.520 [26340.28324] <2> write_data: twin_index: 1 active: 2 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:33:15.520 [26340.28324] <2> write_data: absolute block position prior to writing backup header(s) is 1705074, copy 1
10:33:15.520 [26340.28324] <2> write_data: block position check: actual 1705074, expected 1705074
10:33:15.520 [26340.28324] <2> io_write_back_header: drive index 0, gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, file num = 55, mpx_headers = 0, copy 1
10:33:15.520 [26340.28324] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
10:33:15.520 [26340.28324] <2> write_data: absolute block position prior to writing backup header(s) is 800052, copy 2
10:33:15.520 [26340.28324] <2> write_data: block position check: actual 800052, expected 800052
10:33:15.520 [26340.28324] <2> io_write_back_header: drive index 1, gaalpa1glinkdc1-ebr.aldc.att.com_1352560390, file num = 26, mpx_headers = 0, copy 2
10:33:15.536 [26340.28324] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 2
10:33:15.536 [26340.28324] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
10:33:15.536 [26340.28324] <2> write_data: received first buffer (65536 bytes), begin writing data
10:39:08.365 [26340.28324] <2> mm_check_child_write: Received Terminate Event
10:39:08.365 [26340.28324] <2> io_terminate_tape: writing empty backup header, drive index 0, copy 1
10:39:08.365 [26340.28324] <2> io_terminate_tape: reposition to previous tapemark and rewrite header
10:39:08.365 [26340.28324] <2> io_ioctl: command (2)MTBSF 1 from (bptm.c.8694) on drive index 0
10:39:14.013 [26340.28324] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.8725) on drive index 0
10:39:16.634 [26340.28324] <2> io_terminate_tape: absolute block position prior to writing empty header is 1705074, copy 1
10:39:16.634 [26340.28324] <2> io_write_back_header: drive index 0, empty_file, file num = 55, mpx_headers = 0, copy 1
10:39:16.649 [26340.28324] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66, from bptm.c.8843
10:39:16.649 [26340.28324] <2> send_MDS_msg: MEDIADB 1 13027089 AL0908 4005641 *NULL* 6 1351825237 1352560390 1353769990 0 109117694 54 27 1 11 0 0 1024 0 1705074 0
10:39:16.680 [26340.28324] <2> openTpreqFile: tpreq_file: D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66, serial_num: 0007839108
10:39:16.680 [26340.28324] <2> get_drive_path: SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:39:16.680 [26340.28324] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, drive serial number 0007839108, expected serial number 0007839108
10:39:16.712 [26340.28324] <2> init_tape: \\.\Tape0 (SCSI coordinates {4,0,0,0}) configured with blocksize 0
10:39:16.727 [26340.28324] <2> init_tape: \\.\Tape0 (SCSI coordinates {4,0,0,0}) has compression enabled
10:39:16.727 [26340.28324] <2> io_open: SCSI RESERVE
10:39:16.727 [26340.28324] <2> io_open: file D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66 successfully opened (mode 2)
10:39:18.662 [26340.28324] <2> io_terminate_tape: locate block positioned tape to 1705074 in io_terminate_tape
10:39:18.662 [26340.28324] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66, from bptm.c.9024
10:39:18.662 [26340.28324] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)
10:39:18.662 [26340.28324] <2> io_terminate_tape: writing empty backup header, drive index 1, copy 2
10:39:18.662 [26340.28324] <2> io_terminate_tape: reposition to previous tapemark and rewrite header
10:39:18.662 [26340.28324] <2> io_ioctl: command (2)MTBSF 1 from (bptm.c.8694) on drive index 1
10:39:24.309 [26340.28324] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.8725) on drive index 1
10:39:29.675 [26340.28324] <2> io_terminate_tape: absolute block position prior to writing empty header is 800052, copy 2
10:39:29.675 [26340.28324] <2> io_write_back_header: drive index 1, empty_file, file num = 26, mpx_headers = 0, copy 2
10:39:29.691 [26340.28324] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S8_D68, from bptm.c.8843
10:39:29.691 [26340.28324] <2> send_MDS_msg: MEDIADB 1 13027090 AL2518 4007231 *NULL* 6 1352522946 1352560390 1357917190 0 51200000 25 7 4 4 0 0 1024 0 800052 0
10:39:29.691 [26340.28324] <2> openTpreqFile: tpreq_file: D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S8_D68, serial_num: 0007838646
10:39:29.691 [26340.28324] <2> get_drive_path: SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000100#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:39:29.707 [26340.28324] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, drive serial number 0007838646, expected serial number 0007838646
10:39:29.738 [26340.28324] <2> init_tape: \\.\Tape1 (SCSI coordinates {4,0,1,0}) configured with blocksize 0
10:39:29.753 [26340.28324] <2> init_tape: \\.\Tape1 (SCSI coordinates {4,0,1,0}) has compression enabled
10:39:29.769 [26340.28324] <2> io_open: SCSI RESERVE
10:39:29.769 [26340.28324] <2> io_open: file D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S8_D68 successfully opened (mode 2)
10:39:31.688 [26340.28324] <2> io_terminate_tape: locate block positioned tape to 800052 in io_terminate_tape
10:39:31.703 [26340.28324] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S8_D68, from bptm.c.9024
10:39:31.703 [26340.28324] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)
10:39:31.703 [26340.28324] <2> mm_terminate: EXITING with status 150
10:39:34.714 [26340.28324] <2> cleanup: Detached from BPBRM shared memory
10:39:38.427 [7376.24708] <2> bptm: INITIATING (VERBOSE = 0): -unload -dn A000_F6_S6_D66 -dp {4,0,0,0} -dk 2000190 -m AL0908 -mk 4005641 -mds 0 -alocid 13027089 -jobid -1350857463 -jm 
10:39:38.427 [7376.24708] <4> bptm: emmserver_name = asprod11.aldc.att.com
10:39:38.427 [7376.24708] <4> bptm: emmserver_port = 1556
10:39:38.458 [7376.24708] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:39:38.474 [29636.20872] <2> bptm: INITIATING (VERBOSE = 0): -unload -dn A000_F6_S8_D68 -dp {4,0,1,0} -dk 2000192 -m AL2518 -mk 4007231 -mds 0 -alocid 13027090 -jobid -1350857464 -jm 
10:39:38.474 [29636.20872] <4> bptm: emmserver_name = asprod11.aldc.att.com
10:39:38.474 [29636.20872] <4> bptm: emmserver_port = 1556
10:39:38.489 [7376.24708] <2> send_brm_msg: PID of bpxm = 7376
10:39:38.489 [7376.24708] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
10:39:38.489 [7376.24708] <2> nbjm_media_request: old_media_id = NULL, media_id = AL0908
10:39:38.505 [7376.24708] <2> Orb::init: Created anon service name: NB_7376_1289606909(Orb.cpp:610)
10:39:38.505 [7376.24708] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_7376_1289606909(Orb.cpp:628)
10:39:38.505 [7376.24708] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_7376_1289606909 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:39:38.505 [29636.20872] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:39:38.521 [29636.20872] <2> send_brm_msg: PID of bpxm = 29636
10:39:38.521 [29636.20872] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
10:39:38.521 [29636.20872] <2> nbjm_media_request: old_media_id = NULL, media_id = AL2518
10:39:38.521 [29636.20872] <2> Orb::init: Created anon service name: NB_29636_1289544351(Orb.cpp:610)
10:39:38.521 [29636.20872] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_29636_1289544351(Orb.cpp:628)
10:39:38.521 [29636.20872] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_29636_1289544351 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:39:40.595 [7376.24708] <2> RequestInitialResources: returning
10:39:40.595 [7376.24708] <2> parse_resource_strings: MEDIADB 1 13027089 AL0908 4005641 ------ 6 1351825237 1352524778 1353734378 0 94781694 47 20 1 11 0 0 1024 0 1481060 0
10:39:40.595 [7376.24708] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
10:39:40.595 [7376.24708] <2> parse_resource_strings: VOLUME 1 AL0908 4005641 AL0908L3 Production_onsite FUJIFILM J21RM9L4G4 6 8 0 2363 0 {00000000-0000-0000-0000-000000000000} 0
10:39:40.595 [7376.24708] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
10:39:40.595 [7376.24708] <2> parse_resource_strings: DRIVE 3 A000_F6_S6_D66 2000190 0007839108 {4,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
10:39:40.595 [7376.24708] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
10:39:40.595 [7376.24708] <2> parse_resource_strings: STORAGE 1 gaalpa1glinkdc1_lto 6 2048 2 1 0 0 gaalpa1glinkdc1-ebr.aldc.att.com gaalpa1glinkdc1-ebr.aldc.att.com *NULL*
10:39:40.595 [7376.24708] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
10:39:40.595 [7376.24708] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
10:39:40.595 [7376.24708] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
10:39:40.595 [7376.24708] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
10:39:40.595 [7376.24708] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
10:39:40.595 [7376.24708] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
10:39:40.595 [7376.24708] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
10:39:40.595 [7376.24708] <2> nbjm_media_request: Job control returned to BPTM
10:39:40.595 [7376.24708] <2> drivename_open: Called with Create 1, file A000_F6_S6_D66
10:39:40.595 [29636.20872] <2> RequestInitialResources: returning
10:39:40.595 [29636.20872] <2> parse_resource_strings: MEDIADB 1 13027090 AL2518 4007231 ------ 6 1352522946 1352524778 1357881578 0 36864000 18 0 4 4 0 0 1024 0 576038 0
10:39:40.595 [29636.20872] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
10:39:40.595 [29636.20872] <2> parse_resource_strings: VOLUME 1 AL2518 4007231 AL2518L3 Production FUJIFILM RBZTUKv295 6 8 0 1712 0 {00000000-0000-0000-0000-000000000000} 0
10:39:40.595 [29636.20872] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
10:39:40.595 [29636.20872] <2> parse_resource_strings: DRIVE 3 A000_F6_S8_D68 2000192 0007838646 {4,0,1,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
10:39:40.595 [7376.24708] <2> drivename_checklock: Called
ed message type 17, version 3, 23 parameters
10:39:40.595 [29636.20872] <2> parse_resource_strings: STORAGE 1 gaalpa1glinkdc1_lto 6 2048 2 1 0 0 gaalpa1glinkdc1-ebr.aldc.att.com gaalpa1glinkdc1-ebr.aldc.att.com *NULL*
10:39:40.595 [29636.20872] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
10:39:40.595 [29636.20872] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
10:39:40.595 [29636.20872] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
10:39:40.595 [29636.20872] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
10:39:40.595 [29636.20872] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
10:39:40.595 [29636.20872] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
10:39:40.595 [29636.20872] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
10:39:40.595 [29636.20872] <2> nbjm_media_request: Job control returned to BPTM
10:39:40.595 [29636.20872] <2> drivename_open: Called with Create 1, file A000_F6_S8_D68
10:39:40.595 [29636.20872] <2> drivename_checklock: Called
10:39:40.595 [29636.20872] <2> drivename_lock: lock established
10:39:40.595 [7376.24708] <4> create_tpreq_file: {4,0,0,0}
10:39:40.595 [29636.20872] <4> create_tpreq_file: {4,0,1,0}
10:39:40.595 [7376.24708] <2> drivename_write: Called with mode 2
10:39:40.595 [7376.24708] <2> drivename_unlock: unlocked
10:39:40.595 [7376.24708] <2> drivename_checklock: Called
10:39:40.595 [7376.24708] <2> drivename_lock: lock established
10:39:40.595 [29636.20872] <2> drivename_write: Called with mode 2
10:39:40.595 [7376.24708] <2> openNTDevice: config_path: {4,0,0,0}, serial_num: 0007839108
10:39:40.595 [29636.20872] <2> drivename_unlock: unlocked
10:39:40.595 [29636.20872] <2> drivename_checklock: Called
10:39:40.595 [29636.20872] <2> drivename_lock: lock established
10:39:40.595 [29636.20872] <2> openNTDevice: config_path: {4,0,1,0}, serial_num: 0007838646
10:39:40.595 [7376.24708] <2> get_drive_path: SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:39:40.595 [29636.20872] <2> get_drive_path: SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000100#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:39:40.595 [7376.24708] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, drive serial number 0007839108, expected serial number 0007839108
10:39:40.595 [7376.24708] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
10:39:40.595 [7376.24708] <2> really_tpunmount: tpunmount'ing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66
10:39:40.611 [29636.20872] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, drive serial number 0007838646, expected serial number 0007838646
10:39:40.611 [29636.20872] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
10:39:40.611 [29636.20872] <2> really_tpunmount: tpunmount'ing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S8_D68
10:39:41.609 [7376.24708] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
10:39:42.623 [29636.20872] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
10:40:39.814 [7376.24708] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:40:39.814 [7376.24708] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:40:39.907 [7376.24708] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56240 TO 135.53.7.32.13724
10:40:40.344 [7376.24708] <4> report_resource_done: VBRD 1 7376 0 A000_F6_S6_D66 AL0908
10:40:40.344 [7376.24708] <2> openNTDevice: config_path: {4,0,0,0}, serial_num: 0007839108
10:40:40.344 [7376.24708] <2> get_drive_path: SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:40:40.344 [7376.24708] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, drive serial number 0007839108, expected serial number 0007839108
10:40:40.344 [7376.24708] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
10:40:40.344 [7376.24708] <2> tapealert_and_release: SCSI RELEASE
10:40:40.344 [7376.24708] <2> drivename_unlock: unlocked
10:40:40.344 [7376.24708] <2> drivename_close: Called for file A000_F6_S6_D66
10:40:40.375 [7376.24708] <2> drivename_remove: Called
10:40:40.375 [7376.24708] <2> main: Sending [EXIT STATUS 0] to NBJM
10:40:40.375 [7376.24708] <2> bptm: EXITING with status 0 <----------
10:41:03.979 [29636.20872] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:41:03.979 [29636.20872] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:41:04.088 [29636.20872] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56255 TO 135.53.7.32.13724
10:41:04.525 [29636.20872] <4> report_resource_done: VBRD 1 29636 0 A000_F6_S8_D68 AL2518
10:41:04.525 [29636.20872] <2> openNTDevice: config_path: {4,0,1,0}, serial_num: 0007838646
10:41:04.525 [29636.20872] <2> get_drive_path: SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000100#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:41:04.525 [29636.20872] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, drive serial number 0007838646, expected serial number 0007838646
10:41:04.525 [29636.20872] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
10:41:04.556 [29636.20872] <2> tapealert_and_release: SCSI RELEASE
10:41:04.556 [29636.20872] <2> drivename_unlock: unlocked
10:41:04.556 [29636.20872] <2> drivename_close: Called for file A000_F6_S8_D68
10:41:04.587 [29636.20872] <2> drivename_remove: Called
10:41:04.587 [29636.20872] <2> main: Sending [EXIT STATUS 0] to NBJM
10:41:04.587 [29636.20872] <2> bptm: EXITING with status 0 <----------
10:41:10.936 [38176.13376] <2> bptm: INITIATING (VERBOSE = 0): -w -pid 37672 -c gaalpa1glisql03.itservices.sbc.com -den 6 -rt 8 -rn 0 -stunit gaalpa1glinkdc1_lto -cl gaalpa1glisql03_vip_sql -bt 1352562064 -b gaalpa1glisql03.itservices.sbc.com_1352562064 -st 0 -cj 2 -p Production -reqid -1350857465 -jm -brm -hostname gaalpa1glisql03.itservices.sbc.com -ru root -rclnt gaalpa1glisql03.itservices.sbc.com -rclnthostname gaalpa1glisql03.itservices.sbc.com -rl 1 -rp 1209600 -sl Full -ct 13 -maxfrag 2048 -mediasvr gaalpa1glinkdc1-ebr.aldc.att.com -no_callback -connect_options 0x01010100 -jobid 1262687 -jobgrpid 1259192 -masterversion 650000 -bpbrm_shm_id NetBackup_BPBRM_SHM_Path_-1665012336_37672_26260 -blks_per_buffer 128 -shm 
10:41:10.936 [38176.13376] <4> bptm: emmserver_name = asprod11.aldc.att.com
10:41:10.936 [38176.13376] <4> bptm: emmserver_port = 1556
10:41:10.952 [38176.13376] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:41:10.999 [38176.13376] <2> nbjm_media_request: Passing job control to NBJM, type WRITE/1
10:41:10.999 [38176.13376] <2> nbjm_media_request: old_media_id = , media_id = NULL
10:41:10.999 [38176.13376] <2> Orb::init: Created anon service name: NB_38176_1096897740(Orb.cpp:610)
10:41:10.999 [38176.13376] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_38176_1096897740(Orb.cpp:628)
10:41:10.999 [38176.13376] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_38176_1096897740 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:41:13.042 [38176.13376] <2> RequestInitialResources: returning
10:41:13.042 [38176.13376] <2> parse_resource_strings: MEDIADB 1 13027100 AL3215 4006437 ------ 6 1351652974 1352523822 1353733422 0 536557684 275 186 1 4 0 0 1024 0 8384276 0
10:41:13.042 [38176.13376] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
10:41:13.042 [38176.13376] <2> parse_resource_strings: VOLUME 1 AL3215 4006437 AL3215L3 Production FUJIFILM 1125302600 6 8 0 407 0 {00000000-0000-0000-0000-000000000000} 0
10:41:13.042 [38176.13376] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
10:41:13.042 [38176.13376] <2> parse_resource_strings: DRIVE 3 A000_F6_S6_D66 2000190 0007839108 {4,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
10:41:13.042 [38176.13376] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
10:41:13.042 [38176.13376] <2> parse_resource_strings: STORAGE 1 gaalpa1glinkdc1_lto 6 2048 2 1 0 0 gaalpa1glinkdc1-ebr.aldc.att.com gaalpa1glinkdc1-ebr.aldc.att.com *NULL*
10:41:13.042 [38176.13376] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
10:41:13.042 [38176.13376] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
10:41:13.042 [38176.13376] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
10:41:13.042 [38176.13376] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
10:41:13.042 [38176.13376] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
10:41:13.042 [38176.13376] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
10:41:13.042 [38176.13376] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
10:41:13.042 [38176.13376] <2> nbjm_media_request: Job control returned to BPTM
10:41:13.042 [38176.13376] <2> io_init: bpbrm_handle = 988, buffer address = 0xf80000
10:41:13.042 [38176.13376] <2> io_init: found index: 0
10:41:13.042 [38176.13376] <2> io_init: using 65536 data buffer size
10:41:13.042 [38176.13376] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 60000
10:41:13.042 [38176.13376] <2> io_set_recvbuf: setting receive network buffer to 263168 bytes
10:41:13.042 [38176.13376] <2> io_init: using 30 data buffers
10:41:13.042 [38176.13376] <2> io_init: child delay = 10, parent delay = 15 (milliseconds)
10:41:13.042 [38176.13376] <2> create_shared_memory: shm_size = 1966808, buffer address = 0x2520000, buf control = 0x2700000, ready ptr = 0x27002d0
10:41:13.042 [38176.13376] <2> setup_bpbkar_info: Global\NetBackup Media Manager SHM Info Path gaalpa1glisql03.itservices.sbc.com_1352562064 file successfully created
10:41:13.073 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:41:13.073 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:41:13.183 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56410 TO 135.53.7.32.13724
10:41:13.666 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:41:13.666 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:41:13.791 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56411 TO 135.53.7.32.13724
10:41:14.212 [38176.13376] <4> report_client: VBRC 2 38176 1 gaalpa1glisql03.itservices.sbc.com_1352562064 13 gaalpa1glisql03_vip_sql 0 Full 0 1 1 
10:41:14.243 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:41:14.243 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:41:14.353 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56412 TO 135.53.7.32.13724
10:41:14.789 [38176.13376] <2> drivename_open: Called with Create 1, file A000_F6_S6_D66
10:41:14.805 [38176.13376] <2> drivename_checklock: Called
10:41:14.805 [38176.13376] <2> drivename_lock: lock established
10:41:14.805 [38176.13376] <2> drivename_write: Called with mode 0
10:41:14.805 [38176.13376] <2> drivename_unlock: unlocked
10:41:14.805 [38176.13376] <2> drivename_checklock: Called
10:41:14.805 [38176.13376] <2> drivename_lock: lock established
10:41:14.805 [38176.13376] <2> db_byid: search for media id AL3215
10:41:14.821 [38176.13376] <2> bptm media_id_to_monitor: job_id = 1262687
10:41:14.852 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:41:14.852 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpjobd
10:41:14.852 [38176.13376] <2> job_connect: SO_KEEPALIVE set on socket 996 for client asprod11.aldc.att.com
10:41:14.852 [38176.13376] <2> logconnections: BPJOBD CONNECT FROM 130.8.58.178.56416 TO 135.53.7.32.13724
10:41:14.852 [38176.13376] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
10:41:14.852 [38176.13376] <2> job_connect: Connected to the host asprod11.aldc.att.com contype 10 jobid <1262687> socket <996>
10:41:14.852 [38176.13376] <2> job_connect: Connected on port 56416
10:41:14.852 [38176.13376] <2> bptm media_id_to_monitor: pDstMediaId = AL3215
10:41:14.852 [38176.13376] <2> mount_open_media: Waiting for mount of media id AL3215 (copy 1) on server gaalpa1glinkdc1-ebr.aldc.att.com.
10:41:14.852 [38176.13376] <2> openNTDevice: config_path: {4,0,0,0}, serial_num: 0007839108
10:41:14.852 [38176.13376] <2> get_drive_path: SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:41:14.852 [38176.13376] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, drive serial number 0007839108, expected serial number 0007839108
10:41:14.852 [38176.13376] <2> manage_scsi_reserve: SCSI RESERVE
10:41:15.055 [38176.13376] <2> tapelib: wait_for_ltid, Mount, timeout 0
10:41:30.546 [25992.6476] <2> bptm: INITIATING (VERBOSE = 0): -rptdrv -jobid -1350857478 -jm 
10:41:30.561 [25992.6476] <2> drivename_open: Called with Create 0, file A000_F6_S6_D66
10:41:30.592 [25992.6476] <2> drivename_checklock: Called
10:41:30.592 [25992.6476] <2> drivename_checklock: File is locked
10:41:30.592 [25992.6476] <2> report_drives: DRIVE = A000_F6_S6_D66 LOCK = TRUE CURTIME = 1352562090
10:41:30.592 [25992.6476] <2> drivename_close: Called for file A000_F6_S6_D66
10:41:30.608 [25992.6476] <2> report_drives: MODE = 0
10:41:30.608 [25992.6476] <2> report_drives: TIME = 1352562074
10:41:30.608 [25992.6476] <2> report_drives: MASTER = asprod11.aldc.att.com
10:41:30.608 [25992.6476] <2> report_drives: SR_KEY = 0 1
10:41:30.608 [25992.6476] <2> report_drives: PATH = {4,0,0,0}
10:41:30.608 [25992.6476] <2> report_drives: MEDIA = AL3215
10:41:30.608 [25992.6476] <2> report_drives: REQID = -1350857465
10:41:30.608 [25992.6476] <2> report_drives: ALOCID = 13027100
10:41:30.608 [25992.6476] <2> report_drives: RBID = {FB7B010E-1DD1-11B2-A91F-00144F435F04}
10:41:30.608 [25992.6476] <2> report_drives: PID = 38176
10:41:30.608 [25992.6476] <2> report_drives: FILE = D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66
10:41:30.608 [25992.6476] <2> main: Sending [EXIT STATUS 0] to NBJM
10:41:30.608 [25992.6476] <2> bptm: EXITING with status 0 <----------
10:41:40.795 [38176.13376] <2> openTpreqFile: tpreq_file: D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66, serial_num: 0007839108
10:41:40.795 [38176.13376] <2> get_drive_path: SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:41:40.795 [38176.13376] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, drive serial number 0007839108, expected serial number 0007839108
10:41:40.826 [38176.13376] <2> init_tape: \\.\Tape0 (SCSI coordinates {4,0,0,0}) configured with blocksize 0
10:41:40.842 [38176.13376] <2> init_tape: \\.\Tape0 (SCSI coordinates {4,0,0,0}) has compression enabled
10:41:40.873 [38176.13376] <2> io_open: SCSI RESERVE
10:41:40.904 [38176.13376] <2> manage_drive_attributes: report_attr, fl1 0x00000049, fl2 0x0000000c
10:41:40.904 [38176.13376] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [1125302600]
10:41:40.904 [38176.13376] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [6.5.6]
10:41:40.904 [38176.13376] <2> manage_drive_attributes: DateLabeled [201210310309], Barcode [AL3215L3], Owninghost [gaalpa1glinkdc1-ebr.aldc.att.com]
10:41:40.904 [38176.13376] <2> manage_drive_attributes: MediaPool [Production], MediaLabel [MEDIA=AL3215;]
10:41:40.904 [38176.13376] <2> io_open: file D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66 successfully opened (mode 2)
10:41:40.904 [38176.13376] <2> write_backup: media id AL3215 mounted on drive index 0, drivepath {4,0,0,0}, drivename A000_F6_S6_D66, copy 1
10:41:40.935 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:41:40.935 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:41:41.045 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56432 TO 135.53.7.32.13724
10:41:41.497 [38176.13376] <4> report_throughput: VBRT 1 38176 1 1 A000_F6_S6_D66 AL3215 0 1 0 0  0 (bptm.c.20529)
10:41:41.497 [38176.13376] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x2182e90, copy 1
10:41:41.497 [38176.13376] <2> io_ioctl: command (5)MTREW 1 from (bptm.c.8175) on drive index 0
10:41:41.544 [38176.13376] <2> io_ioctl: command (1)MTFSF 1 from (bptm.c.8432) on drive index 0
10:41:41.544 [38176.13376] <2> io_position_for_write: position media id AL3215, copy 1, current number images = 275
10:41:41.544 [38176.13376] <2> io_position_for_write: locating to absolute block number 8384276, copy 1
10:42:02.822 [38176.13376] <2> io_position_for_write: locate block is done
10:42:04.336 [38176.13376] <2> io_position_for_write: processing empty header, filenum = 276, bid = (empty_file), copy 1
10:42:04.336 [38176.13376] <2> io_position_for_write: empty header found on AL3215, OK, copy 1
10:42:04.336 [38176.13376] <2> io_ioctl: command (2)MTBSF 1 from (bptm.c.24211) on drive index 0
10:42:04.367 [38176.13376] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.24228) on drive index 0
10:42:08.938 [38176.13376] <2> send_MDS_msg: MEDIADB 1 13027100 AL3215 4006437 *NULL* 6 1351652974 1352562064 1353771664 0 536557684 275 186 1 4 0 0 1024 0 8384276 0
10:42:08.985 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:42:08.985 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:42:09.094 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56445 TO 135.53.7.32.13724
10:42:09.515 [38176.13376] <4> write_backup: begin writing backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 1, to media id AL3215 on drive A000_F6_S6_D66 (index 0)
10:42:09.515 [38176.13376] <2> signal_parent: set bpbrm media ready event (pid = 37672)
10:42:09.515 [38176.13376] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:42:09.515 [38176.13376] <2> write_data: Total Kbytes transferred 0
10:42:09.546 [38176.13376] <2> write_data: absolute block position prior to writing backup header(s) is 8384276, copy 1
10:42:09.546 [38176.13376] <2> io_write_back_header: drive index 0, gaalpa1glisql03.itservices.sbc.com_1352562064, file num = 276, mpx_headers = 0, copy 1
10:42:09.546 [38176.13376] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
10:42:09.546 [38176.13376] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
10:42:09.546 [38176.13376] <2> write_data: received first buffer (65536 bytes), begin writing data
10:42:55.926 [38176.13376] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
10:42:55.926 [38176.13376] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 0
10:42:56.784 [38176.13376] <2> write_backup: maximum fragment size written --- Fragmenting
10:42:56.799 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:42:56.799 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:42:56.924 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56463 TO 135.53.7.32.13724
10:42:57.330 [38176.13376] <4> report_throughput: VBRT 1 38176 5 1 A000_F6_S6_D66 AL3215 0 1 0 2048000  2048000 (bptm.c.22568)
10:42:57.361 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:42:57.361 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:42:57.361 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56464 TO 135.53.7.32.13724
10:42:57.798 [38176.13376] <2> send_MDS_msg: MEDIADB 1 13027100 AL3215 4006437 *NULL* 6 1351652974 1352562064 1353771664 0 538605684 276 187 1 4 0 0 1024 0 8384276 0
10:42:57.829 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:42:57.844 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:42:57.954 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56465 TO 135.53.7.32.13724
10:42:58.390 [38176.13376] <4> write_backup: successfully wrote backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 1, 2048000 Kbytes at 44157.916 Kbytes/sec
10:42:58.406 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:42:58.406 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:42:58.515 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.56466 TO 135.53.7.32.13724
10:42:58.952 [38176.13376] <4> write_backup: begin writing backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 2, to media id AL3215 on drive A000_F6_S6_D66 (index 0)
10:42:58.952 [38176.13376] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:42:58.952 [38176.13376] <2> write_data: Total Kbytes transferred 2048000
10:42:58.952 [38176.13376] <2> write_data: absolute block position prior to writing backup header(s) is 8416278, copy 1
10:42:58.952 [38176.13376] <2> write_data: block position check: actual 8416278, expected 8416278
10:42:58.952 [38176.13376] <2> io_write_back_header: drive index 0, gaalpa1glisql03.itservices.sbc.com_1352562064, file num = 277, mpx_headers = 0, copy 1
10:42:58.968 [38176.13376] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
10:42:58.968 [38176.13376] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
10:42:58.968 [38176.13376] <2> write_data: received first buffer (65536 bytes), begin writing data
10:43:39.138 [38176.13376] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
10:43:39.138 [38176.13376] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 0
10:43:39.591 [38176.13376] <2> write_backup: maximum fragment size written --- Fragmenting
10:43:39.622 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:43:39.622 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:43:39.731 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.61168 TO 135.53.7.32.13724
10:43:40.183 [38176.13376] <4> report_throughput: VBRT 1 38176 5 1 A000_F6_S6_D66 AL3215 0 1 0 2048000  2048000 (bptm.c.22568)
10:43:40.215 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:43:40.215 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:43:40.324 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.61169 TO 135.53.7.32.13724
10:43:40.761 [38176.13376] <2> send_MDS_msg: MEDIADB 1 13027100 AL3215 4006437 *NULL* 6 1351652974 1352562064 1353771664 0 540653684 277 188 1 4 0 0 1024 0 8384276 0
10:43:40.839 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:43:40.839 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:43:40.839 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.61170 TO 135.53.7.32.13724
10:43:41.260 [38176.13376] <4> write_backup: successfully wrote backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 2, 2048000 Kbytes at 50983.321 Kbytes/sec
10:43:41.291 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:43:41.291 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:43:41.291 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.61171 TO 135.53.7.32.13724
10:43:41.728 [38176.13376] <4> write_backup: begin writing backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 3, to media id AL3215 on drive A000_F6_S6_D66 (index 0)
10:43:41.728 [38176.13376] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:43:41.728 [38176.13376] <2> write_data: Total Kbytes transferred 4096000
10:43:41.728 [38176.13376] <2> write_data: absolute block position prior to writing backup header(s) is 8448280, copy 1
10:43:41.728 [38176.13376] <2> write_data: block position check: actual 8448280, expected 8448280
10:43:41.728 [38176.13376] <2> io_write_back_header: drive index 0, gaalpa1glisql03.itservices.sbc.com_1352562064, file num = 278, mpx_headers = 0, copy 1
10:43:41.743 [38176.13376] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
10:43:41.743 [38176.13376] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
10:43:41.743 [38176.13376] <2> write_data: received first buffer (65536 bytes), begin writing data
10:44:25.424 [38176.13376] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
10:44:25.424 [38176.13376] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 0
10:44:26.142 [38176.13376] <2> write_backup: maximum fragment size written --- Fragmenting
10:44:26.157 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:44:26.157 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:44:26.157 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.61194 TO 135.53.7.32.13724
10:44:26.610 [38176.13376] <4> report_throughput: VBRT 1 38176 5 1 A000_F6_S6_D66 AL3215 0 1 0 2048000  2048000 (bptm.c.22568)
10:44:26.641 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:44:26.641 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:44:26.641 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.61195 TO 135.53.7.32.13724
10:44:27.078 [38176.13376] <2> send_MDS_msg: MEDIADB 1 13027100 AL3215 4006437 *NULL* 6 1351652974 1352562064 1353771664 0 542701684 278 189 1 4 0 0 1024 0 8384276 0
10:44:27.140 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:44:27.140 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:44:27.140 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.61196 TO 135.53.7.32.13724
10:44:27.546 [38176.13376] <4> write_backup: successfully wrote backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 3, 2048000 Kbytes at 46885.374 Kbytes/sec
10:44:27.592 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:44:27.592 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:44:27.702 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.61197 TO 135.53.7.32.13724
10:44:28.138 [38176.13376] <4> write_backup: begin writing backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 4, to media id AL3215 on drive A000_F6_S6_D66 (index 0)
10:44:28.138 [38176.13376] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:44:28.138 [38176.13376] <2> write_data: Total Kbytes transferred 6144000
10:44:28.170 [38176.13376] <2> write_data: absolute block position prior to writing backup header(s) is 8480282, copy 1
10:44:28.170 [38176.13376] <2> write_data: block position check: actual 8480282, expected 8480282
10:44:28.170 [38176.13376] <2> io_write_back_header: drive index 0, gaalpa1glisql03.itservices.sbc.com_1352562064, file num = 279, mpx_headers = 0, copy 1
10:44:28.185 [38176.13376] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
10:44:28.185 [38176.13376] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
10:44:28.185 [38176.13376] <2> write_data: received first buffer (65536 bytes), begin writing data
10:45:11.788 [38176.13376] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
10:45:11.788 [38176.13376] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 0
10:45:12.303 [38176.13376] <2> write_backup: maximum fragment size written --- Fragmenting
10:45:12.334 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:45:12.334 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:45:12.334 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.62099 TO 135.53.7.32.13724
10:45:12.755 [38176.13376] <4> report_throughput: VBRT 1 38176 5 1 A000_F6_S6_D66 AL3215 0 1 0 2048000  2048000 (bptm.c.22568)
10:45:12.786 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:45:12.786 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:45:12.786 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.62177 TO 135.53.7.32.13724
10:45:13.223 [38176.13376] <2> send_MDS_msg: MEDIADB 1 13027100 AL3215 4006437 *NULL* 6 1351652974 1352562064 1353771664 0 544749684 279 190 1 4 0 0 1024 0 8384276 0
10:45:13.285 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:45:13.285 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:45:13.395 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.62277 TO 135.53.7.32.13724
10:45:13.847 [38176.13376] <4> write_backup: successfully wrote backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 4, 2048000 Kbytes at 46970.322 Kbytes/sec
10:45:13.878 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:45:13.878 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:45:13.878 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.62404 TO 135.53.7.32.13724
10:45:14.315 [38176.13376] <4> write_backup: begin writing backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 5, to media id AL3215 on drive A000_F6_S6_D66 (index 0)
10:45:14.315 [38176.13376] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:45:14.315 [38176.13376] <2> write_data: Total Kbytes transferred 8192000
10:45:14.331 [38176.13376] <2> write_data: absolute block position prior to writing backup header(s) is 8512284, copy 1
10:45:14.331 [38176.13376] <2> write_data: block position check: actual 8512284, expected 8512284
10:45:14.331 [38176.13376] <2> io_write_back_header: drive index 0, gaalpa1glisql03.itservices.sbc.com_1352562064, file num = 280, mpx_headers = 0, copy 1
10:45:14.346 [38176.13376] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
10:45:14.346 [38176.13376] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
10:45:14.346 [38176.13376] <2> write_data: received first buffer (65536 bytes), begin writing data
10:45:58.105 [38176.13376] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
10:45:58.105 [38176.13376] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 0
10:45:59.883 [38176.13376] <2> write_backup: maximum fragment size written --- Fragmenting
10:45:59.899 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:45:59.899 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:46:00.024 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.54587 TO 135.53.7.32.13724
10:46:00.460 [38176.13376] <4> report_throughput: VBRT 1 38176 5 1 A000_F6_S6_D66 AL3215 0 1 0 2048000  2048000 (bptm.c.22568)
10:46:00.492 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:46:00.492 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:46:00.492 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.54713 TO 135.53.7.32.13724
10:46:00.913 [38176.13376] <2> send_MDS_msg: MEDIADB 1 13027100 AL3215 4006437 *NULL* 6 1351652974 1352562064 1353771664 0 546797684 280 191 1 4 0 0 1024 0 8384276 0
10:46:00.960 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:46:00.960 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:46:01.084 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.54777 TO 135.53.7.32.13724
10:46:01.490 [38176.13376] <4> write_backup: successfully wrote backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 5, 2048000 Kbytes at 46801.801 Kbytes/sec
10:46:01.521 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:46:01.521 [38176.13376] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:46:01.537 [38176.13376] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.54919 TO 135.53.7.32.13724
10:46:01.974 [38176.13376] <4> write_backup: begin writing backup id gaalpa1glisql03.itservices.sbc.com_1352562064, copy 1, fragment 6, to media id AL3215 on drive A000_F6_S6_D66 (index 0)
10:46:01.974 [38176.13376] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0
10:46:01.974 [38176.13376] <2> write_data: Total Kbytes transferred 10240000
10:46:01.974 [38176.13376] <2> write_data: absolute block position prior to writing backup header(s) is 8544286, copy 1
10:46:01.974 [38176.13376] <2> write_data: block position check: actual 8544286, expected 8544286
10:46:01.974 [38176.13376] <2> io_write_back_header: drive index 0, gaalpa1glisql03.itservices.sbc.com_1352562064, file num = 281, mpx_headers = 0, copy 1
10:46:01.974 [38176.13376] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
10:46:01.974 [38176.13376] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
10:46:01.974 [38176.13376] <2> write_data: received first buffer (65536 bytes), begin writing data
10:46:42.019 [38176.13376] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = -6
10:46:42.019 [38176.13376] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.22205) on drive index 0
10:46:42.596 [38176.13376] <2> write_backup: maximum fragment size written --- Fragmenting
10:46:42.596 [38176.13376] <2> vnet_bind_to_port_addr_extra: vnet_bind.c.158: Function failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> vnet_async_connect: vnet_vnetd.c.3910: vnet_bind_to_port_addr failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> vnet_bind_to_port_addr_extra: vnet_bind.c.158: Function failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> vnet_async_connect: vnet_vnetd.c.3910: vnet_bind_to_port_addr failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> vnet_connect_to_service_or_vnetd: vnet_vnetd.c.3571: vnet_async_connect failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> nb_connect_to_vnetd_or_legacy: comm.c.2030: vnet_connect_to_vnetd_or_service failed: 10
10:46:42.596 [38176.13376] <2> db_begin: nb_connect_to_vnetd_or_legacy(asprod11.aldc.att.com) failed retval 21 err 0
10:46:42.596 [38176.13376] <2> db_begin: nb_getsockconnected() failed: The operation completed successfully.  (0)
10:46:42.596 [38176.13376] <2> db_ERROR: db_begin() failed: cannot connect on socket
10:46:42.596 [38176.13376] <16> logERROR: cannot log message to error database, error = cannot connect on socket
10:46:42.596 [38176.13376] <4> report_throughput: VBRT 1 38176 5 1 A000_F6_S6_D66 AL3215 0 1 0 2048000  2048000 (bptm.c.22568)
10:46:42.596 [38176.13376] <2> vnet_bind_to_port_addr_extra: vnet_bind.c.158: Function failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> vnet_async_connect: vnet_vnetd.c.3910: vnet_bind_to_port_addr failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> vnet_bind_to_port_addr_extra: vnet_bind.c.158: Function failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> vnet_async_connect: vnet_vnetd.c.3910: vnet_bind_to_port_addr failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> vnet_connect_to_service_or_vnetd: vnet_vnetd.c.3571: vnet_async_connect failed: 10 0x0000000a
10:46:42.596 [38176.13376] <2> nb_connect_to_vnetd_or_legacy: comm.c.2030: vnet_connect_to_vnetd_or_service failed: 10
10:46:42.596 [38176.13376] <2> db_begin: nb_connect_to_vnetd_or_legacy(asprod11.aldc.att.com) failed retval 21 err 0
10:46:42.596 [38176.13376] <2> db_begin: nb_getsockconnected() failed: The operation completed successfully.  (0)
10:46:42.612 [38176.13376] <2> db_IMAGE: db_begin() failed: cannot connect on socket
10:46:42.628 [38176.13376] <2> vnet_bind_to_port_addr_extra: vnet_bind.c.158: Function failed: 10 0x0000000a
10:46:42.628 [38176.13376] <2> vnet_async_connect: vnet_vnetd.c.3910: vnet_bind_to_port_addr failed: 10 0x0000000a
10:46:42.628 [38176.13376] <2> vnet_bind_to_port_addr_extra: vnet_bind.c.158: Function failed: 10 0x0000000a
10:46:42.628 [38176.13376] <2> vnet_async_connect: vnet_vnetd.c.3910: vnet_bind_to_port_addr failed: 10 0x0000000a
10:46:42.628 [38176.13376] <2> vnet_connect_to_service_or_vnetd: vnet_vnetd.c.3571: vnet_async_connect failed: 10 0x0000000a
10:46:42.628 [38176.13376] <2> nb_connect_to_vnetd_or_legacy: comm.c.2030: vnet_connect_to_vnetd_or_service failed: 10
10:46:42.628 [38176.13376] <2> db_begin: nb_connect_to_vnetd_or_legacy(asprod11.aldc.att.com) failed retval 21 err 0
10:46:42.628 [38176.13376] <2> db_begin: nb_getsockconnected() failed: The operation completed successfully.  (0)
10:46:42.628 [38176.13376] <2> db_ERROR: db_begin() failed: cannot connect on socket
10:46:42.628 [38176.13376] <16> logERROR: cannot log message to error database, error = cannot connect on socket
10:46:42.628 [38176.13376] <16> write_backup: cannot add fragment to image database, error = cannot connect on socket
10:46:42.628 [38176.13376] <2> send_MDS_msg: MEDIADB 1 13027100 AL3215 4006437 *NULL* 6 1351652974 1352562064 1353771664 0 548845684 281 191 1 4 0 0 1024 0 8384276 0
10:46:42.643 [38176.13376] <2> io_terminate_tape: writing empty backup header, drive index 0, copy 1
10:46:42.643 [38176.13376] <2> io_terminate_tape: reposition to previous tapemark and rewrite header
10:46:42.643 [38176.13376] <2> io_ioctl: command (2)MTBSF 1 from (bptm.c.8694) on drive index 0
10:46:45.030 [38176.13376] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.8725) on drive index 0
10:46:46.871 [38176.13376] <2> io_terminate_tape: absolute block position prior to writing empty header is 8576288, copy 1
10:46:46.871 [38176.13376] <2> io_write_back_header: drive index 0, empty_file, file num = 282, mpx_headers = 0, copy 1
10:46:46.871 [38176.13376] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66, from bptm.c.8843
10:46:46.871 [38176.13376] <2> send_MDS_msg: MEDIADB 1 13027100 AL3215 4006437 *NULL* 6 1351652974 1352562064 1353771664 0 548845684 281 191 1 4 0 0 1024 0 8576288 0
10:46:46.902 [38176.13376] <2> openTpreqFile: tpreq_file: D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66, serial_num: 0007839108
10:46:46.902 [38176.13376] <2> get_drive_path: SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:46:46.902 [38176.13376] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, drive serial number 0007839108, expected serial number 0007839108
10:46:46.933 [38176.13376] <2> init_tape: \\.\Tape0 (SCSI coordinates {4,0,0,0}) configured with blocksize 0
10:46:46.933 [38176.13376] <2> init_tape: \\.\Tape0 (SCSI coordinates {4,0,0,0}) has compression enabled
10:46:46.949 [38176.13376] <2> io_open: SCSI RESERVE
10:46:46.949 [38176.13376] <2> io_open: file D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66 successfully opened (mode 2)
10:46:48.727 [38176.13376] <2> io_terminate_tape: locate block positioned tape to 8576288 in io_terminate_tape
10:46:48.727 [38176.13376] <2> io_close: closing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66, from bptm.c.9024
10:46:48.727 [38176.13376] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)
10:46:48.727 [38176.13376] <2> bptm: EXITING with status 25 <----------
10:46:51.738 [38176.13376] <2> cleanup: Detached from BPBRM shared memory
10:51:31.029 [18736.20940] <2> bptm: INITIATING (VERBOSE = 0): -rptdrv -jobid -1350857552 -jm 
10:51:31.029 [18736.20940] <2> drivename_open: Called with Create 0, file A000_F6_S6_D66
10:51:31.029 [18736.20940] <2> drivename_checklock: Called
10:51:31.029 [18736.20940] <2> report_drives: DRIVE = A000_F6_S6_D66 LOCK = FALSE CURTIME = 1352562691
10:51:31.029 [18736.20940] <2> drivename_close: Called for file A000_F6_S6_D66
10:51:31.029 [18736.20940] <2> report_drives: MODE = 0
10:51:31.029 [18736.20940] <2> report_drives: TIME = 1352562074
10:51:31.029 [18736.20940] <2> report_drives: MASTER = asprod11.aldc.att.com
10:51:31.029 [18736.20940] <2> report_drives: SR_KEY = 0 1
10:51:31.029 [18736.20940] <2> report_drives: PATH = {4,0,0,0}
10:51:31.029 [18736.20940] <2> report_drives: MEDIA = AL3215
10:51:31.029 [18736.20940] <2> report_drives: REQID = -1350857465
10:51:31.029 [18736.20940] <2> report_drives: ALOCID = 13027100
10:51:31.029 [18736.20940] <2> report_drives: RBID = {FB7B010E-1DD1-11B2-A91F-00144F435F04}
10:51:31.029 [18736.20940] <2> report_drives: PID = 38176
10:51:31.029 [18736.20940] <2> report_drives: FILE = D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66
10:51:31.029 [18736.20940] <2> main: Sending [EXIT STATUS 0] to NBJM
10:51:31.029 [18736.20940] <2> bptm: EXITING with status 0 <----------
10:51:34.851 [23648.38388] <2> bptm: INITIATING (VERBOSE = 0): -unload -dn A000_F6_S6_D66 -dp {4,0,0,0} -dk 2000190 -mds 1024 -alocid 13027106 -jobid -1350857613 -jm 
10:51:34.851 [23648.38388] <4> bptm: emmserver_name = asprod11.aldc.att.com
10:51:34.851 [23648.38388] <4> bptm: emmserver_port = 1556
10:51:34.866 [23648.38388] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:51:34.882 [23648.38388] <2> send_brm_msg: PID of bpxm = 23648
10:51:34.882 [23648.38388] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
10:51:34.882 [23648.38388] <2> nbjm_media_request: old_media_id = NULL, media_id = 
10:51:34.882 [23648.38388] <2> Orb::init: Created anon service name: NB_23648_202911832(Orb.cpp:610)
10:51:34.882 [23648.38388] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_23648_202911832(Orb.cpp:628)
10:51:34.882 [23648.38388] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_23648_202911832 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:51:36.941 [23648.38388] <2> RequestInitialResources: returning
10:51:36.941 [23648.38388] <2> parse_resource_strings: MEDIADB 1 13027106 *NULL* 0 *NULL* 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
10:51:36.941 [23648.38388] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
10:51:36.941 [23648.38388] <2> parse_resource_strings: VOLUME 1 *NULL* 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0
10:51:36.941 [23648.38388] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
10:51:36.941 [23648.38388] <2> parse_resource_strings: DRIVE 3 A000_F6_S6_D66 2000190 0007839108 {4,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 1024 0 1 0 0
10:51:36.941 [23648.38388] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
10:51:36.941 [23648.38388] <2> parse_resource_strings: STORAGE 1 *NULL* 0 0 0 0 0 0 gaalpa1glinkdc1-ebr.aldc.att.com gaalpa1glinkdc1-ebr.aldc.att.com *NULL*
10:51:36.941 [23648.38388] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
10:51:36.941 [23648.38388] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
10:51:36.941 [23648.38388] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
10:51:36.941 [23648.38388] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
10:51:36.941 [23648.38388] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
10:51:36.941 [23648.38388] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
10:51:36.941 [23648.38388] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
10:51:36.941 [23648.38388] <2> nbjm_media_request: Job control returned to BPTM
10:51:36.941 [23648.38388] <2> drivename_open: Called with Create 1, file A000_F6_S6_D66
10:51:36.941 [23648.38388] <2> drivename_checklock: Called
10:51:36.941 [23648.38388] <2> drivename_lock: lock established
10:51:36.941 [23648.38388] <4> create_tpreq_file: {4,0,0,0}
10:51:36.941 [23648.38388] <2> drivename_write: Called with mode 2
10:51:36.941 [23648.38388] <2> drivename_unlock: unlocked
10:51:36.941 [23648.38388] <2> drivename_checklock: Called
10:51:36.941 [23648.38388] <2> drivename_lock: lock established
10:51:36.941 [23648.38388] <2> openNTDevice: config_path: {4,0,0,0}, serial_num: 0007839108
10:51:36.941 [23648.38388] <2> get_drive_path: SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:51:36.941 [23648.38388] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, drive serial number 0007839108, expected serial number 0007839108
10:51:36.957 [23648.38388] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
10:51:36.957 [23648.38388] <2> really_tpunmount: tpunmount'ing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S6_D66
10:51:37.768 [23648.38388] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
10:53:22.305 [23648.38388] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:53:22.305 [23648.38388] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:53:22.398 [23648.38388] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.54896 TO 135.53.7.32.13724
10:53:22.820 [23648.38388] <4> report_resource_done: VBRD 1 23648 0 A000_F6_S6_D66 *NULL*
10:53:22.820 [23648.38388] <2> openNTDevice: config_path: {4,0,0,0}, serial_num: 0007839108
10:53:22.820 [23648.38388] <2> get_drive_path: SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:53:22.835 [23648.38388] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,0,0}, dos_path \\.\Tape0, drive serial number 0007839108, expected serial number 0007839108
10:53:22.835 [23648.38388] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
10:53:22.835 [23648.38388] <2> tapealert_and_release: SCSI RELEASE
10:53:22.835 [23648.38388] <2> drivename_unlock: unlocked
10:53:22.835 [23648.38388] <2> drivename_close: Called for file A000_F6_S6_D66
10:53:22.976 [23648.38388] <2> drivename_remove: Called
10:53:22.976 [23648.38388] <2> main: Sending [EXIT STATUS 0] to NBJM
10:53:22.976 [23648.38388] <2> bptm: EXITING with status 0 <----------
10:55:48.354 [7700.34828] <2> bptm: INITIATING (VERBOSE = 0): -unload -dn A000_F6_S8_D68 -dp {4,0,1,0} -dk 2000192 -m AL4446 -mk 4008696 -mds 0 -alocid 13027101 -jobid -1350857615 -jm 
10:55:48.354 [7700.34828] <4> bptm: emmserver_name = asprod11.aldc.att.com
10:55:48.354 [7700.34828] <4> bptm: emmserver_port = 1556
10:55:48.369 [7700.34828] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:55:48.385 [7700.34828] <2> send_brm_msg: PID of bpxm = 7700
10:55:48.385 [7700.34828] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
10:55:48.385 [7700.34828] <2> nbjm_media_request: old_media_id = NULL, media_id = AL4446
10:55:48.401 [7700.34828] <2> Orb::init: Created anon service name: NB_7700_731061639(Orb.cpp:610)
10:55:48.401 [7700.34828] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_7700_731061639(Orb.cpp:628)
10:55:48.401 [7700.34828] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_7700_731061639 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:739)
10:55:50.429 [7700.34828] <2> RequestInitialResources: returning
10:55:50.429 [7700.34828] <2> parse_resource_strings: MEDIADB 1 13027101 AL4446 4008696 ------ 6 1352347771 1352520729 1353730329 0 29016883 20 9 1 4 0 0 1024 0 453433 0
10:55:50.429 [7700.34828] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
10:55:50.429 [7700.34828] <2> parse_resource_strings: VOLUME 1 AL4446 4008696 AL4446L3 Production FUJIFILM EP3ER7KK18 6 8 0 1925 0 {00000000-0000-0000-0000-000000000000} 0
10:55:50.429 [7700.34828] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
10:55:50.429 [7700.34828] <2> parse_resource_strings: DRIVE 3 A000_F6_S8_D68 2000192 0007838646 {4,0,1,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
10:55:50.429 [7700.34828] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
10:55:50.429 [7700.34828] <2> parse_resource_strings: STORAGE 1 gaalpa1glinkdc1_lto 6 2048 2 1 0 0 gaalpa1glinkdc1-ebr.aldc.att.com gaalpa1glinkdc1-ebr.aldc.att.com *NULL*
10:55:50.429 [7700.34828] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
10:55:50.429 [7700.34828] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
10:55:50.429 [7700.34828] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
10:55:50.429 [7700.34828] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
10:55:50.429 [7700.34828] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
10:55:50.429 [7700.34828] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
10:55:50.429 [7700.34828] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
10:55:50.429 [7700.34828] <2> nbjm_media_request: Job control returned to BPTM
10:55:50.429 [7700.34828] <2> drivename_open: Called with Create 1, file A000_F6_S8_D68
10:55:50.429 [7700.34828] <2> drivename_checklock: Called
10:55:50.429 [7700.34828] <2> drivename_lock: lock established
10:55:50.429 [7700.34828] <4> create_tpreq_file: {4,0,1,0}
10:55:50.429 [7700.34828] <2> drivename_write: Called with mode 2
10:55:50.429 [7700.34828] <2> drivename_unlock: unlocked
10:55:50.429 [7700.34828] <2> drivename_checklock: Called
10:55:50.429 [7700.34828] <2> drivename_lock: lock established
10:55:50.429 [7700.34828] <2> openNTDevice: config_path: {4,0,1,0}, serial_num: 0007838646
10:55:50.429 [7700.34828] <2> get_drive_path: SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000100#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:55:50.444 [7700.34828] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, drive serial number 0007838646, expected serial number 0007838646
10:55:50.444 [7700.34828] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
10:55:50.444 [7700.34828] <2> really_tpunmount: tpunmount'ing D:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_A000_F6_S8_D68
10:55:51.256 [7700.34828] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
10:55:52.831 [7700.34828] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2048: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
10:55:52.831 [7700.34828] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2062: service: bpdbm
10:55:52.940 [7700.34828] <2> logconnections: BPDBM CONNECT FROM 130.8.58.178.63108 TO 135.53.7.32.13724
10:55:53.362 [7700.34828] <4> report_resource_done: VBRD 1 7700 0 A000_F6_S8_D68 AL4446
10:55:53.362 [7700.34828] <2> openNTDevice: config_path: {4,0,1,0}, serial_num: 0007838646
10:55:53.362 [7700.34828] <2> get_drive_path: SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td3#5&2bda6c38&0&000100#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
10:55:53.377 [7700.34828] <2> check_serial_num: serial number match for drive with SCSI coordinates {4,0,1,0}, dos_path \\.\Tape1, drive serial number 0007838646, expected serial number 0007838646
10:55:53.393 [7700.34828] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
10:55:53.393 [7700.34828] <2> tapealert_and_release: SCSI RELEASE
10:55:53.393 [7700.34828] <2> drivename_unlock: unlocked
10:55:53.393 [7700.34828] <2> drivename_close: Called for file A000_F6_S8_D68
10:55:53.408 [7700.34828] <2> drivename_remove: Called
10:55:53.408 [7700.34828] <2> main: Sending [EXIT STATUS 0] to NBJM
10:55:53.408 [7700.34828] <2> bptm: EXITING with status 0 <----------
11:01:30.731 [16468.37380] <2> bptm: INITIATING (VERBOSE = 0): -rptdrv -jobid -1350857628 -jm 
11:01:30.731 [16468.37380] <2> main: Sending [EXIT STATUS 0] to NBJM
11:01:30.731 [16468.37380] <2> bptm: EXITING with status 0 <----------