Stopped running job, set bptm log level to 5, re-ran job. Ended up terminating the job as it was hanging. Start time = 17:21:23
17:20:48.805 [6492.4532] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=440
17:20:48.821 [6492.4532] <2> bptm: instance - 66066595
17:20:48.821 [6492.4532] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1359410557 -jm
17:20:48.821 [6492.4532] <2> bptm: Event Global\NetBackup Terminate Event, pid: 6492 created.
17:20:48.821 [6492.4532] <2> bptm: PORT_STATUS = 0x00000000
17:20:48.821 [6492.4532] <2> main: Sending [EXIT STATUS 0] to NBJM
17:20:48.821 [6492.4532] <2> bptm: EXITING with status 0 <----------
17:20:48.821 [6492.4532] <2> bptm: Global\NetBackup Terminate Event, pid: 6492 closed.
17:21:24.125 [6544.2888] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=440
17:21:24.125 [6544.2888] <2> bptm: instance - 66101898
17:21:24.125 [6544.2888] <2> bptm: INITIATING (VERBOSE = 5): -pid 7172 -den 6 -rt 0 -rn -1 -cj 1 -mpx 3 -reqid -1359410558 -jm -brm -p NetBackup -stunit V01-hcart -eari 0 -maxfrag 1048576 -masterversion 750000 -mediasvr V01 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_66101726_7172_5808 -blks_per_buffer 128
17:21:24.125 [6544.2888] <2> main: bptm.c.1591: maximum fragment size is 1048576000 Kbytes
17:21:24.125 [6544.2888] <2> bptm: PORT_STATUS = 0x00000000
17:21:24.125 [6544.2888] <8> vnet_same_host_and_update: [vnet_addrinfo.c:2820] name2 is empty 0 0x0
17:21:24.125 [6544.2888] <4> bptm: emmserver_name = V01
17:21:24.125 [6544.2888] <4> bptm: emmserver_port = 1556
17:21:24.140 [6544.2888] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)
17:21:24.140 [6544.2888] <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:825)
17:21:24.140 [6544.2888] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840)
17:21:24.140 [6544.2888] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1481)
17:21:24.140 [6544.2888] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1490)
17:21:24.156 [6544.2888] <2> nbjm_media_request: Passing job control to NBJM, type WRITE/1
17:21:24.156 [6544.2888] <2> nbjm_media_request: old_media_id = , media_id = NULL
17:21:24.156 [6544.2888] <2> RequestInitialResources: starting
17:21:24.156 [6544.2888] <2> RequestInitialResources: started
17:21:24.156 [6544.2888] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)
17:21:24.156 [6544.2888] <2> Orb::init: Created anon service name: NB_6544_75722027(Orb.cpp:697)
17:21:24.156 [6544.2888] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_6544_75722027(Orb.cpp:714)
17:21:24.156 [6544.2888] <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_6544_75722027 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:825)
17:21:24.156 [6544.2888] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840)
17:21:24.172 [6544.2888] <2> packageInitialResourceRequest: started
17:21:24.172 [6544.2888] <2> packageInitialResourceRequest: retVal = 0
17:21:24.172 [6544.2888] <2> RequestInitialResources: setting up callback and calling requestResources
17:21:24.172 [6544.2888] <2> logResourceReq: req.versionId : 1
17:21:24.172 [6544.2888] <2> logResourceReq: req.jobId : -1359410558
17:21:24.172 [6544.2888] <2> logResourceReq: req.startedViaJobManager : true
17:21:24.172 [6544.2888] <2> logResourceReq: req.consumer : true
17:21:24.172 [6544.2888] <2> logResourceReq: InitialSTUSelect -
17:21:24.172 [6544.2888] <2> logResourceReq: reqNum : 0
17:21:24.172 [6544.2888] <2> logResourceReq: preferredMediaServer :
17:21:24.172 [6544.2888] <2> logResourceReq: requiredMediaServer : V01
17:21:24.172 [6544.2888] <2> logResourceReq: storageUnit : V01-hcart
17:21:24.172 [6544.2888] <2> logResourceReq: mustBeNdmp : false
17:21:24.172 [6544.2888] <2> logResourceReq: getMaxFreeSpace : false
17:21:24.172 [6544.2888] <2> logResourceReq: mediaPool : NetBackup
17:21:24.172 [6544.2888] <2> logResourceReq: shareGroup :
17:21:24.172 [6544.2888] <2> logResourceReq: requestFlags : 0x0
17:21:24.172 [6544.2888] <2> logResourceReq: NDMPHostName :
17:21:24.172 [6544.2888] <2> logResourceReq: retentionLevel : 0
17:21:24.172 [6544.2888] <2> logResourceReq: mustUseLocalMediaServer : false
17:21:24.172 [6544.2888] <2> logResourceReq: failOnError : false
17:21:24.172 [6544.2888] <2> logResourceReq: mpxRequired : false
17:21:24.172 [6544.2888] <2> logResourceReq: client :
17:21:24.172 [6544.2888] <2> logResourceReq: usageType : 1
17:21:24.172 [6544.2888] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0
17:21:24.172 [6544.2888] <2> Media_signal_poll: terminate event not found
17:21:24.172 [6544.2888] <2> resourcesAvailable: m_allocationSeq.length() == 1
17:21:24.172 [6544.2888] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
17:21:24.172 [6544.2888] <2> resourcesAvailable: MEDIADB 1 1916 A00004 4000005 ------ 6 1317751200 1359469004 1391005004 0 1264389866 52 40 8 1 0 0 1024 0 19756224 0
17:21:24.172 [6544.2888] <2> resourcesAvailable: VOLUME 1 A00004 4000005 -------- NetBackup FUJIFILM 109P105325 6 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0
17:21:24.172 [6544.2888] <2> resourcesAvailable: DRIVE 3 IBM.ULTRIUM-HH4.000 2000002 1068003051 {2,0,3,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 1 0 1 0 0
17:21:24.172 [6544.2888] <2> resourcesAvailable: STORAGE 1 V01-hcart 6 1048576 2 1 0 0 V01 V01 *NULL*
17:21:24.172 [6544.2888] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
17:21:24.172 [6544.2888] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
17:21:24.172 [6544.2888] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
17:21:24.172 [6544.2888] <2> Media_signal_poll: terminate event not found
17:21:24.172 [6544.2888] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
17:21:24.172 [6544.2888] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
17:21:24.172 [6544.2888] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
17:21:24.172 [6544.2888] <2> packageInitialResourceRequestResult: matched MediaAllocation to an initialStuReq
17:21:24.172 [6544.2888] <2> packageInitialResourceRequestResult: retVal = 0
17:21:24.172 [6544.2888] <2> RequestInitialResources: retVal = 0 emmStatus = 0
17:21:24.172 [6544.2888] <2> RequestInitialResources: returning
17:21:24.172 [6544.2888] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 1916 A00004 4000005 ------ 6 1317751200 1359469004 1391005004 0 1264389866 52 40 8 1 0 0 1024 0 19756224 0], length 116
17:21:24.172 [6544.2888] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 A00004 4000005 -------- NetBackup FUJIFILM 109P105325 6 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0], length 113
17:21:24.172 [6544.2888] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 IBM.ULTRIUM-HH4.000 2000002 1068003051 {2,0,3,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 1 0 1 0 0], length 120
17:21:24.172 [6544.2888] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 V01-hcart 6 1048576 2 1 0 0 V01 V01 *NULL*], length 76
17:21:24.172 [6544.2888] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
17:21:24.172 [6544.2888] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
17:21:24.172 [6544.2888] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
17:21:24.172 [6544.2888] <2> populateBptmOpaqueStrings: retVal = 0
17:21:24.172 [6544.2888] <2> parse_resource_strings: MEDIADB 1 1916 A00004 4000005 ------ 6 1317751200 1359469004 1391005004 0 1264389866 52 40 8 1 0 0 1024 0 19756224 0
17:21:24.172 [6544.2888] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
17:21:24.172 [6544.2888] <2> parse_resource_strings: VOLUME 1 A00004 4000005 -------- NetBackup FUJIFILM 109P105325 6 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0
17:21:24.172 [6544.2888] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
17:21:24.172 [6544.2888] <2> parse_resource_strings: DRIVE 3 IBM.ULTRIUM-HH4.000 2000002 1068003051 {2,0,3,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 1 0 1 0 0
17:21:24.172 [6544.2888] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
17:21:24.172 [6544.2888] <2> parse_resource_strings: STORAGE 1 V01-hcart 6 1048576 2 1 0 0 V01 V01 *NULL*
17:21:24.172 [6544.2888] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
17:21:24.172 [6544.2888] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
17:21:24.172 [6544.2888] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
17:21:24.172 [6544.2888] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
17:21:24.172 [6544.2888] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
17:21:24.172 [6544.2888] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
17:21:24.172 [6544.2888] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
17:21:24.172 [6544.2888] <2> nbjm_media_request: Job control returned to BPTM
17:21:24.172 [6544.2888] <2> setup_twin_parameters: bptm.c.3957: maximum fragment size is 1048576000 Kbytes
17:21:24.172 [6544.2888] <2> send_brm_msg: PID of bpxm = 6544
17:21:24.172 [6544.2888] <2> NdmpAgentSession_initialize[0]: initializing all values
17:21:24.172 [6544.2888] <2> NdmpAgentSession_initialize[1]: initializing all values
17:21:24.172 [6544.2888] <2> NdmpAgentSession_initialize[2]: initializing all values
17:21:24.172 [6544.2888] <2> process_mpx_protocol: wait for initial START BACKUP message from bpbrm
17:21:24.172 [6544.2888] <2> mm_check_terminate_event: could not open terminate event, The system cannot find the file specified.
17:21:25.186 [6544.2888] <2> read_brm_msg: START BACKUP -b V01_1359476483 -bt 1359476483 -c V01 -cl V01_Full_Daily -st 0 -rl 8 -rp 31536000 -sl Full -ct 13 -hostname V01 -rclnt V01 -rclnthostname V01 -bclnt V01 -bclnthostname V01 -ru root -shm -no_callback -connect_options 0x01010100 -jobid 4443 -jobgrpid 4443
17:21:25.186 [6544.2888] <2> validate_parameters: common.c.5406: maximum fragment size is 1048576000 Kbytes
17:21:25.186 [6544.2888] <2> io_init: bpbrm_handle = 1028, buffer address = 0x350000
17:21:25.186 [6544.2888] <2> io_init: found index: 0
17:21:25.186 [6544.2888] <2> io_init: using 65536 data buffer size
17:21:25.201 [6544.2888] <2> vnet_pbxConnect: pbxConnectEx Succeeded
17:21:25.201 [6544.2888] <2> job_connect: SO_KEEPALIVE set on socket 1048 for client V01
17:21:25.201 [6544.2888] <2> logconnections: BPJOBD CONNECT FROM 10.58.24.146.50574 TO 10.58.24.146.1556 fd = 1048
17:21:25.201 [6544.2888] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
17:21:25.201 [6544.2888] <2> job_connect: Connected to the host V01 contype 53 jobid <4443> socket <1048>
17:21:25.201 [6544.2888] <2> job_connect: Connected on port 50574
17:21:25.201 [6544.2888] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 600000
17:21:25.201 [6544.2888] <2> io_init: using 12 data buffers
17:21:25.201 [6544.2888] <2> io_init: child delay = 10, parent delay = 15 (milliseconds)
17:21:25.201 [6544.2888] <2> ConnectionCache::connectAndCache: Acquiring new connection for host V01, query type 81
17:21:25.201 [6544.2888] <2> vnet_pbxConnect: pbxConnectEx Succeeded
17:21:25.201 [6544.2888] <2> logconnections: BPDBM CONNECT FROM 10.58.24.146.50575 TO 10.58.24.146.1556 fd = 1056
17:21:25.201 [6544.2888] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
17:21:25.373 [6544.2888] <2> db_end: Need to collect reply
17:21:25.388 [6544.2888] <4> report_client: VBRC 2 6544 1 V01_1359476483 13 V01_Full_Daily 0 Full 0 1 1
17:21:25.388 [6544.2888] <2> mpx_setup_shm: Created "Global\NetBackup Media Manager SHM Path 66101898 6544" shared memory buffer file.
17:21:25.388 [6544.2888] <2> mpx_setup_shm: buffer control shared memory address is 0x360000, size is 888, handle is 1060
17:21:25.388 [6544.2888] <2> mpx_setup_shm: buf control for CINDEX 0 is 0000000000360000
17:21:25.388 [6544.2888] <2> mpx_setup_shm: Created "Global\NetBackup Media Manager SHM MPX Path 66101898 6544 0" shared memory control file.
17:21:25.388 [6544.2888] <2> mpx_setup_shm: shared memory address for group 0 is 0x1f50000, size is 3145728, handle is 1056
17:21:25.388 [6544.2888] <2> mpx_setup_shm: shared memory address for CINDEX 0 is 0000000001F50000, group 0, num_active 1
17:21:25.388 [6544.2888] <2> setup_bpbkar_info: Global\NetBackup Media Manager SHM Info Path V01_1359476483 file successfully created
17:21:25.388 [6544.2888] <2> get_data_socket: mpx.c.4129: port_status: 16843008 16843008 0x01010100
17:21:25.388 [6544.2888] <2> get_data_socket: mpx.c.4130: use_local_sock_protocol: 1 1 0x00000001
17:21:25.388 [6544.2888] <2> get_data_socket: mpx.c.4133: client_hostname: V01
17:21:25.388 [6544.2888] <2> get_data_socket: mpx.c.4197: *port: 2192 2192 0x00000890
17:21:25.388 [6544.2888] <2> get_data_socket: mpx.c.4198: mpx_ipc:
17:21:25.388 [6544.2888] <2> media_id_to_monitor: job_id = 4443, pDstMediaId = A00004
17:21:25.388 [6544.2888] <2> mpx_start_child: mpx.c.1318: Calling: send_brm_msg(BRM_PORT)
17:21:25.388 [6544.2888] <2> send_brm_msg: DATASOCKET V01_1359476483 2192
17:21:25.388 [6544.2888] <2> mpx_start_child: mpx.c.1325: Calling: bpcr_get_socket_rqst2
17:21:25.388 [6544.2888] <2> mpx_start_child: mpx.c.1349: Calling: bpcr_wait_to_rqst4
17:21:26.106 [6544.2888] <2> mpx_start_child: mpx.c.1376: Calling: bpcr_get_socket_rqst4
17:21:26.106 [6544.2888] <2> LOCAL CLASS_ATT_DEFS: Product ID = 6
17:21:26.106 [6544.2888] <2> drivename_open: Called with Create 1, file IBM.ULTRIUM-HH4.000
17:21:26.106 [6544.2888] <2> drivename_checklock: Called
17:21:26.106 [6544.2888] <2> drivename_lock: lock established
17:21:26.106 [6544.2888] <2> drivename_write: Called with mode 0
17:21:26.106 [6544.2888] <2> drivename_unlock: unlocked
17:21:26.106 [6544.2888] <2> drivename_checklock: Called
17:21:26.106 [6544.2888] <2> drivename_lock: lock established
17:21:26.106 [6544.2888] <2> db_byid: search for media id A00004
17:21:26.106 [6544.2888] <2> media_id_to_monitor: job_id = 4443, pDstMediaId = A00004
17:21:26.106 [6544.2888] <2> mount_open_media: Waiting for mount of media id A00004 (copy 1) on server V01.
17:21:26.106 [6544.2888] <2> openNTDevice: config_path: {2,0,3,0}, serial_num: 1068003051
17:21:26.106 [6544.2888] <2> get_drive_path: SCSI coordinates {2,0,3,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ultrium-hh4#5&f8353e0&0&000300#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
17:21:26.106 [6544.2888] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,3,0}, dos_path \\.\Tape0, drive serial number 1068003051, expected serial number 1068003051
17:21:26.122 [6544.2888] <2> manage_drive_before_load: SCSI RESERVE
17:21:26.324 [6544.2888] <2> tapelib: wait_for_ltid, Mount, timeout 0
17:21:26.324 [6544.2888] <2> Media_signal_poll: Read bpbrm message (D:\NB\NB_7.5.0.4\src\mm\lib\tapelib.c:615)
17:21:26.324 [6544.2888] <2> process_brm_msg: no pending message from bpbrm
17:21:27.354 [6544.2888] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-HH4.000, serial_num: 1068003051
17:21:27.354 [6544.2888] <2> get_drive_path: SCSI coordinates {2,0,3,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ultrium-hh4#5&f8353e0&0&000300#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
17:21:27.354 [6544.2888] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,3,0}, dos_path \\.\Tape0, drive serial number 1068003051, expected serial number 1068003051
17:21:27.354 [6544.2888] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,3,0}) configured with blocksize 0
17:21:27.354 [6544.2888] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,3,0}) has compression enabled
17:21:27.370 [6544.2888] <2> io_open: SCSI RESERVE
17:21:27.370 [6544.2888] <2> manage_drive_attributes: report_attr, fl1 0x00030049, fl2 0x0000000c
17:21:27.370 [6544.2888] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [109P105325]
17:21:27.370 [6544.2888] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [7.0]
17:21:27.370 [6544.2888] <2> manage_drive_attributes: DateLabeled [201110041800], Barcode [--------], Owninghost [V01]
17:21:27.370 [6544.2888] <2> manage_drive_attributes: MediaPool [NetBackup], MediaLabel [MEDIA=A00004;]
17:21:27.385 [6544.2888] <2> manage_drive_attributes: encryption status: nexus scope 1, key scope 1
17:21:27.385 [6544.2888] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 1, key instance 38
17:21:27.385 [6544.2888] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-HH4.000 successfully opened (mode 2)
17:21:27.385 [6544.2888] <2> write_backup: media id A00004 mounted on drive index 0, drivepath {2,0,3,0}, drivename IBM.ULTRIUM-HH4.000, copy 1
17:21:27.385 [6544.2888] <4> report_throughput: VBRT 1 6544 1 1 IBM.ULTRIUM-HH4.000 A00004 0 1 0 0 0 (bptm.c.18225)
17:21:27.385 [6544.2888] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x0000000001C9B740, copy 1
17:21:27.385 [6544.2888] <2> io_ioctl: command (5)MTREW 1 0x0 from (bptm.c.8192) on drive index 0
17:21:27.401 [6544.2888] <2> io_ioctl: command (1)MTFSF 1 0x0 from (bptm.c.8444) on drive index 0
17:21:27.401 [6544.2888] <2> io_position_for_write: position media id A00004, copy 1, current number images = 52
17:21:27.401 [6544.2888] <2> io_position_for_write: locating to absolute block number 19756224, copy 1
17:21:40.724 [6544.2888] <2> io_position_for_write: locate block is done
17:21:42.018 [6544.2888] <2> io_position_for_write: processing empty header, filenum = 53, bid = (empty_file), copy 1
17:21:42.018 [6544.2888] <2> io_position_for_write: empty header found on A00004, OK, copy 1
17:21:42.018 [6544.2888] <2> io_ioctl: command (2)MTBSF 1 0x0 from (bptm.c.22419) on drive index 0
17:21:42.034 [6544.2888] <2> io_ioctl: command (0)MTWEOF 1 0x0 from (bptm.c.22471) on drive index 0
17:21:47.869 [6544.2888] <2> send_MDS_msg: MEDIADB 1 1916 A00004 4000005 *NULL* 6 1317751200 1359476483 1391012483 0 1264389866 52 40 8 1 0 0 1024 0 19756224 0
17:21:47.884 [6544.2888] <4> write_backup: begin writing backup id V01_1359476483, copy 1, fragment 1, to media id A00004 on drive IBM.ULTRIUM-HH4.000 (index 0)
17:21:47.884 [6544.2888] <2> process_brm_msg: no pending message from bpbrm
17:21:47.884 [6544.2888] <4> write_backup: waiting for client data or brm message
17:24:26.229 [7236.7064] <2> initialize: fd values STDOUTSOCK=7 STDERRSOCK=11
17:24:26.245 [7236.7064] <2> bptm: instance - 66284013
17:24:26.245 [7236.7064] <2> bptm: INITIATING (VERBOSE = 5): -delete_all_expired
17:24:26.245 [7236.7064] <2> bptm: Event Global\NetBackup Terminate Event, pid: 7236 created.
17:24:26.245 [7236.7064] <2> bptm: PORT_STATUS = 0x00000000
17:24:26.245 [7236.7064] <8> vnet_same_host_and_update: [vnet_addrinfo.c:2820] name2 is empty 0 0x0
17:24:26.245 [7236.7064] <4> bptm: emmserver_name = V01
17:24:26.245 [7236.7064] <4> bptm: emmserver_port = 1556
17:24:26.261 [7236.7064] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)
17:24:26.261 [7236.7064] <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:825)
17:24:26.261 [7236.7064] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840)
17:24:26.261 [7236.7064] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1481)
17:24:26.261 [7236.7064] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1490)
17:24:26.292 [7236.7064] <2> bptm: EXITING with status 0 <----------
17:24:26.292 [7236.7064] <2> bptm: Global\NetBackup Terminate Event, pid: 7236 closed.
17:26:33.654 [6544.2888] <2> mm_check_child_write: Received Message Pending Event from (bptm.c.18971)
17:26:33.654 [6544.2888] <2> read_brm_msg: STOP BACKUP V01_1359476483
17:26:33.654 [6544.2888] <2> io_terminate_tape: writing empty backup header, drive index 0, copy 1
17:26:33.654 [6544.2888] <2> io_terminate_tape: reposition to previous tapemark and rewrite header
17:26:33.654 [6544.2888] <2> io_ioctl: command (2)MTBSF 1 0x0 from (bptm.c.8757) on drive index 0
17:26:33.654 [6544.2888] <2> io_ioctl: command (0)MTWEOF 1 0x1 from (bptm.c.8839) on drive index 0
17:26:35.620 [6544.2888] <2> io_terminate_tape: absolute block position prior to writing empty header is 19756224, copy 1
17:26:35.620 [6544.2888] <2> io_write_back_header: drive index 0, empty_file, file num = 53, mpx_headers = 0, copy 1
17:26:35.635 [6544.2888] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-HH4.000, from bptm.c.8952
17:26:35.635 [6544.2888] <2> send_MDS_msg: MEDIADB 1 1916 A00004 4000005 *NULL* 6 1317751200 1359476483 1391012483 0 1264389866 52 40 8 1 0 0 1024 0 19756224 0
17:26:35.651 [6544.2888] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-HH4.000, serial_num: 1068003051
17:26:35.651 [6544.2888] <2> get_drive_path: SCSI coordinates {2,0,3,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ultrium-hh4#5&f8353e0&0&000300#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
17:26:35.651 [6544.2888] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,3,0}, dos_path \\.\Tape0, drive serial number 1068003051, expected serial number 1068003051
17:26:35.667 [6544.2888] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,3,0}) configured with blocksize 0
17:26:35.682 [6544.2888] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,3,0}) has compression enabled
17:26:35.682 [6544.2888] <2> io_open: SCSI RESERVE
17:26:35.682 [6544.2888] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-HH4.000 successfully opened (mode 2)
17:26:38.818 [6544.2888] <2> io_terminate_tape: locate block positioned tape to 19756224 in io_terminate_tape
17:26:38.818 [6544.2888] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-HH4.000, from bptm.c.9135
17:26:38.818 [6544.2888] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)
17:26:43.826 [6544.2888] <2> send_brm_msg: EXIT V01_1359476483 150
17:26:43.826 [6544.2888] <2> bct_clear_active: removing group 0 handle 1056
17:26:43.826 [6544.2888] <2> NdmpAgentSession_initialize[0]: initializing all values
17:26:43.826 [6544.2888] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0
17:26:43.826 [6544.2888] <2> write_backup_completion_stats: waited for full buffer 0 times, delayed 0 times
17:26:43.826 [6544.2888] <2> bptm: waiting for TERMINATE from bpbrm/IRM
17:26:53.326 [8104.2784] <2> initialize: fd values STDOUTSOCK=244 STDERRSOCK=440
17:26:53.342 [8104.2784] <2> bptm: instance - 66431106
17:26:53.342 [8104.2784] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn IBM.ULTRIUM-HH4.000 -dp {2,0,3,0} -dk 2000002 -m A00004 -mk 4000005 -mds 1 -alocid 1916 -jobid -1359410559 -jm
17:26:53.342 [8104.2784] <2> bptm: Event Global\NetBackup Terminate Event, pid: 8104 created.
17:26:53.342 [8104.2784] <2> bptm: PORT_STATUS = 0x00000000
17:26:53.342 [8104.2784] <8> vnet_same_host_and_update: [vnet_addrinfo.c:2820] name2 is empty 0 0x0
17:26:53.342 [8104.2784] <4> bptm: emmserver_name = V01
17:26:53.342 [8104.2784] <4> bptm: emmserver_port = 1556
17:26:53.358 [8104.2784] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)
17:26:53.358 [8104.2784] <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:825)
17:26:53.358 [8104.2784] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840)
17:26:53.358 [8104.2784] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1481)
17:26:53.358 [8104.2784] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1490)
17:26:53.358 [8104.2784] <2> send_brm_msg: PID of bpxm = 8104
17:26:53.358 [8104.2784] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
17:26:53.358 [8104.2784] <2> nbjm_media_request: old_media_id = NULL, media_id = A00004
17:26:53.373 [8104.2784] <2> RequestInitialResources: starting
17:26:53.373 [8104.2784] <2> RequestInitialResources: started
17:26:53.373 [8104.2784] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)
17:26:53.373 [8104.2784] <2> Orb::init: Created anon service name: NB_8104_693916554(Orb.cpp:697)
17:26:53.373 [8104.2784] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_8104_693916554(Orb.cpp:714)
17:26:53.373 [8104.2784] <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_8104_693916554 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:825)
17:26:53.373 [8104.2784] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840)
17:26:53.373 [8104.2784] <2> packageInitialResourceRequest: started
17:26:53.373 [8104.2784] <2> packageInitialResourceRequest: retVal = 0
17:26:53.373 [8104.2784] <2> RequestInitialResources: setting up callback and calling requestResources
17:26:53.373 [8104.2784] <2> logResourceReq: req.versionId : 1
17:26:53.373 [8104.2784] <2> logResourceReq: req.jobId : -1359410559
17:26:53.373 [8104.2784] <2> logResourceReq: req.startedViaJobManager : true
17:26:53.373 [8104.2784] <2> logResourceReq: req.consumer : true
17:26:53.373 [8104.2784] <2> logResourceReq: InitialMediaSelect -
17:26:53.373 [8104.2784] <2> logResourceReq: reqNum : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.mediaId : A00004
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.mediaKey : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.mediaServer : V01
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.userReservationId :
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.assignedTime : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.client :
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.usageType : 6
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.mustBeNdmp : false
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.driveName : IBM.ULTRIUM-HH4.000
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.drivePath :
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.mediaPool :
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.robotNumber : -1
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.slotNumber : -1
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.density : -1
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.ndmpControlHost :
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.failIfNoMedia : true
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.externalFile :
17:26:53.373 [8104.2784] <2> logMediaRequest: mreq.exp
17:26:53.373 [8104.2784] <2> logMediaRequest: mediaType : -1
17:26:53.373 [8104.2784] <2> logMediaRequest: mediaSubType : -1
17:26:53.373 [8104.2784] <2> logMediaRequest: exp.capabilities
17:26:53.373 [8104.2784] <2> logMediaRequest: isNdmp : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: isTirRestore : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: isFlashbackupRestore : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: isBlockMapRead : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: isCatalogBackup : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: isGcsCatalogBackup : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: preferVtlToDirectAttachedTape : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: isVMWare : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: isLifeCycle : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: useFt : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: failIfNoFt : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: isGranularExchange : 0
17:26:53.373 [8104.2784] <2> logMediaRequest: requestFlags : 0x0
17:26:53.373 [8104.2784] <2> logMediaRequest: NDMPHostName :
17:26:53.373 [8104.2784] <2> logMediaRequest: mediaServerAffinityID : 0
17:26:53.373 [8104.2784] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0
17:26:53.373 [8104.2784] <2> resourcesAvailable: m_allocationSeq.length() == 1
17:26:53.373 [8104.2784] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
17:26:53.373 [8104.2784] <2> resourcesAvailable: MEDIADB 1 1916 A00004 4000005 ------ 6 1317751200 1359469004 1391005004 0 1264389866 52 40 8 1 0 0 1024 0 19756224 0
17:26:53.373 [8104.2784] <2> resourcesAvailable: VOLUME 1 A00004 4000005 -------- NetBackup FUJIFILM 109P105325 6 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0
17:26:53.373 [8104.2784] <2> resourcesAvailable: DRIVE 3 IBM.ULTRIUM-HH4.000 2000002 1068003051 {2,0,3,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 1 0 1 0 0
17:26:53.373 [8104.2784] <2> resourcesAvailable: STORAGE 1 V01-hcart 6 1048576 2 1 0 0 V01 V01 *NULL*
17:26:53.373 [8104.2784] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
17:26:53.373 [8104.2784] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
17:26:53.373 [8104.2784] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
17:26:53.373 [8104.2784] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
17:26:53.373 [8104.2784] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
17:26:53.373 [8104.2784] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
17:26:53.373 [8104.2784] <2> packageInitialResourceRequestResult: matched MediaAllocation to a initialMediaSelect
17:26:53.373 [8104.2784] <2> packageInitialResourceRequestResult: retVal = 0
17:26:53.373 [8104.2784] <2> RequestInitialResources: retVal = 0 emmStatus = 0
17:26:53.373 [8104.2784] <2> RequestInitialResources: returning
17:26:53.373 [8104.2784] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 1916 A00004 4000005 ------ 6 1317751200 1359469004 1391005004 0 1264389866 52 40 8 1 0 0 1024 0 19756224 0], length 116
17:26:53.373 [8104.2784] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 A00004 4000005 -------- NetBackup FUJIFILM 109P105325 6 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0], length 113
17:26:53.373 [8104.2784] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 IBM.ULTRIUM-HH4.000 2000002 1068003051 {2,0,3,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 1 0 1 0 0], length 120
17:26:53.373 [8104.2784] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 V01-hcart 6 1048576 2 1 0 0 V01 V01 *NULL*], length 76
17:26:53.373 [8104.2784] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
17:26:53.373 [8104.2784] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
17:26:53.373 [8104.2784] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
17:26:53.373 [8104.2784] <2> populateBptmOpaqueStrings: retVal = 0
17:26:53.373 [8104.2784] <2> parse_resource_strings: MEDIADB 1 1916 A00004 4000005 ------ 6 1317751200 1359469004 1391005004 0 1264389866 52 40 8 1 0 0 1024 0 19756224 0
17:26:53.373 [8104.2784] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
17:26:53.373 [8104.2784] <2> parse_resource_strings: VOLUME 1 A00004 4000005 -------- NetBackup FUJIFILM 109P105325 6 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0
17:26:53.373 [8104.2784] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
17:26:53.373 [8104.2784] <2> parse_resource_strings: DRIVE 3 IBM.ULTRIUM-HH4.000 2000002 1068003051 {2,0,3,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 1 0 1 0 0
17:26:53.373 [8104.2784] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
17:26:53.373 [8104.2784] <2> parse_resource_strings: STORAGE 1 V01-hcart 6 1048576 2 1 0 0 V01 V01 *NULL*
17:26:53.373 [8104.2784] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
17:26:53.373 [8104.2784] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
17:26:53.373 [8104.2784] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
17:26:53.373 [8104.2784] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
17:26:53.373 [8104.2784] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
17:26:53.373 [8104.2784] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
17:26:53.373 [8104.2784] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
17:26:53.373 [8104.2784] <2> nbjm_media_request: Job control returned to BPTM
17:26:53.373 [8104.2784] <2> drivename_open: Called with Create 1, file IBM.ULTRIUM-HH4.000
17:26:53.373 [8104.2784] <2> drivename_checklock: Called
17:26:53.373 [8104.2784] <2> drivename_checklock: File is locked
17:26:53.373 [8104.2784] <2> drivename_lock: lock failed (already locked)
17:26:53.373 [8104.2784] <2> drivename_close: Called for file IBM.ULTRIUM-HH4.000
17:26:54.387 [8104.2784] <2> drivename_open: Called with Create 1, file IBM.ULTRIUM-HH4.000
17:26:54.387 [8104.2784] <2> drivename_checklock: Called
17:26:54.387 [8104.2784] <2> drivename_checklock: File is locked
17:26:54.387 [8104.2784] <2> drivename_lock: lock failed (already locked)
17:26:54.387 [8104.2784] <2> drivename_close: Called for file IBM.ULTRIUM-HH4.000
17:26:55.401 [8104.2784] <2> drivename_open: Called with Create 1, file IBM.ULTRIUM-HH4.000
17:26:55.401 [8104.2784] <2> drivename_checklock: Called
17:26:55.401 [8104.2784] <2> drivename_checklock: File is locked
17:26:55.401 [8104.2784] <2> drivename_lock: lock failed (already locked)
17:26:55.401 [8104.2784] <2> drivename_close: Called for file IBM.ULTRIUM-HH4.000
17:26:55.901 [6544.2888] <2> read_brm_msg: TERMINATE
17:26:55.901 [6544.2888] <2> updateEMM_freespace: updateEMM_freespace() (1 0)
17:26:55.901 [6544.2888] <2> bptm: EXITING with status 0 <----------
17:26:55.901 [6544.2888] <2> cleanup: Detached from BPBRM shared memory
17:26:56.415 [8104.2784] <2> drivename_open: Called with Create 1, file IBM.ULTRIUM-HH4.000
17:26:56.415 [8104.2784] <2> drivename_checklock: Called
17:26:56.415 [8104.2784] <2> drivename_lock: lock established
17:26:56.415 [8104.2784] <4> create_tpreq_file: {2,0,3,0}
17:26:56.415 [8104.2784] <2> drivename_write: Called with mode 2
17:26:56.415 [8104.2784] <2> drivename_unlock: unlocked
17:26:56.415 [8104.2784] <2> drivename_checklock: Called
17:26:56.415 [8104.2784] <2> drivename_lock: lock established
17:26:56.415 [8104.2784] <2> openNTDevice: config_path: {2,0,3,0}, serial_num: 1068003051
17:26:56.415 [8104.2784] <2> get_drive_path: SCSI coordinates {2,0,3,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ultrium-hh4#5&f8353e0&0&000300#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
17:26:56.415 [8104.2784] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,3,0}, dos_path \\.\Tape0, drive serial number 1068003051, expected serial number 1068003051
17:26:56.415 [8104.2784] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
17:26:56.415 [8104.2784] <2> tapealert_and_release: SCSI RELEASE
17:26:56.415 [8104.2784] <2> really_tpunmount: tpunmount'ing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-HH4.000