Video Screencast Help

Limit has been reached for the logical resource

Created: 28 Jan 2013 | 14 comments

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.

Comments 14 CommentsJump to latest comment

Mark_Solutions's picture

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

Authorised Symantec Consultant

Don't forget to "Mark as Solution" if someones advice has solved your issue - and please bring back the Thumbs Up!!.

thickage's picture

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's picture

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.

Nathan Kippen's picture

-deleted-

Symantec Certified Specialist
(NBU 7.5.0.6)
Don't forget to vote or mark solution!

Mark_Solutions's picture

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

Authorised Symantec Consultant

Don't forget to "Mark as Solution" if someones advice has solved your issue - and please bring back the Thumbs Up!!.

Mark_Solutions's picture

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

Authorised Symantec Consultant

Don't forget to "Mark as Solution" if someones advice has solved your issue - and please bring back the Thumbs Up!!.

Andy Welburn's picture

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's picture

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's picture

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

Authorised Symantec Consultant

Don't forget to "Mark as Solution" if someones advice has solved your issue - and please bring back the Thumbs Up!!.

thickage's picture

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's picture

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

Authorised Symantec Consultant

Don't forget to "Mark as Solution" if someones advice has solved your issue - and please bring back the Thumbs Up!!.

thickage's picture

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's picture

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.)

Authorised Symantec Consultant

Don't forget to "Mark as Solution" if someones advice has solved your issue - and please bring back the Thumbs Up!!.