cancel
Showing results for 
Search instead for 
Did you mean: 

Limit has been reached for the logical resource

thickage
Level 3

NetBackup 7.5.0.4, standalone drive (booo!), Win 2008 R2

I have a server (let's call it V01) that is the media server and hosts two other virtual servers on the same physical server (D01 and R01). I have set up a policy to backup D01, R01 and V01 each night. Until recently, all were running smoothly, but V01 now does not get backed up - I get a "Limit has been reached for the logical resource" and the job eventually stops with error 196 as the job window closes and/or tapes are removed from the drive.

I have also attempted to stream this job to physical disk just to ensure it's not a backup media insertion issue. (Sometimes our site forgets to insert tapes daily). Regardless, V01 gets to the "Writing" operation after a tape is mounted, but never begins the write to tape.

Not sure how to proceed.

14 REPLIES 14

Mark_Solutions
Level 6
Partner Accredited Certified

Take a look at the job details tab - it should tell you which resource limit has been reached - MAX something***

Also check if anything has changed - i am guessing you are using multiplexing to run this type of backup so maybe you have added / changed that clients schedule and it does not have the same multiplexing value as the other clients have - or the storage unit itself has been changed?

Give us as much detail as you can for us to pinn down which resourse limit has been exceeded

thickage
Level 3

Here's an example of the failed job and the successful job, launched on the same day. The storage unit has not changed, but recently another tech upgraded from NBU 7.0 to 7.5.0.4. I'm not certain the upgrade is the root cause, but it was shortly thereafter these jobs began to fail. The storage unit has not changed - it's the same internal tape drive that shipped with the unit.

How do I verify multiplexing?

 

THIS JOB FAILED
----------------
1/22/2013 8:20:00 PM - Info nbjm(pid=6620) starting backup job (jobid=4375) for client V01, policy V01_FULL_DAILY, schedule Full 
1/22/2013 8:20:00 PM - Info nbjm(pid=6620) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=4375, request id:{76854EA2-5C20-4F9D-B30D-D2EB0B4B7465}) 
1/22/2013 8:20:00 PM - requesting resource Any
1/22/2013 8:20:00 PM - requesting resource V01.NBU_CLIENT.MAXJOBS.V01
1/22/2013 8:20:00 PM - requesting resource V01.NBU_POLICY.MAXJOBS.V01_FULL_DAILY
1/22/2013 8:20:00 PM - Info nbrb(pid=3396) Limit has been reached for the logical resource V01.NBU_CLIENT.MAXJOBS.V01   
client backup was not attempted because backup window closed(196)


THIS JOB RAN SUCCESSFULLY
-------------------------
1/22/2013 8:10:00 PM - Info nbjm(pid=6620) starting backup job (jobid=4374) for client R01, policy R01_FULL_DAILY, schedule Full 
1/22/2013 8:10:00 PM - Info nbjm(pid=6620) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=4374, request id:{02F6680E-E1CC-47F1-AC38-5A574345DC83}) 
1/22/2013 8:10:00 PM - requesting resource Any
1/22/2013 8:10:00 PM - requesting resource V01.NBU_CLIENT.MAXJOBS.R01
1/22/2013 8:10:00 PM - requesting resource V01.NBU_POLICY.MAXJOBS.R01_FULL_DAILY
1/22/2013 8:10:00 PM - awaiting resource Any - No drives are available
1/22/2013 8:16:34 PM - granted resource V01.NBU_CLIENT.MAXJOBS.R01
1/22/2013 8:16:34 PM - granted resource V01.NBU_POLICY.MAXJOBS.R01_FULL_DAILY
1/22/2013 8:16:34 PM - granted resource A00016
1/22/2013 8:16:34 PM - granted resource IBM.ULTRIUM-HH4.000
1/22/2013 8:16:34 PM - granted resource V01-hcart
1/22/2013 8:16:34 PM - estimated 198262 Kbytes needed
1/22/2013 8:16:34 PM - Info nbjm(pid=6620) started backup (backupid=R01_1358882194) job for client R01, policy R01_FULL_DAILY, schedule Full on storage unit V01-hcart
1/22/2013 8:16:34 PM - started
1/22/2013 8:16:35 PM - started process bpbrm (8560)
1/22/2013 8:16:40 PM - Info bpbrm(pid=8560) R01 is the host to backup data from    
1/22/2013 8:16:40 PM - Info bpbrm(pid=8560) reading file list from client       
1/22/2013 8:16:40 PM - connecting
1/22/2013 8:16:43 PM - Info bpbrm(pid=8560) starting bpbkar32 on client        
1/22/2013 8:16:43 PM - connected; connect time: 00:00:03
1/22/2013 8:16:46 PM - Info bpbkar32(pid=3112) Backup started          
1/22/2013 8:16:46 PM - Info bptm(pid=8112) start           
1/22/2013 8:16:46 PM - Info bptm(pid=8112) using 65536 data buffer size       
1/22/2013 8:16:46 PM - Info bptm(pid=8112) setting receive network buffer to 263168 bytes     
1/22/2013 8:16:46 PM - Info bptm(pid=8112) using 30 data buffers        
1/22/2013 8:16:47 PM - Info bptm(pid=8112) start backup          
1/22/2013 8:16:47 PM - Info bptm(pid=8112) backup child process is pid 6564.6368      
1/22/2013 8:16:47 PM - Info bptm(pid=8112) media id A00016 mounted on drive index 0, drivepath {2,0,3,0}, drivename IBM.ULTRIUM-HH4.000, copy 1
1/22/2013 8:16:47 PM - Info bptm(pid=6564) start           
1/22/2013 8:16:47 PM - mounted
1/22/2013 8:16:47 PM - positioning A00016 to file 52
1/22/2013 8:16:49 PM - positioned A00016; position time: 00:00:02
1/22/2013 8:16:49 PM - begin writing
1/22/2013 8:16:58 PM - Info bpbkar32(pid=3112) change journal NOT enabled for <C:\Users>      
1/22/2013 8:17:37 PM - Info bpbkar32(pid=3112) change journal NOT enabled for <C:\System Volume Information>    
1/22/2013 8:17:48 PM - Info bpbkar32(pid=3112) change journal NOT enabled for <D:\LogAudit>      
1/22/2013 8:17:48 PM - Info bpbkar32(pid=3112) change journal NOT enabled for <D:\Catalog_Backup>      
1/22/2013 8:18:03 PM - Info bpbkar32(pid=3112) change journal NOT enabled for <E:\Officials>      
1/22/2013 8:18:07 PM - Info bptm(pid=8112) waited for full buffer 1155 times, delayed 5013 times   
1/22/2013 8:18:13 PM - Info bptm(pid=8112) EXITING with status 0 <----------       
1/22/2013 8:18:13 PM - Info bpbrm(pid=8560) validating image for client R01       
1/22/2013 8:18:16 PM - Info bpbkar32(pid=3112) done. status: 0: the requested operation was successfully completed   
1/22/2013 8:18:16 PM - end writing; write time: 00:01:27
the requested operation was successfully completed(0)

thickage
Level 3
Additionally, when I try to stop the NetBackup services, it appears to hang when trying to stop the NetBackup Legacy Client Service - I have restarted the server with the client service stopped and performed a repair from add/remove programs, to no avail.

Mark_Solutions
Level 6
Partner Accredited Certified

This is the key line:

1/22/2013 8:10:00 PM - awaiting resource Any - No drives are available

So that means the job has to wait for a drive to be available.

Either the other jobs are taking longer (if they run one at a time) or mutiplexing has been changed - as i suspected.

First open the properties for the tape storage unit - look at the "Enable Multiplexing" - this should be ticked and the maximum streams per drive value set - this should be more than 1 if using multiplexing.

Next, look at each schedule in each policy for the multiplexing value - these should all be the same value (all schedules should use the same value) and should no more than the one of the Storage Unit.

So if you drive is set to three all schedules should also be set to three

Hope this helps

Nathan_Kippen
Level 6
Certified

-deleted-

Mark_Solutions
Level 6
Partner Accredited Certified

Check for UAC, firewall and anti-virus causing programs to hang - you may need a different thread if you are having NetBackup service issues though

Andy_Welburn
Level 6

THIS JOB FAILED
----------------
1/22/2013 8:20:00 PM - Info nbjm(pid=6620) starting backup job (jobid=4375) for client V01, policy V01_FULL_DAILY, schedule Full 
1/22/2013 8:20:00 PM - Info nbjm(pid=6620) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=4375, request id:{76854EA2-5C20-4F9D-B30D-D2EB0B4B7465}) 
1/22/2013 8:20:00 PM - requesting resource Any
1/22/2013 8:20:00 PM - requesting resource V01.NBU_CLIENT.MAXJOBS.V01
1/22/2013 8:20:00 PM - requesting resource V01.NBU_POLICY.MAXJOBS.V01_FULL_DAILY
1/22/2013 8:20:00 PM - Info nbrb(pid=3396) Limit has been reached for the logical resource V01.NBU_CLIENT.MAXJOBS.V01   
client backup was not attempted because backup window closed(196)

 

Seems to me like you already have backup(s) running for this particular client (V01) and it has reached the limit (default?) set in:

NetBackup Management>Host Properties>Master Servers>master>Global Attributes>Maximum jobs per client

Until such time as the first job(s) for this client finish no other jobs can commence.

Altho', it could well be that the reasons highlighted by Mark are actually the underlying problem ....

thickage
Level 3
Thanks for all the replies. I set multiplexing to 3 on both the storage unit and 3 of our policies. I have launched one policy/job for one client, and no other jobs are currently running. In other words, this is the only job running at this time. Still hangs at the "Writing" stage. I am 100% confident if I attempt to backup the R01 or D01 servers using the V01 media server, those clients will backup successfully. It just cannot seem to backup itself! I'm not sure how to check if UAC, firewall and anti-virus causing programs to hang. As mentioned above, the NetBackup Legacy Client service seems to hang if I try to stop all NBU services. JOB LOG - HANGING JOB ---------------------------------------- 1/29/2013 3:16:44 PM - Info bpbrm(pid=6668) starting bptm 1/29/2013 3:16:44 PM - Info bpbrm(pid=6668) Started media manager using bpcd successfully 1/29/2013 3:16:44 PM - Info nbjm(pid=4484) starting backup job (jobid=4442) for client V01, policy V01_FULL_DAILY, schedule Full 1/29/2013 3:16:44 PM - Info nbjm(pid=4484) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=4442, request id:{4A1BB386-ED2E-4F42-9FCA-EFF150852F03}) 1/29/2013 3:16:44 PM - requesting resource V01-hcart 1/29/2013 3:16:44 PM - requesting resource V01.NBU_CLIENT.MAXJOBS.V01 1/29/2013 3:16:44 PM - requesting resource V01.NBU_POLICY.MAXJOBS.V01_FULL_DAILY 1/29/2013 3:16:44 PM - granted resource V01.NBU_CLIENT.MAXJOBS.V01 1/29/2013 3:16:44 PM - granted resource V01.NBU_POLICY.MAXJOBS.V01_FULL_DAILY 1/29/2013 3:16:44 PM - granted resource A00004 1/29/2013 3:16:44 PM - granted resource IBM.ULTRIUM-HH4.000 1/29/2013 3:16:44 PM - granted resource V01-hcart 1/29/2013 3:16:44 PM - estimated 160833728 Kbytes needed 1/29/2013 3:16:44 PM - Info nbjm(pid=4484) started backup (backupid=V01_1359469004) job for client V01, policy V01_FULL_DAILY, schedule Full on storage unit V01-hcart 1/29/2013 3:16:44 PM - started process bpbrm (6668) 1/29/2013 3:16:46 PM - Info bpbrm(pid=6668) V01 is the host to backup data from 1/29/2013 3:16:46 PM - Info bpbrm(pid=6668) telling media manager to start backup on client 1/29/2013 3:16:47 PM - Info bptm(pid=7716) using 65536 data buffer size 1/29/2013 3:16:47 PM - Info bptm(pid=7716) using 12 data buffers 1/29/2013 3:16:48 PM - Info bpbrm(pid=4308) sending bpsched msg: CONNECTING TO CLIENT FOR V01_1359469004 1/29/2013 3:16:48 PM - Info bpbrm(pid=4308) start bpbkar32 on client 1/29/2013 3:16:48 PM - Info bptm(pid=7716) start backup 1/29/2013 3:16:48 PM - Info bptm(pid=7716) Waiting for mount of media id A00004 (copy 1) on server V01. 1/29/2013 3:16:48 PM - connecting 1/29/2013 3:16:48 PM - connected; connect time: 00:00:00 1/29/2013 3:16:48 PM - mounting A00004 1/29/2013 3:16:49 PM - Info bpbkar32(pid=3744) Backup started 1/29/2013 3:16:49 PM - Info bpbrm(pid=4308) Sending the file list to the client 1/29/2013 3:16:49 PM - Info bptm(pid=7716) media id A00004 mounted on drive index 0, drivepath {2,0,3,0}, drivename IBM.ULTRIUM-HH4.000, copy 1 1/29/2013 3:16:49 PM - mounted; mount time: 00:00:01 1/29/2013 3:16:49 PM - positioning A00004 to file 53 1/29/2013 3:17:10 PM - positioned A00004; position time: 00:00:21 1/29/2013 3:17:10 PM - begin writing

Mark_Solutions
Level 6
Partner Accredited Certified

Ok - take a look at your bptm log file on that media server to see what it is saying

You may need to turn logging up to 5, restart the services and run it again to get the information we need but take a look as it is for now

thickage
Level 3
Here's the tail-end of the bptm log; I have not yet turned up logging to 5 (not sure where to adjust that setting yet): 15:44:24.149 [4520.7860] <2> bptm: INITIATING (VERBOSE = 0): -delete_all_expired 15:44:24.149 [4520.7860] <8> vnet_same_host_and_update: [vnet_addrinfo.c:2820] name2 is empty 0 0x0 15:44:24.149 [4520.7860] <4> bptm: emmserver_name = V01 15:44:24.149 [4520.7860] <4> bptm: emmserver_port = 1556 15:44:24.180 [4520.7860] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594) 15:44:24.180 [4520.7860] <2> Orb::init: initializing ORB EMMlib_Orb with: bptm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:825) 15:44:24.180 [4520.7860] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840) 15:44:24.180 [4520.7860] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1481) 15:44:24.180 [4520.7860] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1490) 15:44:24.212 [4520.7860] <2> bptm: EXITING with status 0 <---------- 15:50:48.754 [7072.7368] <2> bptm: INITIATING (VERBOSE = 0): -rptdrv -jobid -1359410547 -jm 15:50:48.754 [7072.7368] <2> drivename_open: Called with Create 0, file IBM.ULTRIUM-HH4.000 15:50:48.754 [7072.7368] <2> drivename_checklock: Called 15:50:48.754 [7072.7368] <2> drivename_checklock: File is locked 15:50:48.754 [7072.7368] <2> report_drives: DRIVE = IBM.ULTRIUM-HH4.000 LOCK = TRUE CURTIME = 1359471048 15:50:48.754 [7072.7368] <2> drivename_close: Called for file IBM.ULTRIUM-HH4.000 15:50:48.754 [7072.7368] <2> report_drives: MODE = 0 15:50:48.754 [7072.7368] <2> report_drives: TIME = 1359469008 15:50:48.754 [7072.7368] <2> report_drives: MASTER = V01 15:50:48.754 [7072.7368] <2> report_drives: SR_KEY = 0 1 15:50:48.754 [7072.7368] <2> report_drives: PATH = {2,0,3,0} 15:50:48.754 [7072.7368] <2> report_drives: MEDIA = A00004 15:50:48.754 [7072.7368] <2> report_drives: REQID = -1359410543 15:50:48.754 [7072.7368] <2> report_drives: ALOCID = 1915 15:50:48.754 [7072.7368] <2> report_drives: RBID = {6F83D30E-D454-4B4A-84CC-8F247FCF9A0A} 15:50:48.754 [7072.7368] <2> report_drives: PID = 7716 15:50:48.754 [7072.7368] <2> report_drives: FILE = C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-HH4.000 15:50:48.754 [7072.7368] <2> main: Sending [EXIT STATUS 0] to NBJM 15:50:48.754 [7072.7368] <2> bptm: EXITING with status 0 <----------

Mark_Solutions
Level 6
Partner Accredited Certified

Go to Host Properties - Media Servers - open up the media server and go to the logging section - the bptm setting is in there.

Nothin obvious in that log that i can spot

If you can put the logging up, rename the existing log file so that a new one get created and then re-run the job

Provide the start and end times (if it ever does end - if not just grab the log once you are happy it is not doing anything) and then post it on here along with the detailed job information

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

Mark_Solutions
Level 6
Partner Accredited Certified

No obvious issues there - mounts the tape, reads the header including the 64kb block size - positions the tape to the correct position successfully ....

It is then waiting for data to come from the client

So if there is an issue it looks like it is the client not the tape drive ... looks like data is just not flowing so check the client for issues (VSS, disk space, hung and orphaned processes etc.)

thickage
Level 3

Thanks, Mark. I'll let you know if I find anything!