Media server and client are in different subnet. There is firewall configured between 2 subnet but they allow any to any.
The backup speed using NBU is about 10 MB/sec. But if we test copy file between media server & client , the transfer rate is about 90 MB/sec.
did you extract time Netbackup used for creating snapshot(s) ?
8/3/2015 8:24:07 PM - Info bpbrm(pid=5444) Starting delete snapshot processing
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
Copying data between client and server cannot be compared with taking a backup where WOFB using VSS snapshot is required.
Seems snapshot alone took close to 5 minutes.
yes , I wonder why the vss snapshot took serveral minutes.
We installed SF with VCS on these clients. But the test data are on the local disk.
VSS is Microsoft's snapshot software.
Nothing to do with NBU, SF or VCS.
If you want to test without snapshot, go to Host Properties -> Master -> Client Attributes
Add/Select client name (identical to client name used in Policy).
In Windows Open File Backup tab, de-select 'Enable Windows Open File Backups'.
(This option is enabled by default.)
Please understand that in Production environment, VSS snapshots may be needed for WOFB.
Thank you . I will try.
I think I should unregister VxVss from VSS
What does 'vssadmin list providers' show on this server?
It all depends on which VSS provider is used by default.
Let us know how de-registering VxVss has worked for you and if Microsoft VSS is doing snapshots any faster...
I just disable Veritas Volume Snapshot provider in the services.msc.
By default if we do not disable the Veritas Volume Snapshot provider, the Veritas Volume Snapshot provider and MS VSS are both started when we take a backup.
See this TN:
How to configure NetBackup to choose a specific VSS Provider
http://www.symantec.com/docs/TECH156732
Thank you so much.
