Restore Incomplete

If anyone has an idea how to fix my restore I would greatly apprciate it.  I'm using NB 7.0 and windows server 2008, it's a stand alone server, I'm only backing up locally. I cannot restore data, below is the bptm log and activity monitor detailed status,

6/6/2012 9:17:41 AM - restored image z02rsiciu01_1338951600 - (the restore failed to recover the requested files(5)); restore time 00:01:52
6/6/2012 9:17:41 AM - Warning bprd(pid=1836) Restore must be resumed prior to first image expiration on 6/12/2012 10:00:00 PM
6/6/2012 9:17:41 AM - end Restore; elapsed time: 00:01:56
the restore failed to recover the requested files(5)

09:15:49.925 [6408.1792] <2> bptm: instance - 77376386
09:15:49.925 [6408.1792] <2> bptm: INITIATING (VERBOSE = 5): -pid 7432 -mpx_restore -S z02rsiciu01 -mud 180
09:15:49.925 [6408.1792] <2> bptm: Event NetBackup Terminate Event, pid: 6408 created.
09:15:49.925 [6408.1792] <2> bptm: PORT_STATUS = 0x00000000
09:15:49.925 [6408.1792] <2> hosts_equal: The second name is empty
09:15:49.925 [6408.1792] <2> hosts_equal: Comparing hosts <z02rsiciu01> and <z02rsiciu01>
09:15:49.925 [6408.1792] <2> hosts_equal: names are the same
09:15:49.925 [6408.1792] <2> hosts_equal: Comparing hosts <z02rsiciu01> and <z02rsiciu01>
09:15:49.925 [6408.1792] <2> hosts_equal: names are the same
09:15:49.925 [6408.1792] <4> bptm: emmserver_name = z02rsiciu01
09:15:49.925 [6408.1792] <4> bptm: emmserver_port = 1556
09:15:49.941 [6408.1792] <2> dbstunitq@VssSetLogLevel:  ++++ ENTERING ++++
09:15:49.941 [6408.1792] <4> dbstunitq@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:15:49.941 [6408.1792] <2> dbstunitq@VssSetLogLevel:  ---- EXITING ----
09:15:49.956 [6408.1792] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:741)
09:15:49.956 [6408.1792] <2> dbstunitq@VssSetLogLevel:  ++++ ENTERING ++++
09:15:49.956 [6408.1792] <4> dbstunitq@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:15:49.956 [6408.1792] <2> dbstunitq@VssSetLogLevel:  ---- EXITING ----
09:15:49.956 [6408.1792] <2> EndpointSelector::select_endpoint: performing call with the only endpt available!(Endpoint_Selector.cpp:437)
09:15:49.956 [6408.1792] <2> send_brm_msg: PID of bpxm = 6408
09:15:49.956 [6408.1792] <2> process_mpx_protocol: wait for initial START RESTORE message from bpbrm
09:15:50.970 [6408.1792] <2> read_brm_msg: START RESTORE -b z02rsiciu01_1338951600 -bt 1338951600 -c z02rsiciu01 -cl CHI_CIU_Daily -st 0 -ct 13 -firstblk 286926350 -flport 0 -flipc 11404 -restoreid 3881.001 -cn 1 -hostname z02rsiciu01.irmnet.ds2.dhs.gov -rclnt z02rsiciu01 -rclnthostname z02rsiciu01.irmnet.ds2.dhs.gov -L /C/Program��Files/Veritas/NetBackup/logs/user_ops/zzdnb000/logs/NBWIN009 -ru root -lcmsg en -lctime en -no_callback -connect_options 0x01010100 -jobid 3881 -shm
09:15:50.970 [6408.1792] <2> ConnectionCache::connectAndCache: Acquiring new connection for host z02rsiciu01, query type 81
09:15:50.970 [6408.1792] <2> init_cache: ../../libvlibs/vnet_hosts.c.1046: host_cache_size: 200 0x000000c8
09:15:50.970 [6408.1792] <2> init_cache: ../../libvlibs/vnet_hosts.c.1047: cache_time: 3600 0x00000e10
09:15:50.970 [6408.1792] <2> init_cache: ../../libvlibs/vnet_hosts.c.1061: host_failed_cache_size: 40 0x00000028
09:15:50.970 [6408.1792] <2> init_cache: ../../libvlibs/vnet_hosts.c.1062: cache_time: 3600 0x00000e10
09:15:50.970 [6408.1792] <2> init_cache: ../../libvlibs/vnet_hosts.c.1046: host_cache_size: 200 0x000000c8
09:15:50.970 [6408.1792] <2> init_cache: ../../libvlibs/vnet_hosts.c.1047: cache_time: 3600 0x00000e10
09:15:50.970 [6408.1792] <2> init_cache: ../../libvlibs/vnet_hosts.c.1061: host_failed_cache_size: 40 0x00000028
09:15:50.970 [6408.1792] <2> init_cache: ../../libvlibs/vnet_hosts.c.1062: cache_time: 3600 0x00000e10
09:15:50.970 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4052: connect in progress: 0 0x00000000
09:15:51.017 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
09:15:51.017 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpdbm
09:15:51.017 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4238: in progress connect: 0 0x00000000
09:15:51.017 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4241: connect: async CONNECT FROM 10.135.159.133.11452 TO 10.135.159.133.13724 fd = 1004
09:15:51.017 [6408.1792] <2> logconnections: BPDBM CONNECT FROM 10.135.159.133.11452 TO 10.135.159.133.13724
09:15:51.017 [6408.1792] <2> dbstunitq@VssSetLogLevel:  ++++ ENTERING ++++
09:15:51.017 [6408.1792] <4> dbstunitq@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:15:51.017 [6408.1792] <2> dbstunitq@VssSetLogLevel:  ---- EXITING ----
09:15:51.017 [6408.1792] <2> vnet_check_vxss_client_magic_with_info: ../../libvlibs/vnet_vxss_helper.c.878: Ignoring VxSS authentication: 2 0x00000002
09:15:51.126 [6408.1792] <2> db_end: Need to collect reply
09:15:51.126 [6408.1792] <2> mpx_read_init: image is not multiplexed
09:15:51.126 [6408.1792] <2> log_frag_info: frag 1 file 5 of 0002L4 has blocks 0 to 328006135 for z02rsiciu01_1338951600
09:15:51.126 [6408.1792] <2> mpx_read_init: media id 0002L4, copy 1, fragment 1 (164003068 Kbytes) filenum 5 being considered for restore
09:15:51.126 [6408.1792] <2> mpx_compute_skip_info: will skip to block 2241612 of fragment 1 to start restore, remain = 14, bytes_to_skip = 7168
09:15:51.126 [6408.1792] <2> mpx_compute_skip_info: changed Kbytes_left to 20539900
09:15:51.126 [6408.1792] <2> mpx_read_init: filenumber for new restore is 5, Mpx_Filenum is -1
09:15:51.126 [6408.1792] <4> report_client: VBRC 2 6408 0 z02rsiciu01_1338951600 13 CHI_CIU_Daily 0 *NULL* 0 1 1
09:15:51.126 [6408.1792] <2> mpx_setup_restore_shm: using 30 data buffers, buffer size is 65536
09:15:51.126 [6408.1792] <2> mpx_setup_restore_shm: child delay = 10, parent delay = 15 (milliseconds)
09:15:51.126 [6408.1792] <2> mpx_setup_restore_shm: shm_size = 1968600, buffer address = 0000000002FF0000, buf control = 00000000031D0000, ready ptr = 00000000031D02D0, res_cntl = 00000000031D02D8
09:15:51.126 [6408.1792] <2> setup_tar_info: Min_records before frag switch is 90000, locate available = 1
09:15:51.126 [6408.1792] <2> setup_tar_info: Global\NetBackup Media Manager SHM Info Path 3881.001 file successfully created
09:15:51.142 [6408.1792] <2> LOCAL CLASS_ATT_DEFS: Product ID = 6
09:15:51.142 [6408.1792] <2> append_to_client_log: h:\70\src\nb\dblib\dbmisc.c.3358: about to call ConnectToBPCD connect_opts = 0xffffffff
09:15:51.142 [6408.1792] <2> ConnectToBPCD: db_getCLIENT(z02rsiciu01) failed: 227
09:15:51.142 [6408.1792] <2> hosts_equal: Comparing hosts <z02rsiciu01> and <z02rsiciu01.irmnet.ds2.dhs.gov>
09:15:51.142 [6408.1792] <2> hosts_equal: host1 z02rsiciu01 z02rsiciu01.irmnet.ds2.dhs.gov addr 10.135.159.133 (0x859f870a)
09:15:51.142 [6408.1792] <2> hosts_equal: host2 z02rsiciu01.irmnet.ds2.dhs.gov z02rsiciu01.irmnet.ds2.dhs.gov addr 10.135.159.133 (0x859f870a)
09:15:51.142 [6408.1792] <2> hosts_equal: hostnames DO compare (1)
09:15:51.142 [6408.1792] <2> local_bpcr_connect: bpcr.c.276: connect_opts = 0x01000100 connect_opts2 = 0x01000100
09:15:51.142 [6408.1792] <2> local_bpcr_connect: bpcr.c.283: connect_opts = 0x01000100
09:15:51.142 [6408.1792] <2> local_bpcr_connect: bpcr.c.322: daemon_port_type = 0
09:15:51.142 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4052: connect in progress: 0 0x00000000
09:15:51.189 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
09:15:51.189 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpcd
09:15:51.204 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4238: in progress connect: 0 0x00000000
09:15:51.204 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4241: connect: async CONNECT FROM 10.135.159.133.11458 TO 10.135.159.133.13724 fd = 1012
09:15:51.204 [6408.1792] <2> logconnections: BPCD CONNECT FROM 10.135.159.133.11458 TO 10.135.159.133.13724
09:15:51.204 [6408.1792] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.188: msg: VNETD CONNECT FROM 10.135.159.133.11459 TO 10.135.159.133.13724 fd = 1020
09:15:51.251 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.541: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
09:15:51.251 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.558: ipc_string: 11460
09:15:51.251 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.569: hash_str1: aa4341bb5243f2a1c22db5bf4b58afed
09:15:51.313 [6408.1792] <2> nbjm_media_request: Passing job control to NBJM, type READ/2
09:15:51.313 [6408.1792] <2> nbjm_media_request: old_media_id = , media_id = 0002L4
09:15:51.313 [6408.1792] <2> RequestInitialResources: starting
09:15:51.313 [6408.1792] <2> RequestInitialResources: started
09:15:51.313 [6408.1792] <2> Unknown@VssSetLogLevel:  ++++ ENTERING ++++
09:15:51.313 [6408.1792] <4> Unknown@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:15:51.313 [6408.1792] <2> Unknown@VssSetLogLevel:  ---- EXITING ----
09:15:51.313 [6408.1792] <2> Orb::init: Created anon service name: NB_6408_513347914(Orb.cpp:612)
09:15:51.313 [6408.1792] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_6408_513347914(Orb.cpp:630)
09:15:51.313 [6408.1792] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_6408_513347914 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:741)
09:15:51.313 [6408.1792] <2> NB_6408_513347914@VssSetLogLevel:  ++++ ENTERING ++++
09:15:51.313 [6408.1792] <4> NB_6408_513347914@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:15:51.313 [6408.1792] <2> NB_6408_513347914@VssSetLogLevel:  ---- EXITING ----
09:15:51.313 [6408.1792] <2> EndpointSelector::select_endpoint: performing call with the only endpt available!(Endpoint_Selector.cpp:437)
09:15:51.313 [6408.1792] <2> packageInitialResourceRequest: started
09:15:51.313 [6408.1792] <2> packageInitialResourceRequest: retVal = 0
09:15:51.313 [6408.1792] <2> RequestInitialResources: setting up callback and calling requestResources
09:15:51.329 [6408.1792] <2> logResourceReq: req.versionId : 1
09:15:51.329 [6408.1792] <2> logResourceReq: req.jobId : 3881
09:15:51.329 [6408.1792] <2> logResourceReq: req.startedViaJobManager : false
09:15:51.329 [6408.1792] <2> logResourceReq: req.consumer : true
09:15:51.329 [6408.1792] <2> logResourceReq: InitialMediaSelect -
09:15:51.329 [6408.1792] <2> logResourceReq:  reqNum : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.mediaId : 0002L4
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.mediaKey : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.mediaServer : z02rsiciu01
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.userReservationId :
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.assignedTime : 1338433200
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.client : z02rsiciu01
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.usageType : 2
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.mustBeNdmp : false
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.driveName :
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.drivePath :
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.mediaPool :
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.robotNumber : -1
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.slotNumber : -1
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.density : -1
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.ndmpControlHost :
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.failIfNoMedia : true
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.externalFile :
09:15:51.329 [6408.1792] <2> logMediaRequest:  mreq.exp
09:15:51.329 [6408.1792] <2> logMediaRequest:       mediaType : 2
09:15:51.329 [6408.1792] <2> logMediaRequest:       mediaSubType : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:  exp.capabilities
09:15:51.329 [6408.1792] <2> logMediaRequest:          isNdmp : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:          isTirRestore : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:          isFlashbackupRestore : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:          isBlockMapRead : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:          isCatalogBackup : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:          isGcsCatalogBackup : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:          preferVtlToDirectAttachedTape : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:          isVMWare : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:          isLifeCycle : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:     useFt : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:     failIfNoFt : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:     isGranularExchange : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:     requestFlags : 0
09:15:51.329 [6408.1792] <2> logMediaRequest:  mediaServerAffinityID : 0
09:15:51.329 [6408.1792] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0
09:15:51.360 [6408.1792] <2> resourcesAvailable: m_allocationSeq.length() == 1
09:15:51.360 [6408.1792] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
09:15:51.360 [6408.1792] <2> resourcesAvailable: MEDIADB 1 1040 0002L4 4000002 ------ 6 1338433200 1338989867 1339594667 1338991268 819924372 5 5 0 9 10 0 1024 0 12811333 0
09:15:51.360 [6408.1792] <2> resourcesAvailable: VOLUME 1 0002L4 4000002 000002L4 CIU_Daily FUJIFILM AA2TC9LJP3 6 8 0 2 0 {00000000-0000-0000-0000-000000000000} 0
09:15:51.360 [6408.1792] <2> resourcesAvailable: DRIVE 3 IBM.ULT3580-TD4.000 2000004 1310229502 {2,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
09:15:51.360 [6408.1792] <2> resourcesAvailable: STORAGE 1 *NULL* 0 0 0 0 0 0 z02rsiciu01 z02rsiciu01 *NULL*
09:15:51.360 [6408.1792] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
09:15:51.360 [6408.1792] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
09:15:51.360 [6408.1792] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
09:15:53.341 [6408.1792] <2> Media_signal_poll: Read bpbrm message (MultiResReq.cpp:2251)
09:15:53.341 [6408.1792] <2> process_brm_msg: no pending message from bpbrm
09:15:53.341 [6408.1792] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
09:15:53.341 [6408.1792] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
09:15:53.341 [6408.1792] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
09:15:53.341 [6408.1792] <2> packageInitialResourceRequestResult:  matched MediaAllocation to a initialMediaSelect
09:15:53.341 [6408.1792] <2> packageInitialResourceRequestResult: retVal = 0
09:15:53.341 [6408.1792] <2> RequestInitialResources: retVal = 0 emmStatus = 0
09:15:53.341 [6408.1792] <2> RequestInitialResources: returning
09:15:53.341 [6408.1792] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 1040 0002L4 4000002 ------ 6 1338433200 1338989867 1339594667 1338991268 819924372 5 5 0 9 10 0 1024 0 12811333 0], length 123
09:15:53.341 [6408.1792] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0002L4 4000002 000002L4 CIU_Daily FUJIFILM AA2TC9LJP3 6 8 0 2 0 {00000000-0000-0000-0000-000000000000} 0], length 113
09:15:53.341 [6408.1792] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 IBM.ULT3580-TD4.000 2000004 1310229502 {2,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0], length 121
09:15:53.341 [6408.1792] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 *NULL* 0 0 0 0 0 0 z02rsiciu01 z02rsiciu01 *NULL*], length 59
09:15:53.341 [6408.1792] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
09:15:53.341 [6408.1792] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
09:15:53.341 [6408.1792] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
09:15:53.341 [6408.1792] <2> populateBptmOpaqueStrings: retVal  = 0
09:15:53.341 [6408.1792] <2> parse_resource_strings: MEDIADB 1 1040 0002L4 4000002 ------ 6 1338433200 1338989867 1339594667 1338991268 819924372 5 5 0 9 10 0 1024 0 12811333 0
09:15:53.341 [6408.1792] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
09:15:53.341 [6408.1792] <2> parse_resource_strings: VOLUME 1 0002L4 4000002 000002L4 CIU_Daily FUJIFILM AA2TC9LJP3 6 8 0 2 0 {00000000-0000-0000-0000-000000000000} 0
09:15:53.341 [6408.1792] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
09:15:53.341 [6408.1792] <2> parse_resource_strings: DRIVE 3 IBM.ULT3580-TD4.000 2000004 1310229502 {2,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
09:15:53.341 [6408.1792] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
09:15:53.341 [6408.1792] <2> parse_resource_strings: STORAGE 1 *NULL* 0 0 0 0 0 0 z02rsiciu01 z02rsiciu01 *NULL*
09:15:53.341 [6408.1792] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
09:15:53.341 [6408.1792] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
09:15:53.341 [6408.1792] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
09:15:53.341 [6408.1792] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
09:15:53.341 [6408.1792] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
09:15:53.341 [6408.1792] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
09:15:53.341 [6408.1792] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
09:15:53.341 [6408.1792] <2> nbjm_media_request: Job control returned to BPTM
09:15:53.341 [6408.1792] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.000
09:15:53.341 [6408.1792] <2> drivename_checklock: Called
09:15:53.341 [6408.1792] <2> drivename_lock: lock established
09:15:53.341 [6408.1792] <2> drivename_write: Called with mode 0
09:15:53.341 [6408.1792] <2> drivename_unlock: unlocked
09:15:53.341 [6408.1792] <2> drivename_checklock: Called
09:15:53.341 [6408.1792] <2> drivename_lock: lock established
09:15:53.341 [6408.1792] <2> read_backup_mount_media: Number UP drives before restore = 1
09:15:53.341 [6408.1792] <2> mount_open_media: Waiting for mount of media id 0002L4 (copy 1) on server z02rsiciu01.
09:15:53.341 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4052: connect in progress: 0 0x00000000
09:15:53.404 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
09:15:53.404 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpjobd
09:16:16.821 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4238: in progress connect: 0 0x00000000
09:16:16.821 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4241: connect: async CONNECT FROM 10.135.159.133.11472 TO 10.135.159.133.13724 fd = 1156
09:16:16.821 [6408.1792] <2> job_connect: SO_KEEPALIVE set on socket 1156 for client z02rsiciu01
09:16:16.821 [6408.1792] <2> logconnections: BPJOBD CONNECT FROM 10.135.159.133.11472 TO 10.135.159.133.13724
09:16:16.821 [6408.1792] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
09:16:16.821 [6408.1792] <2> job_connect: Connected to the host z02rsiciu01 contype 10 jobid <3881> socket <1156>
09:16:16.821 [6408.1792] <2> job_connect: Connected on port 11472
09:16:16.821 [6408.1792] <2> set_job_details: Tfile (3881): PROCESS 1338992153 6408 bptm

09:16:16.821 [6408.1792] <2> set_job_details: Tfile (3881): MOUNTING 1338992176 0002L4

09:16:16.821 [6408.1792] <2> append_to_client_log: h:\70\src\nb\dblib\dbmisc.c.3358: about to call ConnectToBPCD connect_opts = 0xffffffff
09:16:16.821 [6408.1792] <2> ConnectToBPCD: db_getCLIENT(z02rsiciu01) failed: 227
09:16:16.821 [6408.1792] <2> hosts_equal: Comparing hosts <z02rsiciu01> and <z02rsiciu01.irmnet.ds2.dhs.gov>
09:16:16.821 [6408.1792] <2> hosts_equal: host1 z02rsiciu01 z02rsiciu01.irmnet.ds2.dhs.gov addr 10.135.159.133 (0x859f870a)
09:16:16.836 [6408.1792] <2> hosts_equal: host2 z02rsiciu01.irmnet.ds2.dhs.gov z02rsiciu01.irmnet.ds2.dhs.gov addr 10.135.159.133 (0x859f870a)
09:16:16.836 [6408.1792] <2> hosts_equal: hostnames DO compare (1)
09:16:16.836 [6408.1792] <2> local_bpcr_connect: bpcr.c.276: connect_opts = 0x01000100 connect_opts2 = 0x01000100
09:16:16.836 [6408.1792] <2> local_bpcr_connect: bpcr.c.283: connect_opts = 0x01000100
09:16:16.836 [6408.1792] <2> local_bpcr_connect: bpcr.c.322: daemon_port_type = 0
09:16:16.836 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4052: connect in progress: 0 0x00000000
09:16:16.883 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
09:16:16.883 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpcd
09:16:16.899 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4238: in progress connect: 0 0x00000000
09:16:16.899 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4241: connect: async CONNECT FROM 10.135.159.133.11479 TO 10.135.159.133.13724 fd = 1160
09:16:16.899 [6408.1792] <2> logconnections: BPCD CONNECT FROM 10.135.159.133.11479 TO 10.135.159.133.13724
09:16:16.899 [6408.1792] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.188: msg: VNETD CONNECT FROM 10.135.159.133.11480 TO 10.135.159.133.13724 fd = 1164
09:16:16.945 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.541: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
09:16:16.945 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.558: ipc_string: 11482
09:16:16.945 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.569: hash_str1: bd71d535650bb1f973048b28f1bd5d98
09:16:17.008 [6408.1792] <2> openNTDevice: config_path: {2,0,0,0}, serial_num: 1310229502
09:16:17.008 [6408.1792] <2> get_drive_path: SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td4#6&87a4ae8&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
09:16:17.008 [6408.1792] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, drive serial number 1310229502, expected serial number 1310229502
09:16:17.008 [6408.1792] <2> manage_scsi_reserve: SCSI RESERVE
09:16:17.211 [6408.1792] <2> tapelib: wait_for_ltid, Mount, timeout 0
09:16:52.734 [6408.1792] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000, serial_num: 1310229502
09:16:52.734 [6408.1792] <2> get_drive_path: SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td4#6&87a4ae8&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
09:16:52.734 [6408.1792] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, drive serial number 1310229502, expected serial number 1310229502
09:16:52.734 [6408.1792] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,0,0}) configured with blocksize 0
09:16:52.749 [6408.1792] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,0,0}) has compression enabled
09:16:52.749 [6408.1792] <2> io_open: SCSI RESERVE (C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000)
09:16:52.765 [6408.1792] <2> manage_drive_attributes: report_attr, fl1 0x00030049, fl2 0x0000000c
09:16:52.765 [6408.1792] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [AA2TC9LJP3]
09:16:52.765 [6408.1792] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [7.0]
09:16:52.765 [6408.1792] <2> manage_drive_attributes: DateLabeled [201205310300], Barcode [000002L4], Owninghost [z02rsiciu01]
09:16:52.765 [6408.1792] <2> manage_drive_attributes: MediaPool [CIU_Daily], MediaLabel [MEDIA=0002L4;]
09:16:52.765 [6408.1792] <2> manage_drive_attributes: encryption status: nexus scope 1, key scope 1
09:16:52.765 [6408.1792] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 1, key instance 24
09:16:52.765 [6408.1792] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000, serial_num: 1310229502
09:16:52.765 [6408.1792] <2> get_drive_path: SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td4#6&87a4ae8&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
09:16:52.765 [6408.1792] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, drive serial number 1310229502, expected serial number 1310229502
09:16:52.781 [6408.1792] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,0,0}) configured with blocksize 0
09:16:52.781 [6408.1792] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,0,0}) has compression enabled
09:16:52.796 [6408.1792] <2> manage_drive_attributes: report_attr, fl1 0x00030049, fl2 0x0000000c
09:16:52.796 [6408.1792] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [AA2TC9LJP3]
09:16:52.796 [6408.1792] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [7.0]
09:16:52.796 [6408.1792] <2> manage_drive_attributes: DateLabeled [201205310300], Barcode [000002L4], Owninghost [z02rsiciu01]
09:16:52.796 [6408.1792] <2> manage_drive_attributes: MediaPool [CIU_Daily], MediaLabel [MEDIA=0002L4;]
09:16:52.812 [6408.1792] <2> manage_drive_attributes: encryption status: nexus scope 1, key scope 1
09:16:52.812 [6408.1792] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 1, key instance 25
09:16:52.812 [6408.1792] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000 successfully opened (mode 0)
09:16:52.812 [6408.1792] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x00000000032D7E20, copy 1
09:16:52.812 [6408.1792] <2> io_ioctl: command (5)MTREW 1 from (bptm.c.8183) on drive index 0
09:16:52.843 [6408.1792] <2> io_ioctl: command (1)MTFSF 1 from (bptm.c.8440) on drive index 0
09:16:52.859 [6408.1792] <2> set_job_details: Tfile (3881): MOUNTED 1338992212 0002L4

09:16:52.859 [6408.1792] <2> bptm media_id_to_monitor: job_id = 3881
09:16:52.859 [6408.1792] <2> bptm media_id_to_monitor: pSrcMediaId = 0002L4
09:16:52.859 [6408.1792] <2> set_job_details: jobData (3881)
09:16:52.859 [6408.1792] <2> send_structure_data: Index 25 Field m_szSrcMediaID Value <0002L4>
09:16:52.859 [6408.1792] <2> read_backup_mount_media: media id 0002L4 mounted on drive index 0
09:16:52.859 [6408.1792] <2> send_MDS_msg: MEDIADB 1 1040 0002L4 4000002 *NULL* 6 1338433200 1338989867 1339594667 1338992212 819924372 5 5 0 9 11 0 1024 0 12811333 0
09:16:52.874 [6408.1792] <2> append_to_client_log: h:\70\src\nb\dblib\dbmisc.c.3358: about to call ConnectToBPCD connect_opts = 0xffffffff
09:16:52.874 [6408.1792] <2> ConnectToBPCD: db_getCLIENT(z02rsiciu01) failed: 227
09:16:52.874 [6408.1792] <2> hosts_equal: Comparing hosts <z02rsiciu01> and <z02rsiciu01.irmnet.ds2.dhs.gov>
09:16:52.874 [6408.1792] <2> hosts_equal: host1 z02rsiciu01 z02rsiciu01.irmnet.ds2.dhs.gov addr 10.135.159.133 (0x859f870a)
09:16:52.874 [6408.1792] <2> hosts_equal: host2 z02rsiciu01.irmnet.ds2.dhs.gov z02rsiciu01.irmnet.ds2.dhs.gov addr 10.135.159.133 (0x859f870a)
09:16:52.874 [6408.1792] <2> hosts_equal: hostnames DO compare (1)
09:16:52.874 [6408.1792] <2> local_bpcr_connect: bpcr.c.276: connect_opts = 0x01000100 connect_opts2 = 0x01000100
09:16:52.874 [6408.1792] <2> local_bpcr_connect: bpcr.c.283: connect_opts = 0x01000100
09:16:52.874 [6408.1792] <2> local_bpcr_connect: bpcr.c.322: daemon_port_type = 0
09:16:52.874 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4052: connect in progress: 0 0x00000000
09:16:52.921 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
09:16:52.921 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpcd
09:16:52.937 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4238: in progress connect: 0 0x00000000
09:16:52.937 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4241: connect: async CONNECT FROM 10.135.159.133.11499 TO 10.135.159.133.13724 fd = 1184
09:16:52.937 [6408.1792] <2> logconnections: BPCD CONNECT FROM 10.135.159.133.11499 TO 10.135.159.133.13724
09:16:52.937 [6408.1792] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.188: msg: VNETD CONNECT FROM 10.135.159.133.11500 TO 10.135.159.133.13724 fd = 1180
09:16:52.983 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.541: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
09:16:52.983 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.558: ipc_string: 11501
09:16:52.983 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.569: hash_str1: 666fc486287fd38653142323be21d993
09:16:53.046 [6408.1792] <2> set_job_details: Tfile (3881): POSITIONING 1338992213 0002L4 5

09:16:53.046 [6408.1792] <2> io_position_for_read: positioning 0002L4 to file number 5
09:16:53.046 [6408.1792] <2> io_position_for_read: locating to absolute block number 10248783
09:17:25.246 [6408.1792] <2> io_position_for_read: locate block is done
09:17:25.246 [6408.1792] <2> io_read_back_header: drive index 0, reading backup header
09:17:25.324 [6408.1792] <2> set_job_details: Tfile (3881): POSITIONED 1338992245 0002L4

09:17:25.324 [6408.1792] <2> io_position_for_read: successfully positioned 0002L4 to file number 5
09:17:25.324 [6408.1792] <2> read_backup_fsr: current position of tape is 10248784, locating to 12490396
09:17:29.240 [7100.7824] <2> bptm: instance - 77475696
09:17:29.240 [7100.7824] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1338914983 -jm
09:17:29.240 [7100.7824] <2> bptm: Event NetBackup Terminate Event, pid: 7100 created.
09:17:29.240 [7100.7824] <2> bptm: PORT_STATUS = 0x00000000
09:17:29.240 [7100.7824] <2> drivename_open: Called with Create 0, file IBM.ULT3580-TD4.000
09:17:29.240 [7100.7824] <2> drivename_checklock: Called
09:17:29.240 [7100.7824] <2> drivename_checklock: File is locked
09:17:29.240 [7100.7824] <2> report_drives: DRIVE = IBM.ULT3580-TD4.000 LOCK = TRUE CURTIME = 1338992249
09:17:29.240 [7100.7824] <2> drivename_close: Called for file IBM.ULT3580-TD4.000
09:17:29.240 [7100.7824] <2> report_drives: MODE = 0
09:17:29.240 [7100.7824] <2> report_drives: TIME = 1338992153
09:17:29.240 [7100.7824] <2> report_drives: MASTER = z02rsiciu01
09:17:29.240 [7100.7824] <2> report_drives: SR_KEY = 0 1
09:17:29.240 [7100.7824] <2> report_drives: PATH = {2,0,0,0}
09:17:29.240 [7100.7824] <2> report_drives: MEDIA = 0002L4
09:17:29.240 [7100.7824] <2> report_drives: REQID = 3881
09:17:29.240 [7100.7824] <2> report_drives: ALOCID = 1040
09:17:29.240 [7100.7824] <2> report_drives: RBID = {8C70C330-26F9-4A30-AA78-79B204F4FF30}
09:17:29.240 [7100.7824] <2> report_drives: PID = 6408
09:17:29.240 [7100.7824] <2> report_drives: FILE = C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000
09:17:29.240 [7100.7824] <2> main: Sending [EXIT STATUS 0] to NBJM
09:17:29.240 [7100.7824] <2> bptm: EXITING with status 0 <----------
09:17:29.240 [7100.7824] <2> bptm: NetBackup Terminate Event, pid: 7100 closed.

09:17:38.959 [6408.1792] <2> read_backup_fsr: locate block is done
09:17:38.959 [6408.1792] <2> set_job_details: Tfile (3881): BEGIN_READING 1338992258

09:17:38.959 [6408.1792] <2> append_to_client_log: h:\70\src\nb\dblib\dbmisc.c.3358: about to call ConnectToBPCD connect_opts = 0xffffffff
09:17:38.959 [6408.1792] <2> ConnectToBPCD: db_getCLIENT(z02rsiciu01) failed: 227
09:17:38.959 [6408.1792] <2> hosts_equal: Comparing hosts <z02rsiciu01> and <z02rsiciu01.irmnet.ds2.dhs.gov>
09:17:38.959 [6408.1792] <2> hosts_equal: host1 z02rsiciu01 z02rsiciu01.irmnet.ds2.dhs.gov addr 10.135.159.133 (0x859f870a)
09:17:38.959 [6408.1792] <2> hosts_equal: host2 z02rsiciu01.irmnet.ds2.dhs.gov z02rsiciu01.irmnet.ds2.dhs.gov addr 10.135.159.133 (0x859f870a)
09:17:38.959 [6408.1792] <2> hosts_equal: hostnames DO compare (1)
09:17:38.959 [6408.1792] <2> local_bpcr_connect: bpcr.c.276: connect_opts = 0x01000100 connect_opts2 = 0x01000100
09:17:38.959 [6408.1792] <2> local_bpcr_connect: bpcr.c.283: connect_opts = 0x01000100
09:17:38.959 [6408.1792] <2> local_bpcr_connect: bpcr.c.322: daemon_port_type = 0
09:17:38.959 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4052: connect in progress: 0 0x00000000
09:17:39.021 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
09:17:39.021 [6408.1792] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpcd
09:17:39.021 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4238: in progress connect: 0 0x00000000
09:17:39.021 [6408.1792] <2> vnet_async_connect: ../../libvlibs/vnet_vnetd.c.4241: connect: async CONNECT FROM 10.135.159.133.11524 TO 10.135.159.133.13724 fd = 1180
09:17:39.021 [6408.1792] <2> logconnections: BPCD CONNECT FROM 10.135.159.133.11524 TO 10.135.159.133.13724
09:17:39.021 [6408.1792] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.188: msg: VNETD CONNECT FROM 10.135.159.133.11525 TO 10.135.159.133.13724 fd = 588
09:17:39.084 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.541: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
09:17:39.084 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.558: ipc_string: 11526
09:17:39.084 [6408.1792] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.569: hash_str1: 6f327461b9eb7ba4a52a74ec163d1f2d
09:17:39.146 [6408.1792] <4> mpx_issue_begin_msg: begin reading backup id z02rsiciu01_1338951600 (restore), copy 1, fragment 1, from media id 0002L4 on drive IBM.ULT3580-TD4.000 (index 0)
09:17:39.146 [6408.1792] <2> send_brm_msg: CURRENT POSITION 0002L4 5
09:17:39.146 [6408.1792] <2> process_brm_msg: no pending message from bpbrm
09:17:40.160 [6408.1792] <2> read_brm_msg: CONTINUE RESTORE
09:17:40.160 [6408.1792] <2> send_brm_msg: MEDIA READY
09:17:40.160 [6408.1792] <2> mpx_read_data: begin reading data from media id 0002L4, file num 5
09:17:40.160 [6408.1792] <2> mpx_read_data: Total Kbytes transferred 0
09:17:40.160 [6408.1792] <2> read_position: read position on drive index 0, is LBA 12490396
09:17:40.503 [6408.1792] <2> notify: executing - C:\Program Files\Veritas\NetBackup\bin\restore_notify.cmd bptm z02rsiciu01_1338951600 restore
09:17:40.659 [6408.1792] <2> set_job_details: jobData (3881)
09:17:40.659 [6408.1792] <2> send_structure_data: Index 36 Field m_nKbPerSec Value <82285>
09:17:40.659 [6408.1792] <2> mpx_check_children: Total Kbytes transferred 28224
09:17:40.659 [6408.1792] <2> set_job_details: Tfile (3881): END_READING 1338992260

09:17:40.659 [6408.1792] <4> mpx_check_children: successfully restored from backup id z02rsiciu01_1338951600, copy 1, 28224 kbytes
09:17:40.675 [6408.1792] <4> report_throughput: VBRT 1 6408 0 1 IBM.ULT3580-TD4.000 0002L4 0 1 0 28224  28224 (mpxrestore.c.2662)
09:17:40.675 [6408.1792] <2> send_brm_msg: MEDIA NOT READY
09:17:40.675 [6408.1792] <2> send_brm_msg: EXIT z02rsiciu01_1338951600 0
09:17:40.675 [6408.1792] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0
09:17:40.675 [6408.1792] <4> report_throughput: VBRT 1 6408 4 1 IBM.ULT3580-TD4.000 0002L4 0 0  0 (mpxrestore.c.1294)
09:17:40.675 [6408.1792] <2> mpx_read_data: waited for empty buffer 13 times, delayed 18 times
09:17:40.675 [6408.1792] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000, from mpxrestore.c.2733
09:17:40.675 [6408.1792] <2> mpx_waiting_term: waiting for TERMINATE or another START RESTORE
09:17:40.675 [6408.1792] <2> read_brm_msg: STOP RESTORE z02rsiciu01_1338951600
09:17:40.675 [6408.1792] <2> process_brm_msg: could not find backupid z02rsiciu01_1338951600 to terminate
09:17:41.689 [6408.1792] <2> mpx_check_msg_pending: could not open msg pending event, The system cannot find the file specified.
09:17:41.689 [6408.1792] <2> read_brm_msg: TERMINATE
09:17:41.689 [6408.1792] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000, serial_num: 1310229502
09:17:41.689 [6408.1792] <2> get_drive_path: SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td4#6&87a4ae8&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
09:17:41.689 [6408.1792] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, drive serial number 1310229502, expected serial number 1310229502
09:17:41.705 [6408.1792] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,0,0}) configured with blocksize 0
09:17:41.705 [6408.1792] <2> init_tape: \\.\Tape0 (SCSI coordinates {2,0,0,0}) has compression enabled
09:17:41.720 [6408.1792] <2> io_open: SCSI RESERVE
09:17:41.720 [6408.1792] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000 successfully opened (mode 2)
09:17:41.720 [6408.1792] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tpunmount)
09:17:41.720 [6408.1792] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000, from bptm.c.18948
09:17:41.720 [6408.1792] <2> drivename_write: Called with mode 1
09:17:41.720 [6408.1792] <2> drivename_unlock: unlocked
09:17:41.720 [6408.1792] <2> drivename_checklock: Called
09:17:41.720 [6408.1792] <2> drivename_lock: lock established
09:17:41.720 [6408.1792] <2> drivename_unlock: unlocked
09:17:41.720 [6408.1792] <2> drivename_close: Called for file IBM.ULT3580-TD4.000
09:17:41.720 [6408.1792] <2> tpunmount: NOP: MEDIA_DONE 0 0 0 0002L4 4000002 180 {8C70C330-26F9-4A30-AA78-79B204F4FF30}
09:17:41.720 [6408.1792] <4> mpx_read_backup: successfully restored 1 of 1 requests, read total of 28224 Kbytes at 82046.512 Kbytes/sec
09:17:41.720 [6408.1792] <2> job_monitoring_exex: ACK disconnect
09:17:41.720 [6408.1792] <2> job_disconnect: Disconnected
09:17:41.720 [6408.1792] <2> bptm: Calling tpunmount for media 0002L4
09:17:41.720 [6408.1792] <2> send_MDS_msg: MEDIA_DONE 0 3881 0 0002L4 4000002 180 {8C70C330-26F9-4A30-AA78-79B204F4FF30}
09:17:41.720 [6408.1792] <2> JobInst::sendIrmMsg: starting
09:17:41.720 [6408.1792] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 3881 0 0002L4 4000002 180 {8C70C330-26F9-4A30-AA78-79B204F4FF30})
09:17:41.720 [6408.1792] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 3881 copyNum 0 mediaId 0002L4 mediaKey 4000002 unloadDelay 180 allocId {8C70C330-26F9-4A30-AA78-79B204F4FF30}
09:17:41.720 [6408.1792] <2> packageBptmResourceDoneMsg: returns 0
09:17:41.720 [6408.1792] <2> JobInst::sendIrmMsg: returning
09:17:41.720 [6408.1792] <2> bptm: EXITING with status 0 <----------
09:17:41.720 [6408.1792] <2> bptm: NetBackup Terminate Event, pid: 6408 closed.

09:20:42.299 [7252.7632] <2> bptm: instance - 77668748
09:20:42.299 [7252.7632] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn IBM.ULT3580-TD4.000 -dp {2,0,0,0} -dk 2000004 -m 0002L4 -mk 4000002 -mds 16 -alocid 1040 -jobid -1338914984 -jm
09:20:42.299 [7252.7632] <2> bptm: Event NetBackup Terminate Event, pid: 7252 created.
09:20:42.299 [7252.7632] <2> bptm: PORT_STATUS = 0x00000000
09:20:42.299 [7252.7632] <2> hosts_equal: The second name is empty
09:20:42.299 [7252.7632] <2> hosts_equal: Comparing hosts <z02rsiciu01> and <z02rsiciu01>
09:20:42.299 [7252.7632] <2> hosts_equal: names are the same
09:20:42.299 [7252.7632] <2> hosts_equal: Comparing hosts <z02rsiciu01> and <z02rsiciu01>
09:20:42.299 [7252.7632] <2> hosts_equal: names are the same
09:20:42.299 [7252.7632] <4> bptm: emmserver_name = z02rsiciu01
09:20:42.299 [7252.7632] <4> bptm: emmserver_port = 1556
09:20:42.315 [7252.7632] <2> dbstunitq@VssSetLogLevel:  ++++ ENTERING ++++
09:20:42.315 [7252.7632] <4> dbstunitq@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:20:42.315 [7252.7632] <2> dbstunitq@VssSetLogLevel:  ---- EXITING ----
09:20:42.315 [7252.7632] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:741)
09:20:42.315 [7252.7632] <2> dbstunitq@VssSetLogLevel:  ++++ ENTERING ++++
09:20:42.315 [7252.7632] <4> dbstunitq@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:20:42.315 [7252.7632] <2> dbstunitq@VssSetLogLevel:  ---- EXITING ----
09:20:42.315 [7252.7632] <2> EndpointSelector::select_endpoint: performing call with the only endpt available!(Endpoint_Selector.cpp:437)
09:20:42.331 [7252.7632] <2> send_brm_msg: PID of bpxm = 7252
09:20:42.331 [7252.7632] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
09:20:42.331 [7252.7632] <2> nbjm_media_request: old_media_id = NULL, media_id = 0002L4
09:20:42.331 [7252.7632] <2> RequestInitialResources: starting
09:20:42.331 [7252.7632] <2> RequestInitialResources: started
09:20:42.331 [7252.7632] <2> Unknown@VssSetLogLevel:  ++++ ENTERING ++++
09:20:42.331 [7252.7632] <4> Unknown@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:20:42.331 [7252.7632] <2> Unknown@VssSetLogLevel:  ---- EXITING ----
09:20:42.331 [7252.7632] <2> Orb::init: Created anon service name: NB_7252_1193677744(Orb.cpp:612)
09:20:42.331 [7252.7632] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_7252_1193677744(Orb.cpp:630)
09:20:42.331 [7252.7632] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_7252_1193677744 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:741)
09:20:42.331 [7252.7632] <2> NB_7252_1193677744@VssSetLogLevel:  ++++ ENTERING ++++
09:20:42.331 [7252.7632] <4> NB_7252_1193677744@VssSetLogLevel: (../../libVnbat/vss_auth.cpp,4798): Setting VSSLOG level to 5.
09:20:42.331 [7252.7632] <2> NB_7252_1193677744@VssSetLogLevel:  ---- EXITING ----
09:20:42.331 [7252.7632] <2> init_cache: ../../libvlibs/vnet_hosts.c.1046: host_cache_size: 200 0x000000c8
09:20:42.331 [7252.7632] <2> init_cache: ../../libvlibs/vnet_hosts.c.1047: cache_time: 3600 0x00000e10
09:20:42.331 [7252.7632] <2> init_cache: ../../libvlibs/vnet_hosts.c.1061: host_failed_cache_size: 40 0x00000028
09:20:42.331 [7252.7632] <2> init_cache: ../../libvlibs/vnet_hosts.c.1062: cache_time: 3600 0x00000e10
09:20:42.331 [7252.7632] <2> init_cache: ../../libvlibs/vnet_hosts.c.1046: host_cache_size: 200 0x000000c8
09:20:42.331 [7252.7632] <2> init_cache: ../../libvlibs/vnet_hosts.c.1047: cache_time: 3600 0x00000e10
09:20:42.331 [7252.7632] <2> init_cache: ../../libvlibs/vnet_hosts.c.1061: host_failed_cache_size: 40 0x00000028
09:20:42.331 [7252.7632] <2> init_cache: ../../libvlibs/vnet_hosts.c.1062: cache_time: 3600 0x00000e10
09:20:42.331 [7252.7632] <2> EndpointSelector::select_endpoint: performing call with the only endpt available!(Endpoint_Selector.cpp:437)
09:20:42.331 [7252.7632] <2> packageInitialResourceRequest: started
09:20:42.331 [7252.7632] <2> packageInitialResourceRequest: retVal = 0
09:20:42.331 [7252.7632] <2> RequestInitialResources: setting up callback and calling requestResources
09:20:42.331 [7252.7632] <2> logResourceReq: req.versionId : 1
09:20:42.331 [7252.7632] <2> logResourceReq: req.jobId : -1338914984
09:20:42.331 [7252.7632] <2> logResourceReq: req.startedViaJobManager : true
09:20:42.331 [7252.7632] <2> logResourceReq: req.consumer : true
09:20:42.331 [7252.7632] <2> logResourceReq: InitialMediaSelect -
09:20:42.331 [7252.7632] <2> logResourceReq:  reqNum : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.mediaId : 0002L4
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.mediaKey : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.mediaServer : z02rsiciu01
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.userReservationId :
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.assignedTime : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.client :
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.usageType : 6
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.mustBeNdmp : false
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.driveName : IBM.ULT3580-TD4.000
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.drivePath :
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.mediaPool :
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.robotNumber : -1
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.slotNumber : -1
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.density : -1
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.ndmpControlHost :
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.failIfNoMedia : true
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.externalFile :
09:20:42.331 [7252.7632] <2> logMediaRequest:  mreq.exp
09:20:42.331 [7252.7632] <2> logMediaRequest:       mediaType : -1
09:20:42.331 [7252.7632] <2> logMediaRequest:       mediaSubType : -1
09:20:42.331 [7252.7632] <2> logMediaRequest:  exp.capabilities
09:20:42.331 [7252.7632] <2> logMediaRequest:          isNdmp : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:          isTirRestore : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:          isFlashbackupRestore : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:          isBlockMapRead : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:          isCatalogBackup : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:          isGcsCatalogBackup : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:          preferVtlToDirectAttachedTape : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:          isVMWare : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:          isLifeCycle : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:     useFt : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:     failIfNoFt : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:     isGranularExchange : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:     requestFlags : 0
09:20:42.331 [7252.7632] <2> logMediaRequest:  mediaServerAffinityID : 0
09:20:42.331 [7252.7632] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0
09:20:42.362 [7252.7632] <2> resourcesAvailable: m_allocationSeq.length() == 1
09:20:42.362 [7252.7632] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
09:20:42.362 [7252.7632] <2> resourcesAvailable: MEDIADB 1 1040 0002L4 4000002 ------ 6 1338433200 1338989867 1339594667 1338991268 819924372 5 5 0 9 10 0 1024 0 12811333 0
09:20:42.362 [7252.7632] <2> resourcesAvailable: VOLUME 1 0002L4 4000002 000002L4 CIU_Daily FUJIFILM AA2TC9LJP3 6 8 0 2 0 {00000000-0000-0000-0000-000000000000} 0
09:20:42.362 [7252.7632] <2> resourcesAvailable: DRIVE 3 IBM.ULT3580-TD4.000 2000004 1310229502 {2,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
09:20:42.362 [7252.7632] <2> resourcesAvailable: STORAGE 1 *NULL* 0 0 0 0 0 0 z02rsiciu01 z02rsiciu01 *NULL*
09:20:42.362 [7252.7632] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
09:20:42.362 [7252.7632] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
09:20:42.362 [7252.7632] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
09:20:44.343 [7252.7632] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
09:20:44.343 [7252.7632] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
09:20:44.343 [7252.7632] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
09:20:44.343 [7252.7632] <2> packageInitialResourceRequestResult:  matched MediaAllocation to a initialMediaSelect
09:20:44.343 [7252.7632] <2> packageInitialResourceRequestResult: retVal = 0
09:20:44.343 [7252.7632] <2> RequestInitialResources: retVal = 0 emmStatus = 0
09:20:44.343 [7252.7632] <2> RequestInitialResources: returning
09:20:44.343 [7252.7632] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 1040 0002L4 4000002 ------ 6 1338433200 1338989867 1339594667 1338991268 819924372 5 5 0 9 10 0 1024 0 12811333 0], length 123
09:20:44.343 [7252.7632] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 0002L4 4000002 000002L4 CIU_Daily FUJIFILM AA2TC9LJP3 6 8 0 2 0 {00000000-0000-0000-0000-000000000000} 0], length 113
09:20:44.343 [7252.7632] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 IBM.ULT3580-TD4.000 2000004 1310229502 {2,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0], length 121
09:20:44.343 [7252.7632] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 *NULL* 0 0 0 0 0 0 z02rsiciu01 z02rsiciu01 *NULL*], length 59
09:20:44.343 [7252.7632] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
09:20:44.343 [7252.7632] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
09:20:44.343 [7252.7632] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
09:20:44.343 [7252.7632] <2> populateBptmOpaqueStrings: retVal  = 0
09:20:44.343 [7252.7632] <2> parse_resource_strings: MEDIADB 1 1040 0002L4 4000002 ------ 6 1338433200 1338989867 1339594667 1338991268 819924372 5 5 0 9 10 0 1024 0 12811333 0
09:20:44.343 [7252.7632] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
09:20:44.343 [7252.7632] <2> parse_resource_strings: VOLUME 1 0002L4 4000002 000002L4 CIU_Daily FUJIFILM AA2TC9LJP3 6 8 0 2 0 {00000000-0000-0000-0000-000000000000} 0
09:20:44.343 [7252.7632] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
09:20:44.343 [7252.7632] <2> parse_resource_strings: DRIVE 3 IBM.ULT3580-TD4.000 2000004 1310229502 {2,0,0,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
09:20:44.343 [7252.7632] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
09:20:44.343 [7252.7632] <2> parse_resource_strings: STORAGE 1 *NULL* 0 0 0 0 0 0 z02rsiciu01 z02rsiciu01 *NULL*
09:20:44.343 [7252.7632] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
09:20:44.343 [7252.7632] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
09:20:44.343 [7252.7632] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
09:20:44.343 [7252.7632] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
09:20:44.343 [7252.7632] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
09:20:44.343 [7252.7632] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
09:20:44.343 [7252.7632] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
09:20:44.343 [7252.7632] <2> nbjm_media_request: Job control returned to BPTM
09:20:44.343 [7252.7632] <2> drivename_open: Called with Create 1, file IBM.ULT3580-TD4.000
09:20:44.343 [7252.7632] <2> drivename_checklock: Called
09:20:44.343 [7252.7632] <2> drivename_lock: lock established
09:20:44.343 [7252.7632] <4> create_tpreq_file: {2,0,0,0}
09:20:44.343 [7252.7632] <2> drivename_write: Called with mode 2
09:20:44.343 [7252.7632] <2> drivename_unlock: unlocked
09:20:44.343 [7252.7632] <2> drivename_checklock: Called
09:20:44.343 [7252.7632] <2> drivename_lock: lock established
09:20:44.343 [7252.7632] <2> openNTDevice: config_path: {2,0,0,0}, serial_num: 1310229502
09:20:44.343 [7252.7632] <2> get_drive_path: SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td4#6&87a4ae8&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
09:20:44.343 [7252.7632] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, drive serial number 1310229502, expected serial number 1310229502
09:20:44.343 [7252.7632] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
09:20:44.343 [7252.7632] <2> really_tpunmount: tpunmount'ing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULT3580-TD4.000
09:20:45.154 [7252.7632] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
09:21:40.756 [7252.7632] <4> report_resource_done: VBRD 1 7252 0 IBM.ULT3580-TD4.000 0002L4
09:21:40.756 [7252.7632] <2> openNTDevice: config_path: {2,0,0,0}, serial_num: 1310229502
09:21:40.756 [7252.7632] <2> get_drive_path: SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td4#6&87a4ae8&0&000000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
09:21:40.756 [7252.7632] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,0,0}, dos_path \\.\Tape0, drive serial number 1310229502, expected serial number 1310229502
09:21:40.756 [7252.7632] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
09:21:40.756 [7252.7632] <2> tapealert_and_release: SCSI RELEASE
09:21:40.756 [7252.7632] <2> drivename_unlock: unlocked
09:21:40.756 [7252.7632] <2> drivename_close: Called for file IBM.ULT3580-TD4.000
09:21:40.771 [7252.7632] <2> drivename_remove: Called
09:21:40.771 [7252.7632] <2> main: Sending [EXIT STATUS 0] to NBJM
09:21:40.771 [7252.7632] <2> bptm: EXITING with status 0 <----------
09:21:40.771 [7252.7632] <2> bptm: NetBackup Terminate Event, pid: 7252 closed.