bptm on media
20:40:58.770 [5728.3232] <2> bptm: INITIATING (VERBOSE = 0): -w -pid 4240 -c cofsvrt1 -dpath Z:\nbu_disk_stu\DAILY_FILE -stunit backupsvr02-disk-z-DAILY_FILE -cl COFSVR_TEMP -bt 1438609177 -b cofsvrt1_1438609177 -st 0 -cj 1 -reqid -1438580893 -jm -brm -hostname cofsvrt1 -ru root -rclnt cofsvrt1 -rclnthostname cofsvrt1 -rl 0 -rp 604800 -sl full -ct 13 -maxfrag 524288 -eari 0 -mediasvr backupsvr02 -no_callback -connect_options 0x01010100 -jobid 12931 -jobgrpid 12931 -masterversion 760000 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_54696859_4240_5592 -blks_per_buffer 512
20:40:58.786 [5728.3232] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:40:58.786 [5728.3232] <2> job_connect: SO_KEEPALIVE set on socket 668 for client backupsvr
20:40:58.786 [5728.3232] <2> logconnections: BPJOBD CONNECT FROM 192.168.234.144.57338 TO 192.168.234.142.1556 fd = 668
20:40:58.786 [5728.3232] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
20:40:58.786 [5728.3232] <2> job_connect: Connected to the host backupsvr contype 53 jobid <12931> socket <668>
20:40:58.786 [5728.3232] <2> job_connect: Connected on port 57338
20:40:58.786 [5728.3232] <4> bptm: emmserver_name = backupsvr
20:40:58.786 [5728.3232] <4> bptm: emmserver_port = 1556
20:40:58.817 [5728.3232] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:40:58.817 [5728.3232] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -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:916)
20:40:58.817 [5728.3232] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:40:58.817 [5728.3232] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1562)
20:40:58.817 [5728.3232] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1571)
20:40:58.832 [5728.3232] <2> nbjm_media_request: Passing job control to NBJM, type WRITE/1
20:40:58.832 [5728.3232] <2> nbjm_media_request: old_media_id = , media_id = NULL
20:40:58.832 [5728.3232] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:40:58.832 [5728.3232] <2> Orb::init: Created anon service name: NB_5728_1500262627(Orb.cpp:795)
20:40:58.832 [5728.3232] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_5728_1500262627(Orb.cpp:805)
20:40:58.832 [5728.3232] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_5728_1500262627 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:916)
20:40:58.832 [5728.3232] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:41:03.567 [5728.3232] <2> RequestInitialResources: returning
20:41:03.567 [5728.3232] <2> parse_resource_strings: MEDIADB 1 3704 *NULL* 0 *NULL* 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
20:41:03.567 [5728.3232] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
20:41:03.567 [5728.3232] <2> parse_resource_strings: VOLUME 1 *NULL* 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0
20:41:03.567 [5728.3232] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
20:41:03.567 [5728.3232] <2> parse_resource_strings: DRIVE 3 *NULL* 0 *NULL* *NULL* 0 0 0 0 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 1 0 0
20:41:03.567 [5728.3232] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
20:41:03.567 [5728.3232] <2> parse_resource_strings: STORAGE 1 backupsvr02-disk-z-DAILY_FILE 0 524288 0 1 0 1 backupsvr02 backupsvr02 *NULL*
20:41:03.567 [5728.3232] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
20:41:03.567 [5728.3232] <2> parse_resource_strings: DISKGROUP 0 9 BasicDisk 11 backupsvr02 29 backupsvr02-disk-z-DAILY_FILE
20:41:03.567 [5728.3232] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
20:41:03.567 [5728.3232] <2> parse_resource_strings: DISKVOLUME 0 6 @aaaag 11 Internal_16 0
20:41:03.567 [5728.3232] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
20:41:03.567 [5728.3232] <2> parse_resource_strings: DISKMOUNTPOINT 0 26 Z:\nbu_disk_stu\DAILY_FILE
20:41:03.567 [5728.3232] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
20:41:03.567 [5728.3232] <2> nbjm_media_request: Job control returned to BPTM
20:41:03.567 [5728.3232] <2> io_init: bpbrm_handle = 1092, buffer address = 0x9e0000
20:41:03.567 [5728.3232] <2> io_init: found index: 0
20:41:03.567 [5728.3232] <2> read_legacy_touch_file: Found C:\Program Files\Veritas\NetBackup\db\config\SIZE_DATA_BUFFERS; requested from (miscsvr.c.528).
20:41:03.567 [5728.3232] <2> read_legacy_touch_file: 262144 read ; requested from (miscsvr.c.528).
20:41:03.567 [5728.3232] <2> io_init: using 262144 data buffer size
20:41:03.567 [5728.3232] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 400000
20:41:03.567 [5728.3232] <2> io_set_recvbuf: setting receive network buffer to 1049600 bytes
20:41:03.567 [5728.3232] <2> read_legacy_touch_file: Found C:\Program Files\Veritas\NetBackup\db\config\NUMBER_DATA_BUFFERS; requested from (common.c.3525).
20:41:03.567 [5728.3232] <2> read_legacy_touch_file: 64 read ; requested from (common.c.3525).
20:41:03.567 [5728.3232] <2> io_init: using 64 data buffers
20:41:03.567 [5728.3232] <2> io_init: child delay = 10, parent delay = 15 (milliseconds)
20:41:03.567 [5728.3232] <2> create_shared_memory: Created "Global\NetBackup Media Manager SHM Path 54698609 5728" shared memory file.
20:41:03.567 [5728.3232] <2> create_shared_memory: shm_size = 16778760, buffer address = 0x0000000001A10000, buf control = 0x0000000002A10000, ready ptr = 0x0000000002A10600
20:41:03.598 [5728.3232] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 21
20:41:03.614 [5728.3232] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:41:03.614 [5728.3232] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57361 TO 192.168.234.142.1556 fd = 1120
20:41:03.614 [5728.3232] <2> db_end: Need to collect reply
20:41:03.614 [5728.3232] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:41:03.629 [5728.3232] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:41:03.629 [5728.3232] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57362 TO 192.168.234.142.1556 fd = 1120
20:41:03.629 [5728.3232] <2> db_end: Need to collect reply
20:41:03.629 [5728.3232] <4> report_client: VBRC 2 5728 1 cofsvrt1_1438609177 13 COFSVR_TEMP 0 full 0 1 1
20:41:03.629 [5728.3232] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 81
20:41:03.645 [5728.3232] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:41:03.645 [5728.3232] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57363 TO 192.168.234.142.1556 fd = 1120
20:41:04.082 [5728.3232] <2> db_end: Need to collect reply
20:41:04.192 [5728.3232] <2> stu_name_to_monitor: job_id = 12931
20:41:04.192 [5728.3232] <2> stu_name_to_monitor: stuName = 'backupsvr02-disk-z-DAILY_FILE'
20:41:04.192 [5728.3232] <2> path_on_root: LSU Z:\nbu_disk_stu\DAILY_FILE is not a network share, continue processing
20:41:04.192 [5728.3232] <2> path_on_root: windows system volume is \\?\Volume{074e9e98-bf30-49fa-ba7f-8b8c58c50fa7}\
20:41:04.192 [5728.3232] <2> path_on_root: LSU Z:\nbu_disk_stu\DAILY_FILE volume name is \\?\Volume{23e05d63-bcc4-11e4-80bd-6eae8b552651}\
20:41:04.192 [5728.3232] <2> bp_sts_get_lsu: entry Z:\nbu_disk_stu\DAILY_FILE
20:41:04.192 [5728.3232] <2> construct_sts_isid: master_server backupsvr, client cofsvrt1, backup_time 1438609177, copy_number 1, stream_number 0, fragment_number 1, resume_number 0, spl_name NULL
20:41:04.192 [5728.3232] <2> bp_sts_open_image: STH set to STS_SA_IMAGE
20:41:04.192 [5728.3232] <2> io_open_disk: file cofsvrt1_1438609177_C1_F1 successfully opened
20:41:04.192 [5728.3232] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 77
20:41:04.223 [5728.3232] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:41:04.223 [5728.3232] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57365 TO 192.168.234.142.1556 fd = 1336
20:41:04.223 [5728.3232] <2> db_end: Need to collect reply
20:41:04.551 [5728.3232] <2> write_backup: backup child process is pid 3468.5812
20:41:04.551 [5728.3232] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:41:04.567 [5728.3232] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:41:04.567 [5728.3232] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57368 TO 192.168.234.142.1556 fd = 588
20:41:04.567 [5728.3232] <2> db_end: Need to collect reply
20:41:04.567 [5728.3232] <4> write_backup: begin writing backup id cofsvrt1_1438609177, copy 1, fragment 1, destination path Z:\nbu_disk_stu\DAILY_FILE
20:41:04.567 [5728.3232] <2> signal_parent: set bpbrm media ready event (pid = 4240)
20:41:04.567 [5728.3232] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 1 delay_brm: 0
20:41:04.567 [5728.3232] <2> write_data: Total Kbytes transferred 0
20:41:04.614 [3468.5812] <2> bptm: INITIATING (VERBOSE = 0): -w -pid 4240 -c cofsvrt1 -dpath Z:\nbu_disk_stu\DAILY_FILE -stunit backupsvr02-disk-z-DAILY_FILE -cl COFSVR_TEMP -bt 1438609177 -b cofsvrt1_1438609177 -st 0 -cj 1 -reqid -1438580893 -jm -brm -hostname cofsvrt1 -ru root -rclnt cofsvrt1 -rclnthostname cofsvrt1 -rl 0 -rp 604800 -sl full -ct 13 -maxfrag 524288 -eari 0 -mediasvr backupsvr02 -no_callback -connect_options 0x01010100 -jobid 12931 -jobgrpid 12931 -masterversion 760000 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_54696859_4240_5592 -blks_per_buffer 512 -mmfill 5728 0 262144 64 10 54698609 0 1438609177 0 COFSVR_TEMP cofsvrt1 cofsvrt1_1438609177
20:41:04.629 [3468.5812] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:41:04.629 [3468.5812] <2> job_connect: SO_KEEPALIVE set on socket 680 for client backupsvr
20:41:04.629 [3468.5812] <2> logconnections: BPJOBD CONNECT FROM 192.168.234.144.57369 TO 192.168.234.142.1556 fd = 680
20:41:04.629 [3468.5812] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
20:41:04.629 [3468.5812] <2> job_connect: Connected to the host backupsvr contype 53 jobid <12931> socket <680>
20:41:04.629 [3468.5812] <2> job_connect: Connected on port 57369
20:41:04.629 [3468.5812] <4> bptm: emmserver_name = backupsvr
20:41:04.629 [3468.5812] <4> bptm: emmserver_port = 1556
20:41:04.661 [3468.5812] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:41:04.661 [3468.5812] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -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:916)
20:41:04.661 [3468.5812] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:41:04.661 [3468.5812] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1562)
20:41:04.661 [3468.5812] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1571)
20:41:04.661 [3468.5812] <2> setup_mm_child: [5728] child using 64 data buffers
20:41:04.661 [3468.5812] <2> setup_mm_child: [5728] child buffer size is 262144
20:41:04.661 [3468.5812] <2> setup_mm_child: [5728] buffer address = 0x1670000, buf control = 0x2670000
20:41:13.145 [6024.5664] <2> bptm: INITIATING (VERBOSE = 0): -unload -dn IBM.ULT3580-HH6.002 -dp {5,0,0,0} -dk 2000133 -m VMD103 -mk 4000090 -mds 0 -alocid 3692 -jobid -1438580894 -jm
20:41:13.145 [6024.5664] <4> bptm: emmserver_name = backupsvr
20:41:13.145 [6024.5664] <4> bptm: emmserver_port = 1556
20:41:13.176 [6024.5664] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:41:13.176 [6024.5664] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -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:916)
20:41:13.176 [6024.5664] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:41:13.176 [6024.5664] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1562)
20:41:13.176 [6024.5664] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1571)
20:41:13.176 [6024.5664] <2> send_brm_msg: PID of bpxm = 6024
20:41:13.176 [6024.5664] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
20:41:13.176 [6024.5664] <2> nbjm_media_request: old_media_id = NULL, media_id = VMD103
20:41:13.176 [6024.5664] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:41:13.176 [6024.5664] <2> Orb::init: Created anon service name: NB_6024_1533899078(Orb.cpp:795)
20:41:13.176 [6024.5664] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_6024_1533899078(Orb.cpp:805)
20:41:13.176 [6024.5664] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_6024_1533899078 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:916)
20:41:13.176 [6024.5664] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:41:17.754 [6024.5664] <2> RequestInitialResources: returning
20:41:17.754 [6024.5664] <2> parse_resource_strings: MEDIADB 1 3692 VMD103 4000090 ------ 20 1438609040 0 0 0 0 0 0 22 7 0 0 0 0 0 0
20:41:17.754 [6024.5664] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
20:41:17.754 [6024.5664] <2> parse_resource_strings: VOLUME 1 VMD103 4000090 VMD103 DAILY_VM *NULL* *NULL* 24 8 0 9 0 {00000000-0000-0000-0000-000000000000} 0
20:41:17.754 [6024.5664] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
20:41:17.754 [6024.5664] <2> parse_resource_strings: DRIVE 3 IBM.ULT3580-HH6.002 2000133 10WT036579 {5,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
20:41:17.754 [6024.5664] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
20:41:17.754 [6024.5664] <2> parse_resource_strings: STORAGE 1 backupsvr02-hcart3-robot-tld-0 20 1048576 2 1 0 0 backupsvr02 backupsvr02 *NULL*
20:41:17.754 [6024.5664] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
20:41:17.754 [6024.5664] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
20:41:17.754 [6024.5664] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
20:41:17.754 [6024.5664] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
20:41:17.754 [6024.5664] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
20:41:17.754 [6024.5664] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
20:41:17.754 [6024.5664] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
20:41:17.754 [6024.5664] <2> nbjm_media_request: Job control returned to BPTM
20:41:17.754 [6024.5664] <2> drivename_open: Called with Create 1, file IBM.ULT3580-HH6.002
20:41:17.754 [6024.5664] <2> drivename_checklock: Called
20:41:17.754 [6024.5664] <2> drivename_lock: lock established
20:41:17.754 [6024.5664] <4> create_tpreq_file: {5,0,0,0}
20:41:17.754 [6024.5664] <2> drivename_write: Called with mode 2
20:41:17.754 [6024.5664] <2> drivename_unlock: unlocked
20:41:17.754 [6024.5664] <2> drivename_checklock: Called
20:41:17.754 [6024.5664] <2> drivename_lock: lock established
20:41:17.754 [6024.5664] <2> openNTDevice: config_path: {5,0,0,0}, serial_num: 10WT036579
20:41:17.754 [6024.5664] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh6#5&35d788dc&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
20:41:17.770 [6024.5664] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, drive serial number 10WT036579, expected serial number 10WT036579
20:41:17.770 [6024.5664] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
20:41:17.770 [6024.5664] <2> really_tpunmount: tpunmount'ing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-HH6.002
20:41:18.192 [6024.5664] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
20:42:28.223 [6024.5664] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:42:28.238 [6024.5664] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:42:28.238 [6024.5664] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57492 TO 192.168.234.142.1556 fd = 1092
20:42:28.238 [6024.5664] <2> db_end: Need to collect reply
20:42:28.254 [6024.5664] <4> report_resource_done: VBRD 1 6024 0 IBM.ULT3580-HH6.002 VMD103
20:42:28.254 [6024.5664] <2> openNTDevice: config_path: {5,0,0,0}, serial_num: 10WT036579
20:42:28.254 [6024.5664] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh6#5&35d788dc&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
20:42:28.270 [6024.5664] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, drive serial number 10WT036579, expected serial number 10WT036579
20:42:28.270 [6024.5664] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
20:42:28.270 [6024.5664] <2> tapealert_and_release: report_attr, fl1 0x00100001, fl2 0x00000000
20:42:28.270 [6024.5664] <2> tapealert_and_release: SCSI RELEASE
20:42:28.285 [6024.5664] <2> drivename_unlock: unlocked
20:42:28.285 [6024.5664] <2> drivename_close: Called for file IBM.ULT3580-HH6.002
20:42:28.285 [6024.5664] <2> drivename_remove: Called
20:42:28.285 [6024.5664] <2> main: Sending [EXIT STATUS 0] to NBJM
20:42:28.285 [6024.5664] <2> bptm: EXITING with status 0 <----------
20:42:31.832 [2964.3796] <2> bptm: INITIATING (VERBOSE = 0): -pid 4840 -den 20 -rt 8 -rn 0 -cj 4 -mpx 4 -reqid -1438580895 -jm -brm -p SQL_POOL -stunit backupsvr02-hcart3-robot-tld-0 -eari 0 -maxfrag 1048576 -masterversion 760000 -mediasvr backupsvr02 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_54791359_4840_3248 -blks_per_buffer 512
20:42:31.832 [2964.3796] <4> bptm: emmserver_name = backupsvr
20:42:31.832 [2964.3796] <4> bptm: emmserver_port = 1556
20:42:31.863 [2964.3796] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:42:31.863 [2964.3796] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -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:916)
20:42:31.863 [2964.3796] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:42:31.863 [2964.3796] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1562)
20:42:31.863 [2964.3796] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1571)
20:42:31.879 [2964.3796] <2> nbjm_media_request: Passing job control to NBJM, type WRITE/1
20:42:31.879 [2964.3796] <2> nbjm_media_request: old_media_id = , media_id = NULL
20:42:31.879 [2964.3796] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:42:31.879 [2964.3796] <2> Orb::init: Created anon service name: NB_2964_1718338736(Orb.cpp:795)
20:42:31.879 [2964.3796] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_2964_1718338736(Orb.cpp:805)
20:42:31.879 [2964.3796] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_2964_1718338736 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:916)
20:42:31.879 [2964.3796] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:42:36.395 [2964.3796] <2> Media_signal_poll: terminate event not found
20:42:36.395 [2964.3796] <2> Media_signal_poll: terminate event not found
20:42:36.395 [2964.3796] <2> Media_signal_poll: terminate event not found
20:42:36.410 [2964.3796] <2> RequestInitialResources: returning
20:42:36.410 [2964.3796] <2> parse_resource_strings: MEDIADB 1 3705 SQLD03 4000075 ------ 20 1437356723 1438570201 1439779801 0 9022472661 199 199 0 4 0 576 1024 0 35244506 0
20:42:36.410 [2964.3796] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
20:42:36.410 [2964.3796] <2> parse_resource_strings: VOLUME 1 SQLD03 4000075 SQLD03 SQL_POOL SONY S141012612 24 8 0 37 0 {00000000-0000-0000-0000-000000000000} 0
20:42:36.410 [2964.3796] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
20:42:36.410 [2964.3796] <2> parse_resource_strings: DRIVE 3 IBM.ULT3580-HH6.002 2000133 10WT036579 {5,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
20:42:36.410 [2964.3796] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
20:42:36.410 [2964.3796] <2> parse_resource_strings: STORAGE 1 backupsvr02-hcart3-robot-tld-0 20 1048576 2 1 0 0 backupsvr02 backupsvr02 *NULL*
20:42:36.410 [2964.3796] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
20:42:36.410 [2964.3796] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
20:42:36.410 [2964.3796] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
20:42:36.410 [2964.3796] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
20:42:36.410 [2964.3796] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
20:42:36.410 [2964.3796] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
20:42:36.410 [2964.3796] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
20:42:36.410 [2964.3796] <2> nbjm_media_request: Job control returned to BPTM
20:42:36.410 [2964.3796] <2> send_brm_msg: PID of bpxm = 2964
20:42:36.410 [2964.3796] <2> process_mpx_protocol: wait for initial START BACKUP message from bpbrm
20:42:38.426 [2964.3796] <2> read_brm_msg: START BACKUP -b vcodesvr_1438609273 -bt 1438609273 -c vcodesvr -cl VCODESVR_SQL -st 2 -rl 22 -rp 518400 -sl Default-Application-Backup -ct 15 -hostname vcodesvr -rclnt vcodesvr -rclnthostname vcodesvr -bclnt vcodesvr -bclnthostname vcodesvr -L /C/ProgramA Files/Veritas/NetBackup/Logs/user_ops/dbext/logs/4928.0.1438605891 -ru SYSTEM -no_callback -connect_options 0x01010100 -jobid 12915 -jobgrpid 12915
20:42:38.426 [2964.3796] <2> io_init: bpbrm_handle = 1076, buffer address = 0xf00000
20:42:38.426 [2964.3796] <2> io_init: found index: 0
20:42:38.426 [2964.3796] <2> read_legacy_touch_file: Found C:\Program Files\Veritas\NetBackup\db\config\SIZE_DATA_BUFFERS; requested from (miscsvr.c.496).
20:42:38.426 [2964.3796] <2> read_legacy_touch_file: 262144 read ; requested from (miscsvr.c.496).
20:42:38.426 [2964.3796] <2> io_init: using 262144 data buffer size
20:42:38.442 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:42:38.442 [2964.3796] <2> job_connect: SO_KEEPALIVE set on socket 1072 for client backupsvr
20:42:38.442 [2964.3796] <2> logconnections: BPJOBD CONNECT FROM 192.168.234.144.57551 TO 192.168.234.142.1556 fd = 1072
20:42:38.442 [2964.3796] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
20:42:38.442 [2964.3796] <2> job_connect: Connected to the host backupsvr contype 53 jobid <12915> socket <1072>
20:42:38.442 [2964.3796] <2> job_connect: Connected on port 57551
20:42:38.442 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 223
20:42:38.457 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:42:38.457 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57552 TO 192.168.234.142.1556 fd = 1084
20:42:38.457 [2964.3796] <2> db_CLIENTsend: reset client protocol version from 0 to 8
20:42:38.629 [2964.3796] <2> db_getCLIENT: db_CLIENTreceive: no entity was found 227
20:42:38.629 [2964.3796] <2> vnet_pbxConnect: ../../libvlibs/vnet_pbx.c.654: pbxSetAddrEx/pbxConnectEx return error 0:The operation completed successfully.
20:42:38.629 [2964.3796] <8> do_pbx_service: [vnet_connect.c:2085] vnet_pbxConnect() failed, status=18, errno=0, use_vnetd=0, cr->vcr_service=bpcd
20:42:38.629 [2964.3796] <8> async_connect: [vnet_connect.c:1677] do_service failed 18 0x12
20:42:38.660 [2964.3796] <8> vnet_vnetd_service_socket: [vnet_vnetd.c:1995] VN_REQUEST_SERVICE_SOCKET 6 0x6
20:42:38.660 [2964.3796] <8> vnet_vnetd_service_socket: [vnet_vnetd.c:2009] service bpcd
20:42:38.910 [2964.3796] <2> logconnections: BPCD CONNECT FROM 192.168.234.144.57554 TO 192.168.234.150.13724 fd = 1084
20:42:38.926 [2964.3796] <2> vnet_pbxConnect: ../../libvlibs/vnet_pbx.c.654: pbxSetAddrEx/pbxConnectEx return error 0:The operation completed successfully.
20:42:38.926 [2964.3796] <8> do_pbx_service: [vnet_connect.c:2085] vnet_pbxConnect() failed, status=18, errno=0, use_vnetd=1, cr->vcr_service=vnetd
20:42:38.926 [2964.3796] <8> async_connect: [vnet_connect.c:1677] do_service failed 18 0x12
20:42:38.942 [2964.3796] <8> do_vnetd_service: [vnet_connect.c:2042] connect VNETD CONNECT FROM 192.168.234.144.57556 TO 192.168.234.150.13724 fd = 1044
20:42:38.942 [2964.3796] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:440] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
20:42:39.129 [2964.3796] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:457] ipc_string 3944
20:42:40.645 [2964.3796] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 400000
20:42:40.645 [2964.3796] <2> read_legacy_touch_file: Found C:\Program Files\Veritas\NetBackup\db\config\NUMBER_DATA_BUFFERS; requested from (common.c.3525).
20:42:40.645 [2964.3796] <2> read_legacy_touch_file: 64 read ; requested from (common.c.3525).
20:42:40.645 [2964.3796] <2> io_init: using 64 data buffers
20:42:40.645 [2964.3796] <2> io_init: child delay = 10, parent delay = 15 (milliseconds)
20:42:40.645 [2964.3796] <2> process_start_msg: Setting mud from bp.conf
20:42:40.645 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 81
20:42:40.660 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:42:40.660 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57561 TO 192.168.234.142.1556 fd = 1044
20:42:41.004 [2964.3796] <2> db_end: Need to collect reply
20:42:41.051 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:42:41.051 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:42:41.051 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57566 TO 192.168.234.142.1556 fd = 1044
20:42:41.051 [2964.3796] <2> db_end: Need to collect reply
20:42:41.067 [2964.3796] <4> report_client: VBRC 2 2964 1 vcodesvr_1438609273 15 VCODESVR_SQL 2 Default-Application-Backup 0 1 1
20:42:41.067 [2964.3796] <2> mpx_setup_shm: Created "Global\NetBackup Media Manager SHM Path 54791671 2964" shared memory buffer file.
20:42:41.067 [2964.3796] <2> mpx_setup_shm: buffer control shared memory address is 0xf10000, size is 6176, handle is 1044
20:42:41.067 [2964.3796] <2> mpx_setup_shm: buf control for CINDEX 0 is 0000000000F10000
20:42:41.067 [2964.3796] <2> mpx_setup_shm: Created "Global\NetBackup Media Manager SHM MPX Path 54791671 2964 0" shared memory control file.
20:42:41.067 [2964.3796] <2> mpx_setup_shm: shared memory address for group 0 is 0x2080000, size is 67108864, handle is 1084
20:42:41.067 [2964.3796] <2> mpx_setup_shm: shared memory address for CINDEX 0 is 0000000002080000, group 0, num_active 1
20:42:41.067 [2964.3796] <2> vnet_pbxConnect: ../../libvlibs/vnet_pbx.c.654: pbxSetAddrEx/pbxConnectEx return error 0:The operation completed successfully.
20:42:41.067 [2964.3796] <8> do_pbx_service: [vnet_connect.c:2085] vnet_pbxConnect() failed, status=18, errno=0, use_vnetd=1, cr->vcr_service=vnetd
20:42:41.067 [2964.3796] <8> async_connect: [vnet_connect.c:1677] do_service failed 18 0x12
20:42:41.082 [2964.3796] <8> do_vnetd_service: [vnet_connect.c:2042] connect VNETD CONNECT FROM 192.168.234.144.57568 TO 192.168.234.150.13724 fd = 1068
20:42:41.082 [2964.3796] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:440] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
20:42:41.207 [2964.3796] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:457] ipc_string 3947
20:42:41.270 [2964.3796] <2> media_id_to_monitor: job_id = 12915, pDstMediaId = SQLD03
20:42:41.270 [2964.3796] <2> mpx_start_child: backup child for vcodesvr_1438609273 is pid 4708.4652, CINDEX = 0
20:42:41.270 [2964.3796] <2> send_brm_msg: NCB_DATASOCKET vcodesvr_1438609273 3947;2ed46b053b9f5c5490dc789e1a19f464;4;300
20:42:41.270 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 21
20:42:41.285 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:42:41.285 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57570 TO 192.168.234.142.1556 fd = 1068
20:42:41.285 [2964.3796] <2> db_end: Need to collect reply
20:42:41.285 [2964.3796] <2> drivename_open: Called with Create 1, file IBM.ULT3580-HH6.002
20:42:41.285 [2964.3796] <2> drivename_checklock: Called
20:42:41.285 [2964.3796] <2> drivename_lock: lock established
20:42:41.285 [2964.3796] <2> drivename_write: Called with mode 0
20:42:41.285 [2964.3796] <2> drivename_unlock: unlocked
20:42:41.285 [2964.3796] <2> drivename_checklock: Called
20:42:41.285 [2964.3796] <2> drivename_lock: lock established
20:42:41.285 [2964.3796] <2> db_byid: search for media id SQLD03
20:42:41.301 [2964.3796] <2> media_id_to_monitor: job_id = 12915, pDstMediaId = SQLD03
20:42:41.301 [2964.3796] <2> mount_open_media: Waiting for mount of media id SQLD03 (copy 1) on server backupsvr02.
20:42:41.301 [2964.3796] <2> openNTDevice: config_path: {5,0,0,0}, serial_num: 10WT036579
20:42:41.317 [2964.3796] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh6#5&35d788dc&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
20:42:41.317 [2964.3796] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, drive serial number 10WT036579, expected serial number 10WT036579
20:42:41.317 [2964.3796] <2> manage_drive_before_load: SCSI RESERVE
20:42:41.317 [2964.3796] <2> manage_drive_before_load: report_attr, fl1 0x00100001, fl2 0x00000000
20:42:41.317 [2964.3796] <2> manage_drive_before_load: write mode set to 1
20:42:41.332 [4708.4652] <2> bptm: INITIATING (VERBOSE = 0): -pid 4840 -den 20 -rt 8 -rn 0 -cj 4 -mpx 4 -reqid -1438580895 -jm -brm -p SQL_POOL -stunit backupsvr02-hcart3-robot-tld-0 -eari 0 -maxfrag 1048576 -masterversion 760000 -mediasvr backupsvr02 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_54791359_4840_3248 -blks_per_buffer 512 -b vcodesvr_1438609273 -cl VCODESVR_SQL -c vcodesvr -hostname vcodesvr -bclnt vcodesvr -bclnthostname vcodesvr -L /C/ProgramA Files/Veritas/NetBackup/Logs/user_ops/dbext/logs/4928.0.1438605891 -ru SYSTEM -rclnt vcodesvr -rclnthostname vcodesvr -sl Default-Application-Backup -mmfill 2964 0 262144 64 10 54791671 0 1438609273 2 VCODESVR_SQL vcodesvr vcodesvr_1438609273
20:42:41.332 [4708.4652] <4> bptm: emmserver_name = backupsvr
20:42:41.332 [4708.4652] <4> bptm: emmserver_port = 1556
20:42:41.363 [4708.4652] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:42:41.363 [4708.4652] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -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:916)
20:42:41.363 [4708.4652] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:42:41.363 [4708.4652] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1562)
20:42:41.363 [4708.4652] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1571)
20:42:41.363 [4708.4652] <2> setup_mm_child: [2964] child using 64 data buffers
20:42:41.363 [4708.4652] <2> setup_mm_child: [2964] child buffer size is 262144
20:42:41.363 [4708.4652] <2> setup_mm_child: [2964] buf control for CINDEX 0 is 0xf40000
20:42:41.363 [4708.4652] <2> setup_mm_child: [2964] shared memory address for group 0 is 0x1d10000, handle is 904
20:42:41.363 [4708.4652] <2> setup_mm_child: [2964] shared memory address for CINDEX 0 is 0x1d10000, group 0
20:42:41.551 [2964.3796] <2> tapelib: wait_for_ltid, Mount, timeout 0
20:42:41.551 [2964.3796] <2> Media_signal_poll: Read bpbrm message (D:\NB\7.6.1\src\mm\lib\tapelib.c:613)
20:42:41.551 [2964.3796] <2> process_brm_msg: no pending message from bpbrm
20:42:53.832 [4708.4652] <2> io_set_recvbuf: setting receive network buffer to 1049600 bytes
20:42:53.848 [4708.4652] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:42:53.848 [4708.4652] <2> job_connect: SO_KEEPALIVE set on socket 844 for client backupsvr
20:42:53.848 [4708.4652] <2> logconnections: BPJOBD CONNECT FROM 192.168.234.144.57643 TO 192.168.234.142.1556 fd = 844
20:42:53.848 [4708.4652] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
20:42:53.848 [4708.4652] <2> job_connect: Connected to the host backupsvr contype 53 jobid <12915> socket <844>
20:42:53.848 [4708.4652] <2> job_connect: Connected on port 57643
20:43:37.816 [2964.3796] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-HH6.002, serial_num: 10WT036579
20:43:37.816 [2964.3796] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh6#5&35d788dc&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
20:43:37.816 [2964.3796] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, drive serial number 10WT036579, expected serial number 10WT036579
20:43:37.832 [2964.3796] <2> init_tape: \\.\Tape2 (SCSI coordinates {5,0,0,0}) configured with blocksize 0
20:43:37.832 [2964.3796] <2> init_tape: \\.\Tape2 (SCSI coordinates {5,0,0,0}) has compression enabled
20:43:37.832 [2964.3796] <2> io_open: SCSI RESERVE
20:43:37.848 [2964.3796] <2> manage_drive_attributes: report_attr, fl1 0x00200049, fl2 0x0000000c
20:43:37.848 [2964.3796] <2> manage_drive_attributes: Matching medium manufacturer [SONY], sn [S141012612]
20:43:37.848 [2964.3796] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [7.6.1]
20:43:37.848 [2964.3796] <2> manage_drive_attributes: DateLabeled [201507200145], Barcode [SQLD03], Owninghost [backupsvr02]
20:43:37.848 [2964.3796] <2> manage_drive_attributes: MediaPool [SQL_POOL], MediaLabel [MEDIA=SQLD03;]
20:43:37.848 [2964.3796] <2> manage_drive_attributes: Media is protected with APPEND_ONLY
20:43:37.848 [2964.3796] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-HH6.002 successfully opened (mode 2)
20:43:37.848 [2964.3796] <2> write_backup: media id SQLD03 mounted on drive index 2, drivepath {5,0,0,0}, drivename IBM.ULT3580-HH6.002, copy 1
20:43:37.848 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:43:37.863 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:43:37.863 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57644 TO 192.168.234.142.1556 fd = 1124
20:43:37.863 [2964.3796] <2> db_end: Need to collect reply
20:43:37.863 [2964.3796] <4> report_throughput: VBRT 1 2964 1 1 IBM.ULT3580-HH6.002 SQLD03 0 1 0 0 0 (bptm.c.18469)
20:43:37.863 [2964.3796] <2> io_read_media_header: drive index 2, reading media header, buflen = 65536, buff = 0x00000000019E0460, copy 1
20:43:37.863 [2964.3796] <2> io_ioctl: command (5)MTREW 1 0x0 from (bptm.c.8312) on drive index 2
20:43:37.879 [2964.3796] <2> io_ioctl: command (1)MTFSF 1 0x0 from (bptm.c.8564) on drive index 2
20:43:37.895 [2964.3796] <2> io_position_for_write: position media id SQLD03, copy 1, current number images = 199
20:43:37.895 [2964.3796] <2> io_position_for_write: locating to absolute block number 35244506, copy 1
20:45:14.691 [2964.3796] <2> io_position_for_write: locate block is done
20:45:14.691 [2964.3796] <2> io_position_for_write: If header checks out, then overwrite it at LBA 35244505
20:45:15.723 [2964.3796] <2> io_position_for_write: processing empty header, filenum = 200, bid = (empty_file), copy 1
20:45:15.723 [2964.3796] <2> io_position_for_write: empty header found on SQLD03, OK, copy 1
20:45:15.723 [2964.3796] <2> io_ioctl: command (2)MTBSF 1 0x0 from (bptm.c.22802) on drive index 2
20:45:15.738 [2964.3796] <2> write_backup_position: Authorized data overwrite at LBA 35244505
20:45:15.738 [2964.3796] <2> io_ioctl: command (0)MTWEOF 1 0x0 from (bptm.c.22854) on drive index 2
20:45:21.113 [2964.3796] <2> send_MDS_msg: MEDIADB 1 3705 SQLD03 4000075 *NULL* 20 1437356723 1438609273 1439779801 0 9022472661 199 199 0 4 0 576 1024 0 35244506 0
20:45:21.144 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:45:21.160 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:45:21.160 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57701 TO 192.168.234.142.1556 fd = 1068
20:45:21.160 [2964.3796] <2> db_end: Need to collect reply
20:45:21.160 [2964.3796] <4> write_backup: begin writing backup id vcodesvr_1438609273, copy 1, fragment 1, to media id SQLD03 on drive IBM.ULT3580-HH6.002 (index 2)
20:45:21.160 [2964.3796] <2> process_brm_msg: no pending message from bpbrm
20:45:21.160 [2964.3796] <4> write_backup: waiting for client data or brm message
20:45:29.144 [2964.3796] <2> send_brm_msg: MEDIA READY
20:45:29.144 [2964.3796] <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
20:45:29.144 [2964.3796] <2> write_data: Total Kbytes transferred 0
20:45:29.144 [2964.3796] <2> write_data: absolute block position prior to writing backup header(s) is 35244506, copy 1
20:45:29.144 [2964.3796] <2> io_write_back_header: drive index 2, vcodesvr_1438609273, file num = 200, mpx_headers = 1, copy 1
20:45:29.144 [2964.3796] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1
20:45:29.144 [2964.3796] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0
20:45:29.144 [2964.3796] <2> write_data: received first buffer (262144 bytes), begin writing data
20:45:30.504 [4708.4652] <2> fill_buffer: [2964] socket is closed, waited for empty buffer 0 times, delayed 0 times, read 1867776 bytes
20:45:30.519 [2964.3796] <2> write_data: writing block shorter than BUFF_SIZE, 36864 bytes
20:45:30.519 [2964.3796] <2> write_data: writing short block, 36864 bytes, remainder 0
20:45:30.519 [2964.3796] <2> write_data: Total Kbytes transferred 1828
20:45:30.519 [2964.3796] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = 0
20:45:30.519 [2964.3796] <2> io_ioctl: command (0)MTWEOF 1 0x1 from (bptm.c.20632) on drive index 2
20:45:32.097 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:45:32.129 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:45:32.129 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57704 TO 192.168.234.142.1556 fd = 576
20:45:32.129 [2964.3796] <2> db_end: Need to collect reply
20:45:32.129 [2964.3796] <4> report_throughput: VBRT 1 2964 5 1 IBM.ULT3580-HH6.002 SQLD03 0 1 0 1828 1828 (bptm.c.20837)
20:45:32.129 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 77
20:45:32.144 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:45:32.144 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57705 TO 192.168.234.142.1556 fd = 576
20:45:32.144 [2964.3796] <2> db_end: Need to collect reply
20:45:32.488 [2964.3796] <2> send_MDS_msg: MEDIADB 1 3705 SQLD03 4000075 *NULL* 20 1437356723 1438609273 1439779801 0 9022474489 200 200 0 4 0 576 1024 0 35244506 0
20:45:32.504 [2964.3796] <2> send_brm_msg: MEDIA NOT READY
20:45:32.504 [2964.3796] <2> send_brm_msg: EXIT vcodesvr_1438609273 0
20:45:32.504 [2964.3796] <2> notify: executing - C:\Program Files\Veritas\NetBackup\bin\backup_notify.cmd bptm vcodesvr_1438609273
20:45:34.597 [2964.3796] <4> write_backup: detected brm message, type 2
20:45:34.597 [2964.3796] <2> io_terminate_tape: writing empty backup header, drive index 2, copy 1
20:45:34.597 [2964.3796] <2> io_ioctl: command (0)MTWEOF 0 0x1 from (bptm.c.8977) on drive index 2
20:45:34.597 [2964.3796] <2> io_terminate_tape: absolute block position prior to writing empty header is 35244516, copy 1
20:45:34.597 [2964.3796] <2> io_write_back_header: drive index 2, empty_file, file num = 201, mpx_headers = 0, copy 1
20:45:34.597 [2964.3796] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-HH6.002, from bptm.c.9092
20:45:34.597 [2964.3796] <2> io_terminate_tape: block position check: actual 35244516, expected 35244516
20:45:34.597 [2964.3796] <2> send_MDS_msg: MEDIADB 1 3705 SQLD03 4000075 *NULL* 20 1437356723 1438609273 1439779801 0 9022474489 200 200 0 4 0 576 1024 0 35244516 0
20:45:34.613 [2964.3796] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-HH6.002, serial_num: 10WT036579
20:45:34.613 [2964.3796] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh6#5&35d788dc&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
20:45:34.629 [2964.3796] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, drive serial number 10WT036579, expected serial number 10WT036579
20:45:34.629 [2964.3796] <2> init_tape: \\.\Tape2 (SCSI coordinates {5,0,0,0}) configured with blocksize 0
20:45:34.629 [2964.3796] <2> init_tape: \\.\Tape2 (SCSI coordinates {5,0,0,0}) has compression enabled
20:45:34.629 [2964.3796] <2> io_open: SCSI RESERVE
20:45:34.629 [2964.3796] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-HH6.002 successfully opened (mode 2)
20:45:34.941 [5820.2436] <2> bptm: INITIATING (VERBOSE = 0): -unload -dn IBM.ULT3580-HH6.002 -dp {5,0,0,0} -dk 2000133 -m SQLD03 -mk 4000075 -mds 0 -alocid 3705 -jobid -1438580896 -jm
20:45:34.941 [5820.2436] <4> bptm: emmserver_name = backupsvr
20:45:34.941 [5820.2436] <4> bptm: emmserver_port = 1556
20:45:34.972 [5820.2436] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:45:34.972 [5820.2436] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -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:916)
20:45:34.988 [5820.2436] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:45:34.988 [5820.2436] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1562)
20:45:34.988 [5820.2436] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1571)
20:45:34.988 [5820.2436] <2> send_brm_msg: PID of bpxm = 5820
20:45:34.988 [5820.2436] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
20:45:34.988 [5820.2436] <2> nbjm_media_request: old_media_id = NULL, media_id = SQLD03
20:45:34.988 [5820.2436] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:713)
20:45:34.988 [5820.2436] <2> Orb::init: Created anon service name: NB_5820_37397(Orb.cpp:795)
20:45:34.988 [5820.2436] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_5820_37397(Orb.cpp:805)
20:45:34.988 [5820.2436] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_5820_37397 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:916)
20:45:34.988 [5820.2436] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:930)
20:45:36.504 [2964.3796] <2> io_terminate_tape: locate block positioned tape to 35244516 in io_terminate_tape
20:45:36.504 [2964.3796] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-HH6.002, from bptm.c.9275
20:45:36.504 [2964.3796] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)
20:45:36.504 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:45:36.504 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:45:36.504 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57718 TO 192.168.234.142.1556 fd = 520
20:45:36.519 [2964.3796] <2> db_end: Need to collect reply
20:45:36.519 [2964.3796] <4> write_backup: successfully wrote backup id vcodesvr_1438609273, copy 1, 1828 Kbytes
20:45:36.519 [2964.3796] <2> bct_clear_active: removing group 0 handle 1084
20:45:36.519 [2964.3796] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0
20:45:36.519 [2964.3796] <2> write_backup_completion_stats: waited for full buffer 2 times, delayed 88 times
20:45:36.519 [2964.3796] <2> ConnectionCache::connectAndCache: Acquiring new connection for host backupsvr, query type 1
20:45:36.519 [2964.3796] <2> vnet_pbxConnect: pbxConnectEx Succeeded
20:45:36.519 [2964.3796] <2> logconnections: BPDBM CONNECT FROM 192.168.234.144.57719 TO 192.168.234.142.1556 fd = 1084
20:45:36.519 [2964.3796] <2> db_end: Need to collect reply
20:45:36.535 [2964.3796] <4> write_backup_completion_stats: successfully wrote 1 of 1 multiplexed backups, total Kbytes 1828 at 1329.455 Kbytes/sec
20:45:36.535 [2964.3796] <2> bptm: waiting for TERMINATE from bpbrm/IRM
20:45:36.535 [2964.3796] <4> read_brm_msg: Found pre-fetched BRM_MSG string
20:45:36.535 [2964.3796] <2> read_brm_msg: TERMINATE
20:45:36.535 [2964.3796] <2> updateEMM_freespace: updateEMM_freespace() (1 0)
20:45:36.535 [2964.3796] <2> bptm: Calling tpunmount for media SQLD03
20:45:36.535 [2964.3796] <2> drivename_write: Called with mode 1
20:45:36.535 [2964.3796] <2> drivename_unlock: unlocked
20:45:36.535 [2964.3796] <2> drivename_checklock: Called
20:45:36.535 [2964.3796] <2> drivename_lock: lock established
20:45:36.535 [2964.3796] <2> drivename_unlock: unlocked
20:45:36.535 [2964.3796] <2> drivename_close: Called for file IBM.ULT3580-HH6.002
20:45:36.535 [2964.3796] <2> send_MDS_msg: MEDIA_DONE 0 -1438580895 0 SQLD03 4000075 180 {4DB3441E-39E5-11E5-A4E4-5697BA7C0000}
20:45:36.535 [2964.3796] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 -1438580895 0 SQLD03 4000075 180 {4DB3441E-39E5-11E5-A4E4-5697BA7C0000})
20:45:36.535 [2964.3796] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid -1438580895 copyNum 0 mediaId SQLD03 mediaKey 4000075 unloadDelay 180 allocId {4DB3441E-39E5-11E5-A4E4-5697BA7C0000}
20:45:36.535 [2964.3796] <2> packageBptmResourceDoneMsg: returns 0
20:45:36.535 [2964.3796] <2> JobInst::sendIrmMsg: returning
20:45:36.535 [2964.3796] <2> send_MDS_msg: Error from sendIrmMsg, Master backupsvr, type 11, returned error 805
20:45:36.535 [2964.3796] <2> send_MDS_msg: NBJM returned an extended error status: invalid jobid (805)
20:45:36.535 [2964.3796] <2> bptm: EXITING with status 0 <----------
20:45:36.535 [2964.3796] <2> cleanup: Detached from BPBRM shared memory
20:45:39.566 [5820.2436] <2> RequestInitialResources: returning
20:45:39.566 [5820.2436] <2> parse_resource_strings: MEDIADB 1 3705 SQLD03 4000075 ------ 20 1437356723 1438570201 1439779801 0 9022472661 199 199 0 4 0 576 1024 0 35244506 0
20:45:39.566 [5820.2436] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
20:45:39.566 [5820.2436] <2> parse_resource_strings: VOLUME 1 SQLD03 4000075 SQLD03 SQL_POOL SONY S141012612 24 8 0 37 0 {00000000-0000-0000-0000-000000000000} 0
20:45:39.566 [5820.2436] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
20:45:39.566 [5820.2436] <2> parse_resource_strings: DRIVE 3 IBM.ULT3580-HH6.002 2000133 10WT036579 {5,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
20:45:39.566 [5820.2436] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
20:45:39.566 [5820.2436] <2> parse_resource_strings: STORAGE 1 backupsvr02-hcart3-robot-tld-0 20 1048576 2 1 0 0 backupsvr02 backupsvr02 *NULL*
20:45:39.566 [5820.2436] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
20:45:39.566 [5820.2436] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
20:45:39.566 [5820.2436] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
20:45:39.566 [5820.2436] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
20:45:39.566 [5820.2436] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
20:45:39.566 [5820.2436] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
20:45:39.566 [5820.2436] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
20:45:39.566 [5820.2436] <2> nbjm_media_request: Job control returned to BPTM
20:45:39.566 [5820.2436] <2> drivename_open: Called with Create 1, file IBM.ULT3580-HH6.002
20:45:39.566 [5820.2436] <2> drivename_checklock: Called
20:45:39.566 [5820.2436] <2> drivename_lock: lock established
20:45:39.566 [5820.2436] <4> create_tpreq_file: {5,0,0,0}
20:45:39.566 [5820.2436] <2> drivename_write: Called with mode 2
20:45:39.566 [5820.2436] <2> drivename_unlock: unlocked
20:45:39.566 [5820.2436] <2> drivename_checklock: Called
20:45:39.566 [5820.2436] <2> drivename_lock: lock established
20:45:39.566 [5820.2436] <2> openNTDevice: config_path: {5,0,0,0}, serial_num: 10WT036579
20:45:39.566 [5820.2436] <2> get_drive_path: SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-hh6#5&35d788dc&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
20:45:39.566 [5820.2436] <2> check_serial_num: serial number match for drive with SCSI coordinates {5,0,0,0}, dos_path \\.\Tape2, drive serial number 10WT036579, expected serial number 10WT036579
20:45:39.582 [5820.2436] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
20:45:39.582 [5820.2436] <2> really_tpunmount: tpunmount'ing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-HH6.002
20:45:40.207 [5820.2436] <2> tapelib: wait_for_ltid, UnMount, timeout 2400