We use Windows server 2008 R2 netbackup server (NBU 7) to backup Lotus notes 7 (windows server 2003 R2 sp2). The process failed:
4/21/2010 11:52:11 AM - estimated 0 Kbytes needed
4/21/2010 11:52:11 AM - started process bpbrm (6840)
4/21/2010 11:52:12 AM - connecting
4/21/2010 11:52:15 AM - connected; connect time: 00:00:03
4/21/2010 11:52:21 AM - Error bpbrm(pid=6840) could not send server status message
4/21/2010 11:52:23 AM - end writing
none of the files in the file list exist(71)
===========================
/21/2010 11:52:09 AM - requesting resource pmssapp27-hcart-robot-tld-1
4/21/2010 11:52:09 AM - requesting resource pmssapp27.NBU_CLIENT.MAXJOBS.venms01
4/21/2010 11:52:09 AM - requesting resource pmssapp27.NBU_POLICY.MAXJOBS.NBU_Tape_VENMS01
4/21/2010 11:52:09 AM - granted resource pmssapp27.NBU_CLIENT.MAXJOBS.venms01
4/21/2010 11:52:09 AM - granted resource pmssapp27.NBU_POLICY.MAXJOBS.NBU_Tape_VENMS01
4/21/2010 11:52:09 AM - granted resource J802L4
4/21/2010 11:52:09 AM - granted resource HP.ULTRIUM4-SCSI.001
4/21/2010 11:52:09 AM - granted resource pmssapp27-hcart-robot-tld-1
4/21/2010 11:52:09 AM - estimated 0 Kbytes needed
4/21/2010 11:52:09 AM - begin Parent Job
4/21/2010 11:52:09 AM - begin Stream Discovery, Start Notify Script
4/21/2010 11:52:09 AM - started process RUNCMD (6972)
4/21/2010 11:52:10 AM - ended process 0 (6972)
Status 0
4/21/2010 11:52:10 AM - end Stream Discovery, Start Notify Script; elapsed time: 00:00:01
4/21/2010 11:52:10 AM - begin Stream Discovery, Stream Discovery
Status 0
4/21/2010 11:52:10 AM - end Stream Discovery, Stream Discovery; elapsed time: 00:00:00
4/21/2010 11:52:10 AM - begin Stream Discovery, Policy Execution Manager Preprocessed
Status 71
4/21/2010 11:52:23 AM - end Stream Discovery, Policy Execution Manager Preprocessed; elapsed time: 00:00:13
4/21/2010 11:52:23 AM - begin Stream Discovery, Stop On Error
Status 0
4/21/2010 11:52:23 AM - end Stream Discovery, Stop On Error; elapsed time: 00:00:00
4/21/2010 11:52:23 AM - begin Stream Discovery, End Notify Script
4/21/2010 11:52:23 AM - started process RUNCMD (6064)
4/21/2010 11:52:23 AM - ended process 0 (6064)
Status 0
4/21/2010 11:52:23 AM - end Stream Discovery, End Notify Script; elapsed time: 00:00:00
Status 71
4/21/2010 11:52:23 AM - end Parent Job; elapsed time: 00:00:14
none of the files in the file list exist(71)
=================================================
BPBRM log
11:52:11.514 [6840.932] <2> bpbrm main: INITIATING (VERBOSE = 0): version NetBackup 7.0 0
11:52:11.514 [6840.932] <2> logparams: -backup -S pmssapp27 -c venms01 -ct 25 -ru root -cl NBU_Tape_VENMS01 -sched Full -bt 1271825531 -dt 0 -st 0 -b venms01_1271825531 -mediasvr pmssapp27 -jobid 605 -jobgrpid 604 -masterversion 700000 -maxfrag 1048576 -reqid -1271736053 -mt 2 -to 0 -stunit pmssapp27-hcart-robot-tld-1 -rl 1 -rp 1209600 -cj 1 -D 6 -rt 8 -rn 1 -pool Monthly -use_ofb -use_otm -jm -secure 1 -kl 28 -rg other -fso -stream_count 1 -stream_number 1 -connect_options 16974338
11:52:11.530 [6840.932] <2> verify_client: bpbrm.c.34211: db_getCLIENT failed for CLIENT: venms01
11:52:11.530 [6840.932] <2> verify_client: bpbrm.c.34361: db_getCLIENT failed: 227 227 0x000000e3
11:52:11.624 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
11:52:11.624 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpcd
11:52:11.780 [6840.932] <2> logconnections: BPCD CONNECT FROM 128.235.106.171.56645 TO 128.235.106.55.13724
11:52:11.780 [6840.932] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.188: msg: VNETD CONNECT FROM 128.235.106.171.56646 TO 128.235.106.55.13724 fd = 700
11:52:11.843 [6840.932] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.541: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
11:52:11.999 [6840.932] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.558: ipc_string: 3677
11:52:12.421 [6840.932] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 680
11:52:12.421 [6840.932] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 700
11:52:12.421 [6840.932] <2> bpbrm create_events: created suspend event name NetBackup Suspend Event, pid: 6840
11:52:12.421 [6840.932] <2> bpbrm main: send_3_0_client_params = 1
11:52:12.421 [6840.932] <2> bpbrm main: backup_cmd = /usr/openv/netbackup/bin/bpbkar bpbkar32 -r 1209600 -ru root -dt 0 -to 0 -clnt venms01 -class NBU_Tape_VENMS01 -sched Full -st FULL -bpstart_to 3000 -bpend_to 300 -read_to 300 -stream_count 1 -stream_number 1 -jobgrpid 604 -blks_per_buffer 128 -use_otm -fso -b venms01_1271825531 -kl 28 -ct 25
11:52:12.483 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
11:52:12.483 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpcd
11:52:12.655 [6840.932] <2> logconnections: BPCD CONNECT FROM 128.235.106.171.56647 TO 128.235.106.55.13724
11:52:12.655 [6840.932] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.188: msg: VNETD CONNECT FROM 128.235.106.171.56648 TO 128.235.106.55.13724 fd = 732
11:52:12.718 [6840.932] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.541: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
11:52:12.874 [6840.932] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.558: ipc_string: 3679
11:52:13.514 [6840.932] <2> bpcr_get_version_rqst: bpcd version: 07000000
11:52:13.718 [6840.932] <2> bpcr_get_charset_rqst: bpcd charset: 00000054
11:52:13.718 [6840.932] <2> ConnectionCache::connectAndCache: Acquiring new connection for host pmssapp27, query type 89
11:52:13.749 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
11:52:13.749 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpdbm
11:52:13.749 [6840.932] <2> logconnections: BPDBM CONNECT FROM 128.235.106.171.56649 TO 128.235.106.171.13724
11:52:13.827 [6840.932] <2> db_end: Need to collect reply
11:52:14.061 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
11:52:14.061 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpcd
11:52:14.186 [6840.932] <2> logconnections: BPCD CONNECT FROM 128.235.106.171.56653 TO 128.235.106.55.13724
11:52:14.186 [6840.932] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.188: msg: VNETD CONNECT FROM 128.235.106.171.56654 TO 128.235.106.55.13724 fd = 736
11:52:14.249 [6840.932] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.541: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
11:52:14.405 [6840.932] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.558: ipc_string: 3681
11:52:14.827 [6840.932] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 728
11:52:14.827 [6840.932] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 736
11:52:15.030 [6840.932] <2> bpcr_get_version_rqst: bpcd version: 07000000
11:52:15.233 [6840.932] <2> bpcr_get_platform_rqst: Server client platform length = 2
11:52:15.233 [6840.932] <2> bpcr_check_for_use_ofb_support: bpcd platform nt
11:52:15.233 [6840.932] <2> bpbrm main: received bpcd success message
11:52:18.718 [6840.932] <2> get_readline_type: Returning BPBRM_READ_INFORM_WHEN_DONE
11:52:18.936 [6840.932] <2> bpbrm main: from client venms01: read client start message
11:52:18.936 [6840.932] <2> bpbrm spawn_child: "C:\Program Files\Veritas\NetBackup\bin\bptm.exe" -w -pid 6840 -c venms01 -den 6 -rt 8 -rn 1 -stunit pmssapp27-hcart-robot-tld-1 -cl NBU_Tape_VENMS01 -bt 1271825531 -b venms01_1271825531 -st 0 -cj 1 -p Monthly -reqid -1271736053 -jm -brm -hostname venms01 -ru root -rclnt venms01 -rclnthostname venms01 -rl 1 -rp 1209600 -sl Full -ct 25 -maxfrag 1048576 -mediasvr pmssapp27 -no_callback -connect_options 0x01010100 -jobid 605 -jobgrpid 604 -masterversion 700000 -bpbrm_shm_id NetBackup_BPBRM_SHM_Path_90963296_6840_932 -blks_per_buffer 128
11:52:18.936 [6840.932] <2> bpbrm create_mm_terminate: created terminate event pid 6536
11:52:18.936 [6840.932] <2> bpbrm create_mm_suspend: created suspend event pid 6536
11:52:18.936 [6840.932] <2> bpbrm write_continue_backup: wrote CONTINUE BACKUP on COMM_SOCK <728>
11:52:18.936 [6840.932] <2> write_file_names: buffering file name 'D:\Domino\data\mail1' for output
11:52:18.936 [6840.932] <2> write_file_names: successfully wrote buffer to COMM_SOCK
11:52:18.936 [6840.932] <2> bpbrm main: wrote CONTINUE on COMM_SOCK
11:52:19.436 [6840.932] <2> bpbrm main: ESTIMATE -1 -1 venms01_1271825531
11:52:19.452 [6840.932] <4> bpbrm main: from client venms01: TRV - object not found for file system backup: Lotus Notes:\D:\Domino\data\mail1
11:52:19.468 [6840.932] <2> bpbrm main: client venms01 EXIT STATUS = 71: none of the files in the file list exist
11:52:19.468 [6840.932] <2> bpbrm kill_child_process_Ex: start
11:52:21.108 [6840.932] <2> bpbrm wait_for_child: start
11:52:21.108 [6840.932] <2> bpbrm wait_for_child: child exit_status = 150
11:52:21.108 [6840.932] <2> inform_client_of_status: INF - Server status = 71
11:52:21.108 [6840.932] <2> put_string: cannot write data to network: An existing connection was forcibly closed by the remote host.
11:52:21.108 [6840.932] <16> inform_client_of_status: could not send server status message
11:52:21.155 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
11:52:21.155 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpjobd
11:52:21.155 [6840.932] <2> job_connect: SO_KEEPALIVE set on socket 744 for client pmssapp27
11:52:21.155 [6840.932] <2> logconnections: BPJOBD CONNECT FROM 128.235.106.171.56670 TO 128.235.106.171.13724
11:52:21.155 [6840.932] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
11:52:21.155 [6840.932] <2> job_connect: Connected to the host pmssapp27 contype 10 jobid <605> socket <744>
11:52:21.155 [6840.932] <2> job_connect: Connected on port 56670
11:52:21.171 [6840.932] <2> job_monitoring_exex: ACK disconnect
11:52:21.171 [6840.932] <2> job_disconnect: Disconnected
11:52:21.171 [6840.932] <2> bpbrm Exit: attempting to send mail to root on venms01
11:52:21.280 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2054: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
11:52:21.280 [6840.932] <2> vnet_vnetd_service_socket: ../../libvlibs/vnet_vnetd.c.2068: service: bpcd
11:52:21.405 [6840.932] <2> logconnections: BPCD CONNECT FROM 128.235.106.171.56672 TO 128.235.106.55.13724
11:52:21.405 [6840.932] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.188: msg: VNETD CONNECT FROM 128.235.106.171.56673 TO 128.235.106.55.13724 fd = 728
11:52:21.468 [6840.932] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.541: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
11:52:21.624 [6840.932] <2> vnet_vnetd_connect_forward_socket_begin: ../../libvlibs/vnet_vnetd.c.558: ipc_string: 3686
11:52:22.171 [6840.932] <2> bpbrm Exit: OUT_SOCK from bpcr = 732
11:52:22.171 [6840.932] <2> bpbrm Exit: IN_SOCK from bpcr = 728
11:52:22.374 [6840.932] <2> bpcr_get_version_rqst: bpcd version: 07000000
11:52:22.577 [6840.932] <2> bpcr_get_version_rqst: bpcd version: 07000000
11:52:23.014 [6840.932] <2> bpcr_get_version_rqst: bpcd version: 07000000
11:52:28.374 [6840.932] <2> bpbrm Exit: client backup EXIT STATUS 71: none of the files in the file list exist
BPTM Log
11:52:19.014 [6536.7068] <2> bptm: instance - 90969890
11:52:19.014 [6536.7068] <2> bptm: INITIATING (VERBOSE = 5): -w -pid 6840 -c venms01 -den 6 -rt 8 -rn 1 -stunit pmssapp27-hcart-robot-tld-1 -cl NBU_Tape_VENMS01 -bt 1271825531 -b venms01_1271825531 -st 0 -cj 1 -p Monthly -reqid -1271736053 -jm -brm -hostname venms01 -ru root -rclnt venms01 -rclnthostname venms01 -rl 1 -rp 1209600 -sl Full -ct 25 -maxfrag 1048576 -mediasvr pmssapp27 -no_callback -connect_options 0x01010100 -jobid 605 -jobgrpid 604 -masterversion 700000 -bpbrm_shm_id NetBackup_BPBRM_SHM_Path_90963296_6840_932 -blks_per_buffer 128
11:52:19.014 [6536.7068] <2> main: bptm.c.1686: maximum fragment size is 1048576000 Kbytes
11:52:19.014 [6536.7068] <2> bptm: PORT_STATUS = 0x01010100
11:52:19.014 [6536.7068] <2> hosts_equal: The second name is empty
11:52:19.014 [6536.7068] <2> hosts_equal: Comparing hosts <pmssapp27> and <pmssapp27>
11:52:19.014 [6536.7068] <2> hosts_equal: names are the same
11:52:19.014 [6536.7068] <2> hosts_equal: Comparing hosts <pmssapp27> and <pmssapp27>
11:52:19.014 [6536.7068] <2> hosts_equal: names are the same
11:52:19.014 [6536.7068] <4> bptm: emmserver_name = pmssapp27
11:52:19.014 [6536.7068] <4> bptm: emmserver_port = 1556
11:52:19.046 [6536.7068] <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)
11:52:19.046 [6536.7068] <2> EndpointSelector::select_endpoint: performing call with the only endpt available!(Endpoint_Selector.cpp:437)
11:52:19.061 [6536.7068] <2> nbjm_media_request: Passing job control to NBJM, type WRITE/1
11:52:19.061 [6536.7068] <2> nbjm_media_request: old_media_id = , media_id = NULL
11:52:19.061 [6536.7068] <2> RequestInitialResources: starting
11:52:19.061 [6536.7068] <2> RequestInitialResources: started
11:52:19.061 [6536.7068] <2> Orb::init: Created anon service name: NB_6536_1998325995(Orb.cpp:612)
11:52:19.061 [6536.7068] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_6536_1998325995(Orb.cpp:630)
11:52:19.061 [6536.7068] <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_6536_1998325995 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:741)
11:52:19.077 [6536.7068] <2> EndpointSelector::select_endpoint: performing call with the only endpt available!(Endpoint_Selector.cpp:437)
11:52:19.093 [6536.7068] <2> packageInitialResourceRequest: started
11:52:19.093 [6536.7068] <2> packageInitialResourceRequest: retVal = 0
11:52:19.093 [6536.7068] <2> RequestInitialResources: setting up callback and calling requestResources
11:52:19.093 [6536.7068] <2> logResourceReq: req.versionId : 1
11:52:19.093 [6536.7068] <2> logResourceReq: req.jobId : -1271736053
11:52:19.093 [6536.7068] <2> logResourceReq: req.startedViaJobManager : true
11:52:19.093 [6536.7068] <2> logResourceReq: req.consumer : true
11:52:19.093 [6536.7068] <2> logResourceReq: InitialSTUSelect -
11:52:19.093 [6536.7068] <2> logResourceReq: reqNum : 0
11:52:19.093 [6536.7068] <2> logResourceReq: preferredMediaServer :
11:52:19.093 [6536.7068] <2> logResourceReq: requiredMediaServer : pmssapp27
11:52:19.093 [6536.7068] <2> logResourceReq: storageUnit : pmssapp27-hcart-robot-tld-1
11:52:19.093 [6536.7068] <2> logResourceReq: mustBeNdmp : false
11:52:19.093 [6536.7068] <2> logResourceReq: getMaxFreeSpace : false
11:52:19.093 [6536.7068] <2> logResourceReq: mediaPool : Monthly
11:52:19.093 [6536.7068] <2> logResourceReq: shareGroup :
11:52:19.093 [6536.7068] <2> logResourceReq: retentionLevel : 1
11:52:19.093 [6536.7068] <2> logResourceReq: mustUseLocalMediaServer : false
11:52:19.093 [6536.7068] <2> logResourceReq: failOnError : false
11:52:19.093 [6536.7068] <2> logResourceReq: mpxRequired : false
11:52:19.093 [6536.7068] <2> logResourceReq: client : venms01
11:52:19.093 [6536.7068] <2> logResourceReq: usageType : 1
11:52:19.093 [6536.7068] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0
11:52:19.093 [6536.7068] <2> resourcesAvailable: m_allocationSeq.length() == 1
11:52:19.093 [6536.7068] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
11:52:19.093 [6536.7068] <2> resourcesAvailable: MEDIADB 1 284 J802L4 4000015 ------ 6 1271133419 1271820612 1273030212 1271300640 482660298 31 31 1 5 0 0 1024 0 5301854 0
11:52:19.093 [6536.7068] <2> resourcesAvailable: VOLUME 1 J802L4 4000015 GJJ802L4 Monthly HP C090825222 6 8 1 18 0 {00000000-0000-0000-0000-000000000000} 0
11:52:19.093 [6536.7068] <2> resourcesAvailable: DRIVE 3 HP.ULTRIUM4-SCSI.001 2000012 HU19376UKU {2,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
11:52:19.093 [6536.7068] <2> resourcesAvailable: STORAGE 1 pmssapp27-hcart-robot-tld-1 6 1048576 2 1 0 0 pmssapp27 pmssapp27 *NULL*
11:52:19.093 [6536.7068] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
11:52:19.093 [6536.7068] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
11:52:19.093 [6536.7068] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
11:52:21.093 [6536.7068] <2> Media_signal_poll: Terminate detected (MultiResReq.cpp:2251)
11:52:21.093 [6536.7068] <2> RequestInitialResources: Cancellation requested
11:52:21.093 [6536.7068] <16> RequestInitialResources: MultiResReq.cpp:2327 resource request failed [150]
11:52:21.093 [6536.7068] <2> RequestInitialResources: Requesting cancellation from jobmgr
11:52:21.093 [6536.7068] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
11:52:21.093 [6536.7068] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
11:52:21.093 [6536.7068] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
11:52:21.093 [6536.7068] <2> packageInitialResourceRequestResult: matched MediaAllocation to an initialStuReq
11:52:21.093 [6536.7068] <2> packageInitialResourceRequestResult: retVal = 0
11:52:21.093 [6536.7068] <16> RequestInitialResources: MultiResReq.cpp:2371 cancel request resourcesAllocated=[1], caller must free resources returned
11:52:21.093 [6536.7068] <2> RequestInitialResources: retVal = 150 emmStatus = 4000008
11:52:21.093 [6536.7068] <2> RequestInitialResources: returning
11:52:21.093 [6536.7068] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 284 J802L4 4000015 ------ 6 1271133419 1271820612 1273030212 1271300640 482660298 31 31 1 5 0 0 1024 0 5301854 0], length 122
11:52:21.093 [6536.7068] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 J802L4 4000015 GJJ802L4 Monthly HP C090825222 6 8 1 18 0 {00000000-0000-0000-0000-000000000000} 0], length 106
11:52:21.093 [6536.7068] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 HP.ULTRIUM4-SCSI.001 2000012 HU19376UKU {2,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0], length 121
11:52:21.093 [6536.7068] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 pmssapp27-hcart-robot-tld-1 6 1048576 2 1 0 0 pmssapp27 pmssapp27 *NULL*], length 82
11:52:21.093 [6536.7068] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
11:52:21.093 [6536.7068] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
11:52:21.093 [6536.7068] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
11:52:21.093 [6536.7068] <2> populateBptmOpaqueStrings: retVal = 0
11:52:21.093 [6536.7068] <4> nbjm_media_request: Error from RequestMultipleResources, Master pmssapp27, error 150, resourceAllocated 1
11:52:21.093 [6536.7068] <2> parse_resource_strings: MEDIADB 1 284 J802L4 4000015 ------ 6 1271133419 1271820612 1273030212 1271300640 482660298 31 31 1 5 0 0 1024 0 5301854 0
11:52:21.093 [6536.7068] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
11:52:21.093 [6536.7068] <2> parse_resource_strings: VOLUME 1 J802L4 4000015 GJJ802L4 Monthly HP C090825222 6 8 1 18 0 {00000000-0000-0000-0000-000000000000} 0
11:52:21.093 [6536.7068] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
11:52:21.093 [6536.7068] <2> parse_resource_strings: DRIVE 3 HP.ULTRIUM4-SCSI.001 2000012 HU19376UKU {2,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
11:52:21.093 [6536.7068] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
11:52:21.093 [6536.7068] <2> parse_resource_strings: STORAGE 1 pmssapp27-hcart-robot-tld-1 6 1048576 2 1 0 0 pmssapp27 pmssapp27 *NULL*
11:52:21.093 [6536.7068] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
11:52:21.093 [6536.7068] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
11:52:21.093 [6536.7068] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
11:52:21.093 [6536.7068] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
11:52:21.093 [6536.7068] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
11:52:21.093 [6536.7068] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
11:52:21.093 [6536.7068] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
11:52:21.093 [6536.7068] <2> nbjm_media_request: Job control returned to BPTM
11:52:21.093 [6536.7068] <4> nbjm_media_request: Shutdown requested
11:52:21.093 [6536.7068] <2> send_MDS_msg: MEDIA_DONE 0 -1271736053 0 J802L4 4000015 0 {D4235D14-6B61-4F41-A339-C85940AA5810}
11:52:21.093 [6536.7068] <2> JobInst::sendIrmMsg: starting
11:52:21.093 [6536.7068] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 -1271736053 0 J802L4 4000015 0 {D4235D14-6B61-4F41-A339-C85940AA5810})
11:52:21.093 [6536.7068] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid -1271736053 copyNum 0 mediaId J802L4 mediaKey 4000015 unloadDelay 0 allocId {D4235D14-6B61-4F41-A339-C85940AA5810}
11:52:21.093 [6536.7068] <2> packageBptmResourceDoneMsg: returns 0
11:52:21.093 [6536.7068] <2> JobInst::sendIrmMsg: returning
11:52:21.093 [6536.7068] <2> mm_terminate: EXITING with status 150
11:52:24.218 [6576.4392] <2> bptm: instance - 90975093
11:52:24.218 [6576.4392] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn HP.ULTRIUM4-SCSI.001 -dp {2,0,2,0} -dk 2000012 -m J802L4 -mk 4000015 -mds 0 -alocid 284 -jobid -1271736054 -jm
11:52:24.218 [6576.4392] <2> bptm: Event NetBackup Terminate Event, pid: 6576 created.
11:52:24.218 [6576.4392] <2> bptm: PORT_STATUS = 0x00000000
11:52:24.218 [6576.4392] <2> hosts_equal: The second name is empty
11:52:24.218 [6576.4392] <2> hosts_equal: Comparing hosts <pmssapp27> and <pmssapp27>
11:52:24.218 [6576.4392] <2> hosts_equal: names are the same
11:52:24.218 [6576.4392] <2> hosts_equal: Comparing hosts <pmssapp27> and <pmssapp27>
11:52:24.218 [6576.4392] <2> hosts_equal: names are the same
11:52:24.218 [6576.4392] <4> bptm: emmserver_name = pmssapp27
11:52:24.218 [6576.4392] <4> bptm: emmserver_port = 1556
11:52:24.249 [6576.4392] <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)
11:52:24.249 [6576.4392] <2> EndpointSelector::select_endpoint: performing call with the only endpt available!(Endpoint_Selector.cpp:437)
11:52:24.264 [6576.4392] <2> send_brm_msg: PID of bpxm = 6576
11:52:24.264 [6576.4392] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
11:52:24.264 [6576.4392] <2> nbjm_media_request: old_media_id = NULL, media_id = J802L4
11:52:24.264 [6576.4392] <2> RequestInitialResources: starting
11:52:24.264 [6576.4392] <2> RequestInitialResources: started
11:52:24.264 [6576.4392] <2> Orb::init: Created anon service name: NB_6576_2016609440(Orb.cpp:612)
11:52:24.264 [6576.4392] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_6576_2016609440(Orb.cpp:630)
11:52:24.264 [6576.4392] <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_6576_2016609440 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:741)
11:52:24.280 [6576.4392] <2> EndpointSelector::select_endpoint: performing call with the only endpt available!(Endpoint_Selector.cpp:437)
11:52:24.280 [6576.4392] <2> packageInitialResourceRequest: started
11:52:24.280 [6576.4392] <2> packageInitialResourceRequest: retVal = 0
11:52:24.280 [6576.4392] <2> RequestInitialResources: setting up callback and calling requestResources
11:52:24.280 [6576.4392] <2> logResourceReq: req.versionId : 1
11:52:24.280 [6576.4392] <2> logResourceReq: req.jobId : -1271736054
11:52:24.280 [6576.4392] <2> logResourceReq: req.startedViaJobManager : true
11:52:24.280 [6576.4392] <2> logResourceReq: req.consumer : true
11:52:24.280 [6576.4392] <2> logResourceReq: InitialMediaSelect -
11:52:24.280 [6576.4392] <2> logResourceReq: reqNum : 0
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.mediaId : J802L4
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.mediaKey : 0
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.mediaServer : pmssapp27
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.userReservationId :
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.assignedTime : 0
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.client :
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.usageType : 6
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.mustBeNdmp : false
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.driveName : HP.ULTRIUM4-SCSI.001
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.drivePath :
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.mediaPool :
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.robotNumber : -1
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.slotNumber : -1
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.density : -1
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.ndmpControlHost :
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.failIfNoMedia : true
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.externalFile :
11:52:24.280 [6576.4392] <2> logMediaRequest: mreq.exp
11:52:24.280 [6576.4392] <2> logMediaRequest: mediaType : -1
11:52:24.280 [6576.4392] <2> logMediaRequest: mediaSubType : -1
11:52:24.280 [6576.4392] <2> logMediaRequest: exp.capabilities
11:52:24.280 [6576.4392] <2> logMediaRequest: isNdmp : 0
11:52:24.280 [6576.4392] <2> logMediaRequest: isTirRestore : 0
11:52:24.280 [6576.4392] <2> logMediaRequest: isFlashbackupRestore : 0
11:52:24.280 [6576.4392] <2> logMediaRequest: isBlockMapRead : 0
11:52:24.280 [6576.4392] <2> logMediaRequest: isCatalogBackup : 0
11:52:24.280 [6576.4392] <2> logMediaRequest: isGcsCatalogBackup : 0
11:52:24.296 [6576.4392] <2> logMediaRequest: preferVtlToDirectAttachedTape : 0
11:52:24.296 [6576.4392] <2> logMediaRequest: isVMWare : 0
11:52:24.296 [6576.4392] <2> logMediaRequest: isLifeCycle : 0
11:52:24.296 [6576.4392] <2> logMediaRequest: useFt : 0
11:52:24.296 [6576.4392] <2> logMediaRequest: failIfNoFt : 0
11:52:24.296 [6576.4392] <2> logMediaRequest: isGranularExchange : 0
11:52:24.296 [6576.4392] <2> logMediaRequest: requestFlags : 0
11:52:24.296 [6576.4392] <2> logMediaRequest: mediaServerAffinityID : 0
11:52:24.296 [6576.4392] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0
11:52:24.296 [6576.4392] <2> resourcesAvailable: m_allocationSeq.length() == 1
11:52:24.296 [6576.4392] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
11:52:24.296 [6576.4392] <2> resourcesAvailable: MEDIADB 1 284 J802L4 4000015 ------ 6 1271133419 1271820612 1273030212 1271300640 482660298 31 31 1 5 0 0 1024 0 5301854 0
11:52:24.296 [6576.4392] <2> resourcesAvailable: VOLUME 1 J802L4 4000015 GJJ802L4 Monthly HP C090825222 6 8 1 18 0 {00000000-0000-0000-0000-000000000000} 0
11:52:24.296 [6576.4392] <2> resourcesAvailable: DRIVE 3 HP.ULTRIUM4-SCSI.001 2000012 HU19376UKU {2,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
11:52:24.296 [6576.4392] <2> resourcesAvailable: STORAGE 1 pmssapp27-hcart-robot-tld-1 6 1048576 2 1 0 0 pmssapp27 pmssapp27 *NULL*
11:52:24.296 [6576.4392] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
11:52:24.296 [6576.4392] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
11:52:24.296 [6576.4392] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
11:52:26.296 [6576.4392] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
11:52:26.296 [6576.4392] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
11:52:26.296 [6576.4392] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
11:52:26.296 [6576.4392] <2> packageInitialResourceRequestResult: matched MediaAllocation to a initialMediaSelect
11:52:26.296 [6576.4392] <2> packageInitialResourceRequestResult: retVal = 0
11:52:26.296 [6576.4392] <2> RequestInitialResources: retVal = 0 emmStatus = 0
11:52:26.296 [6576.4392] <2> RequestInitialResources: returning
11:52:26.296 [6576.4392] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 284 J802L4 4000015 ------ 6 1271133419 1271820612 1273030212 1271300640 482660298 31 31 1 5 0 0 1024 0 5301854 0], length 122
11:52:26.296 [6576.4392] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 J802L4 4000015 GJJ802L4 Monthly HP C090825222 6 8 1 18 0 {00000000-0000-0000-0000-000000000000} 0], length 106
11:52:26.296 [6576.4392] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 HP.ULTRIUM4-SCSI.001 2000012 HU19376UKU {2,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0], length 121
11:52:26.296 [6576.4392] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 pmssapp27-hcart-robot-tld-1 6 1048576 2 1 0 0 pmssapp27 pmssapp27 *NULL*], length 82
11:52:26.296 [6576.4392] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
11:52:26.296 [6576.4392] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
11:52:26.296 [6576.4392] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
11:52:26.296 [6576.4392] <2> populateBptmOpaqueStrings: retVal = 0
11:52:26.296 [6576.4392] <2> parse_resource_strings: MEDIADB 1 284 J802L4 4000015 ------ 6 1271133419 1271820612 1273030212 1271300640 482660298 31 31 1 5 0 0 1024 0 5301854 0
11:52:26.296 [6576.4392] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
11:52:26.296 [6576.4392] <2> parse_resource_strings: VOLUME 1 J802L4 4000015 GJJ802L4 Monthly HP C090825222 6 8 1 18 0 {00000000-0000-0000-0000-000000000000} 0
11:52:26.296 [6576.4392] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
11:52:26.296 [6576.4392] <2> parse_resource_strings: DRIVE 3 HP.ULTRIUM4-SCSI.001 2000012 HU19376UKU {2,0,2,0} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
11:52:26.296 [6576.4392] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
11:52:26.296 [6576.4392] <2> parse_resource_strings: STORAGE 1 pmssapp27-hcart-robot-tld-1 6 1048576 2 1 0 0 pmssapp27 pmssapp27 *NULL*
11:52:26.296 [6576.4392] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
11:52:26.296 [6576.4392] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
11:52:26.296 [6576.4392] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
11:52:26.296 [6576.4392] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
11:52:26.296 [6576.4392] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
11:52:26.296 [6576.4392] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
11:52:26.296 [6576.4392] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
11:52:26.296 [6576.4392] <2> nbjm_media_request: Job control returned to BPTM
11:52:26.296 [6576.4392] <2> drivename_open: Called with Create 1, file HP.ULTRIUM4-SCSI.001
11:52:26.296 [6576.4392] <2> drivename_checklock: Called
11:52:26.296 [6576.4392] <2> drivename_lock: lock established
11:52:26.296 [6576.4392] <4> create_tpreq_file: {2,0,2,0}
11:52:26.296 [6576.4392] <2> drivename_write: Called with mode 2
11:52:26.296 [6576.4392] <2> drivename_unlock: unlocked
11:52:26.296 [6576.4392] <2> drivename_checklock: Called
11:52:26.296 [6576.4392] <2> drivename_lock: lock established
11:52:26.296 [6576.4392] <2> openNTDevice: config_path: {2,0,2,0}, serial_num: HU19376UKU
11:52:26.296 [6576.4392] <2> get_drive_path: SCSI coordinates {2,0,2,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#6&3ab404c2&4&000200#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
11:52:26.311 [6576.4392] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,2,0}, dos_path \\.\Tape1, drive serial number HU19376UKU, expected serial number HU19376UKU
11:52:26.327 [6576.4392] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
11:52:26.327 [6576.4392] <2> really_tpunmount: tpunmount'ing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_HP.ULTRIUM4-SCSI.001
11:52:26.733 [6576.4392] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
11:52:28.733 [6576.4392] <4> report_resource_done: VBRD 1 6576 0 HP.ULTRIUM4-SCSI.001 J802L4
11:52:28.733 [6576.4392] <2> openNTDevice: config_path: {2,0,2,0}, serial_num: HU19376UKU
11:52:28.733 [6576.4392] <2> get_drive_path: SCSI coordinates {2,0,2,0}, dos_path \\.\Tape1, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#6&3ab404c2&4&000200#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
11:52:28.749 [6576.4392] <2> check_serial_num: serial number match for drive with SCSI coordinates {2,0,2,0}, dos_path \\.\Tape1, drive serial number HU19376UKU, expected serial number HU19376UKU
11:52:28.749 [6576.4392] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
11:52:28.764 [6576.4392] <2> tapealert_and_release: SCSI RELEASE
11:52:28.764 [6576.4392] <2> drivename_unlock: unlocked
11:52:28.764 [6576.4392] <2> drivename_close: Called for file HP.ULTRIUM4-SCSI.001
11:52:28.764 [6576.4392] <2> drivename_remove: Called
11:52:28.764 [6576.4392] <2> main: Sending [EXIT STATUS 0] to NBJM
11:52:28.764 [6576.4392] <2> bptm: EXITING with status 0 <----------
11:52:28.764 [6576.4392] <2> bptm: NetBackup Terminate Event, pid: 6576 closed.
Thanks for any help.
Vic