Video Screencast Help

Netbackup SLP Duplication Stuck at mounting

Created: 31 Dec 2012 | 10 comments

Hello,

We have been using Netbackup with SLP duplications for over a year with no issues. Suddenly within the last two weeks I am having issues with duplications of SLP duplication from Advanced disk to tape of Exchange GRT backups. This has happened with a regular exchange database and also now a DAG setup. It does not happen for all images though, for the DAG the backup makes mulitple images and others duplicate fine but one seems to get stuck. In the activity monitor all I see is the SLP job with the two duplication jobs (we are copying to two tapes) and they show the operation as mounting. I have left them there for over a day and the state never changes.

This is Netbackup 7.1 running on Windows 2008 R2. We only have one master/media server.

Backing up from Exchange 2010 running on Windows 2008 R2

The job log shows:

30/12/2012 11:45:09 PM - requesting resource LCM_nayul-netbackup-hcart2-robot-tld-0
30/12/2012 11:45:09 PM - granted resource LCM_nayul-netbackup-hcart2-robot-tld-0
30/12/2012 11:45:10 PM - begin Duplicate
30/12/2012 11:45:10 PM - started process RUNCMD (1236)
30/12/2012 11:45:10 PM - ended process 0 (1236)
30/12/2012 11:45:10 PM - requesting resource nayul-netbackup-hcart2-robot-tld-0
30/12/2012 11:45:10 PM - requesting resource nayul-netbackup-hcart2-robot-tld-0
30/12/2012 11:45:10 PM - requesting resource @aaaad
30/12/2012 11:45:10 PM - reserving resource @aaaad
30/12/2012 11:45:10 PM - reserved resource @aaaad
30/12/2012 11:45:10 PM - granted resource 7997L5
30/12/2012 11:45:10 PM - granted resource HP.ULTRIUM5-SCSI.005
30/12/2012 11:45:10 PM - granted resource nayul-netbackup-hcart2-robot-tld-0
30/12/2012 11:45:10 PM - granted resource 7770L5
30/12/2012 11:45:10 PM - granted resource HP.ULTRIUM5-SCSI.003
30/12/2012 11:45:10 PM - granted resource nayul-netbackup-hcart2-robot-tld-0
30/12/2012 11:45:10 PM - granted resource MediaID=@aaaad;DiskVolume=D:\;DiskPool=AdvanceDisk;Path=D:\;StorageServer=nayul-netbackup.na.manwin.local;MediaServer=nayul-netbackup.na.manwin.local

The duplication jobs just show:

30/12/2012 11:45:10 PM - begin Duplicate

This job only started last night since I paused SLP, killed the service so the job stopped and froze the tape it was using because I thought maybe it was an issue with the tape. I had left it run or over a day before that and there was no change. Always in state "mounting"

I am not sure where to look to see what the issue is since I don't know to much about the netbackup log structure. What I do find odd is that the file list is empty (but I read this is normal sometimes until the duplication reaches a certain stage). I do need to find a solution though as the backup is filling up our disk and I can't run others. Also when the image cleanup tries to run it hangs when it reaches this client. I am guessing because it wants the duplication to be done first??

I really need a solution as I need to get these jobs done.

Thank you,

Brent

Comments 10 CommentsJump to latest comment

Nagalla's picture

Always in state "mounting"

i dont think it has a relation with the exchage images.. 

its seems its a issue with the tape drives or with the image..but as your saying its happening only with exchage images.. we would need some testing to make sure this.

1)make a note of tape drives  and tapes being allocated for the exhcange image duplications. and check if those tape drives aer being allocated to any othe jbos and getting successfull or not.

you can directly check those functionlaty by sending the test backup jobs also..

2)try to chage the source location of the exchage backup image and try duplications form new location to tape drive.

 

PS:-do you aware that the Exchage GRT restore are not supported from tapes.?

 

Brentos's picture

Hello,

The tape drives that the image is using was used just before for another backup sucessfully, as was the tape for another backup image in the same set from the DAG. Other images from the DAG set duplicate fine. Just this one is not. I can't really tell why it is stuck since it just says mounting.

I don't have another location to test from as we have a small Netbackup install. Only have one advanced disk.

 

I know GRT doesn't work from tape, if we need to restore we duplicate back from tape and then do the restore. We don't have a large enough advanced disk to keep the backups there.

Brent

Marianne's picture

Check bptm log on master/media server.

If the log folder does not exist, create it in ...veritas\\netbackup\logs.

Also add VERBOSE entry to vm.conf (in ...veritas\volmgr) and restart NBU Device Management service.
Robot mount actions will be logged in Event Viewer Application log and bptm log.

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

Nagalla's picture

 Other images from the DAG set duplicate fine. Just this one is not.

Does this image is having any issues?

did you try verifying the image?

GUI--->catalog -->search the image--->right click on it and select Verify.. --

see the activity moniter for results.

 

Brentos's picture

Hello,

I verified the other image and it is fine. I created the bptm filder and added the verbose and restarted the service. The duplication restarted and I don't see anything in the log file about it or anything in the event manager? I only see this which seems unrelated:

15:25:52.553 [4752.5112] <2> bptm: INITIATING (VERBOSE = 0): -rptdrv -jobid -1356983144 -jm
15:25:52.553 [4752.5112] <2> main: Sending [EXIT STATUS 0] to NBJM
15:25:52.553 [4752.5112] <2> bptm: EXITING with status 0 <----------
15:26:37.266 [1180.5336] <2> bptm: INITIATING (VERBOSE = 0): -delete_all_expired
15:26:37.266 [1180.5336] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2915: 0: name2 is empty: 0 0x00000000
15:26:37.266 [1180.5336] <4> bptm: emmserver_name = nayul-netbackup.na.manwin.local
15:26:37.266 [1180.5336] <4> bptm: emmserver_port = 1556
15:26:37.297 [1180.5336] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -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:824)
15:26:37.297 [1180.5336] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)
15:26:37.360 [1180.5336] <2> bptm: EXITING with status 0 <----------

Is it possible it isn't even asking for the tape? When I ran the verify it did show me the tape mount. Activity monitor does show the drive as mounting though.

Brent

Nagalla's picture

hi could you provide the detail status of the duplicate job?

Brentos's picture

Hello,

 

Is is the same as before

31/12/2012 3:22:53 PM - begin Duplicate
31/12/2012 3:22:53 PM - requesting resource LCM_nayul-netbackup-hcart2-robot-tld-0
31/12/2012 3:22:53 PM - granted resource LCM_nayul-netbackup-hcart2-robot-tld-0
31/12/2012 3:22:53 PM - started process RUNCMD (5276)
31/12/2012 3:22:53 PM - ended process 0 (5276)
31/12/2012 3:22:54 PM - requesting resource nayul-netbackup-hcart2-robot-tld-0
31/12/2012 3:22:54 PM - requesting resource nayul-netbackup-hcart2-robot-tld-0
31/12/2012 3:22:54 PM - requesting resource @aaaad
31/12/2012 3:22:54 PM - reserving resource @aaaad
31/12/2012 3:22:54 PM - reserved resource @aaaad
31/12/2012 3:22:54 PM - granted resource 7997L5
31/12/2012 3:22:54 PM - granted resource HP.ULTRIUM5-SCSI.003
31/12/2012 3:22:54 PM - granted resource nayul-netbackup-hcart2-robot-tld-0
31/12/2012 3:22:54 PM - granted resource 7770L5
31/12/2012 3:22:54 PM - granted resource HP.ULTRIUM5-SCSI.001
31/12/2012 3:22:54 PM - granted resource nayul-netbackup-hcart2-robot-tld-0
31/12/2012 3:22:54 PM - granted resource MediaID=@aaaad;DiskVolume=D:\;

Brent

Marianne's picture

Where exactly do you see 'mounting'?

Seems to me that the resource broker got stuck between identifying and activating resources.
nbrb does not pass job to nbjm which will start bpbrm and bptm on the media server. Only in bptm will we see 'mounting'....

You did not mention your NBU 7.1 patch level?
I seem to remember that basically every 7.1 patch contained nbrb fixes.
You should be on 7.1.0.4 as a minimum.

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

mph999's picture

 

Marianne beat me too it ( as usual ... ;0)  ) ...
 
Need to trace this through the logs ...
 
We can forget nbpem as the job starts and appears in activity monitor.
 
Resorces are found, so we can forget nbemm, and probably nbrb.
 
So this is what should happen (basic view)
 
nbpem starts job > passes to nbjm > nbjm goes to nbrb for resources which it gets from nbemm and passes back to nbjm, at which point the job goes 'active'.
 
I think we should start looking at this point onwards, perhaps it right, perhaps not, but you have to start somewhere,
 
So with the above complete, the following should happen.
 
As I have some exaples from logs I will use these, they are from 6.x but it is close enough to show whats happening (nothing much has changed even at 7.x for this part - perhaps the log lines will look a bit different, but you should still be able to find the line, as the key bits should be the same, eg, the line will show the jobid and the word bpbrm.
 
If nbjm has the resources correctly, you'll see something like this in the nbjm log
 
11/16/08 09:18:30.805 [Debug] NB 51216 nbjm 117 PID:25292 TID:8 File ID:117 [No context] 6 [ResCallback_i::resourcesAvailable] +++ ENTERING +++ : obj = 8dab48 (ResCallback_i.cpp:47)
11/16/08 09:18:30.805 [Diagnostic] NB 51216 nbjm 117 PID:25292 TID:8 File ID:117 [No context] 3 V-117-248 [ResCallback_i::resourcesAvailable] resources available for jobid=jobid=75, reqid={87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE}
11/16/08 09:18:30.806 [Debug] NB 51216 nbjm 117 PID:25292 TID:8 File ID:117 [jobid=75 parentid=75] 6 [JobInstance::resourceAvailable] +++ ENTERING +++ : obj = 960b20 (JobInstance.cpp:187)
11/16/08 09:18:30.809 [Debug] NB 51216 nbjm 117 PID:25292 TID:8 File ID:117 [No context] 4 [ERM_EventData::addToResourceStatusList] (fba7e2f0) resource status, type=13, msg=RESOURCE_GRANTED 1226827110 maintest.NBU_CLIENT.MAXJOBS.maintest
11/16/08 09:18:30.815 [Debug] NB 51216 nbjm 117 PID:25292 TID:8 File ID:117 [jobid=75 reqid=0] 6 [ExportedResourceMgr::determineAllocationType] +++ ENTERING +++ : obj = 9306b8 (ExportedResourceMgr.cpp:618)
11/16/08 09:18:30.816 [Debug] NB 51216 nbjm 117 PID:25292 TID:8 File ID:117 [jobid=75 reqid=0] 4 [ExportedResourceMgr::determineAllocationType] (9306b8) allocation type: Media_Drive_Allocation_Record -- MediaServer=maintest, MediaServerVersion=650000, MediaId=TAPE03, DriveName=HP.C5733A.000, PrimaryPath=/dev/rmt/0cbn, PoolName=Testpool, NdmpControlHost=, RetentionLevel=0(ExportedResourceMgr.cpp:637)
11/16/08 09:18:30.816 [Debug] NB 51216 nbjm 117 PID:25292 TID:8 File ID:117 [jobid=75 reqid=0] 6 [ExportedResourceMgr::determineAllocationType] --- EXITING --- : obj = 9306b8 (ExportedResourceMgr.cpp:618)
11/16/08 09:18:30.818 [Debug] NB 51216 nbjm 117 PID:25292 TID:8 File ID:117 [No context] 4 [ERM_EventData::addToResourceStatusList] (fba7e2f0) resource status, type=13, msg=RESOURCE_GRANTED 1226827110 TAPE03
RESOURCE_GRANTED 1226827110 HP.C5733A.000
RESOURCE_GRANTED 1226827110 maintest-4mm-robot-tl4-0
, usn=0(ExportedResourceMgr.cpp:1982)
 
nbjm should start bpbrm on the media server, just make sure you get the right job id ...
 
[jobid=75 parentid=75] 1 [BackupJob::processProxyResponse] (960b20) Done: create/increment resume image, Next:start BPBRM
 
bpbrm should start, and this will start bptm ....  I don't have an example of this, but it's easy enough to find, I think bpbrm gives the PID of bptm.
 
So, bptm then goes to nbjm to get the allocationed resources ...
 
In bptm log
 
09:18:34.474 [15245] <2> nbjm_media_request: Passing job control to NBJM, type WRITE
09:18:34.477 [15245] <2> RequestInitialResources: starting
09:18:34.477 [15245] <2> RequestInitialResources: started
09:18:34.479 [15245] <2> Orb::init: Created anon service name: NB_15245_1552775538791257(Orb.cpp:600)
09:18:34.479 [15245] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_15245_1552775538791257(Orb.cpp:618)
09:18:34.481 [15245] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory ''" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_15245_1552775538791257 -ORBSvcConf /dev/null -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:725)
09:18:34.565 [15245] <2> packageInitialResourceRequest: started
09:18:34.567 [15245] <2> packageInitialResourceRequest: retVal = 0
09:18:34.567 [15245] <2> RequestInitialResources: setting up callback and calling requestResources
 
 
 
Oh, before I forget, for each chunk of the vx logs (nbjm for ex) the PID and TID should be the same.  What you will see in the logs, are other lines that are to do with different activities, which mixes things up a bit ...
 
The website formatting will wrap the lines round which will make them hard to read, so I suggest downloading a trial copy of TextPad and then copy past into that, as you can rurn off 'linw wrap'.  I recommend textpad for NBU log work, it is so good, that Symantec license it for our own you, it's about $20.
 
Back into nbjm ...
 
11/16/08 09:18:34.585 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportRequest::ExportRequest_1] +++ ENTERING +++ : obj = 864898 (ExportedResource.cpp:1463)
11/16/08 09:18:34.585 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportRequest::ExportRequest_1] --- EXITING --- : obj = 864898 (ExportedResource.cpp:1463)
11/16/08 09:18:34.586 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 4 [ExportRequest::getName] (864898) request has no name(ExportedResource.cpp:1822)
11/16/08 09:18:34.586 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=0 reqid=-1226681332] 6 [ExportedResourceMgr::findExported_1] +++ ENTERING +++ : obj = 9341b8 (ExportedResourceMgr.cpp:540)
11/16/08 09:18:34.586 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResourceMediaDrive::matchRequest] +++ ENTERING +++ : obj = 857b10 (ExportedResource.cpp:896)
11/16/08 09:18:34.586 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 4 [ExportedResourceMediaDrive::matchRequest] (857b10) matching request InitialStuSelectCriteria: reqNum=0, preferredMediaServer=, requiredMediaServer=maintest(ExportedResource.cpp:938)
11/16/08 09:18:34.586 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 4 [ExportedResourceMediaDrive::matchRequest] (857b10) matched InitialStuSelectCriteria(ExportedResource.cpp:964)
11/16/08 09:18:34.587 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResourceMediaDrive::matchRequest] --- EXITING --- : obj = 857b10 (ExportedResource.cpp:896)
11/16/08 09:18:34.587 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=0 reqid=-1226681332] 4 [ExportedResourceMgr::findExported_1] (9341b8) matched request with an exported resource, type=12, reqNum=0(ExportedResourceMgr.cpp:547)
11/16/08 09:18:34.587 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=0 reqid=-1226681332] 6 [ExportedResourceMgr::findExported_1] --- EXITING --- : obj = 9341b8 (ExportedResourceMgr.cpp:540)
11/16/08 09:18:34.587 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResourceMediaDrive::appendResourceAvailable] +++ ENTERING +++ : obj = 857b10 (ExportedResource.cpp:861)
11/16/08 09:18:34.588 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 4 [ExportedResourceMediaDrive::appendResourceAvailable] available resource MediaDriveResource: MasterServer=None
                    MediaServer=None
                    MediaServerVersion=650000
                    MediaServerClusterName=None
                    MediaId=None
                    MediaKey=4000046
                    DriveKey=2000004
                    DriveName=None
                    PrimaryPath=None
                    SerialNumber=None
                    PoolName=None
                    NdmpControlHost=
                    NdmpUserName=
                    NdmpPassword=
                    NdmpPasswordKey=
                    NdmpClientUserName=
                    NdmpClientPassword=
                    NdmpClientPasswordKey=
                    RetentionLevel=0
                    PolicyType=2
                    JobType=1
 
 exportable = 0 requestId = {87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE} JMowned = 1 Allocation -- id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE}, usn=0, groupId={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE}, provider=MPXProvider, resourcename=maintest-4mm-robot-tl4-0, userAllocationId=jobid=75, masterServer=maintest(ExportedResource.cpp:887)
11/16/08 09:18:34.589 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResourceMediaDrive::appendResourceAvailable] --- EXITING --- : obj = 857b10 (ExportedResource.cpp:861)
 
 
Next, it bptm we should see confirmation of resources ...
 
... And just after this in bptm we can see confirmation of resources ...
 
09:18:34.605 [15245] <2> RequestInitialResources: BpxmiV->requestResources returns 0
09:18:34.619 [15245] <2> resourcesAvailable: m_allocationSeq.length() == 1
09:18:34.620 [15245] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 8
09:18:34.620 [15245] <2> resourcesAvailable: MEDIADB 1 40 TAPE03 4000046 ------ 12 1226827110 0 0 0 0 0 0 0 5 0 0 0 0 0 0
09:18:34.620 [15245] <2> resourcesAvailable: VOLUME 1 TAPE03 4000046 -------- Testpool *NULL* *NULL* 9 7 0 4 0 {00000000-0000-0000-0000-000000000000} 0
09:18:34.621 [15245] <2> resourcesAvailable: DRIVE 3 HP.C5733A.000 2000004 0000730089 /dev/rmt/0cbn -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 0 0 1 0 0
09:18:34.621 [15245] <2> resourcesAvailable: STORAGE 1 maintest-4mm-robot-tl4-0 12 1048576 2 1 0 0 maintest maintest *NULL*
09:18:34.621 [15245] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
09:18:34.621 [15245] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
09:18:34.621 [15245] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
09:18:34.621 [15245] <2> resourcesAvailable: FTRANS 0 0 6 *NULL* 6 *NULL* 0 0 0
 
 
still in bptm ... setup shared memory
 
09:18:34.637 [15245] <2> nbjm_media_request: Job control returned to BPTM
09:18:34.637 [15245] <2> setup_twin_parameters: bptm.c.3856: maximum fragment size is 1048576000 Kbytes
09:18:34.638 [15245] <2> validate_parameters: tmcommon.c.4847: maximum fragment size is 1048576000 Kbytes
09:18:34.638 [15245] <2> io_init: using 65536 data buffer size
09:18:34.638 [15245] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 60000
09:18:34.639 [15245] <2> io_set_recvbuf: receive network buffer is 49152 bytes
09:18:34.639 [15245] <2> io_init: using 30 data buffers
09:18:34.639 [15245] <2> io_init: child delay = 10, parent delay = 15 (milliseconds)
09:18:34.642 [15245] <2> create_shared_memory: shm_size = 1966808, buffer address = 0xfca00000, buf control = 0xfcbe0000, ready ptr = 0xfcbe02d0
09:18:34.644 [15245] <2> setup_bpbkar_info: /usr/openv/netbackup/db/config/shm/maintest_1226827110 file successfully created
 
 
09:18:35.298 [15245] <2> mount_open_media: Waiting for mount of media id TAPE03 (copy 1) on server maintest.
09:18:35.305 [15245] <4> create_tpreq_file: symlink to path /dev/rmt/0cbn
09:18:35.308 [15245] <2> manage_scsi_reserve: SCSI RESERVE
09:18:35.310 [15245] <4> expandpath: /usr/openv/netbackup/db/media/tpreq/drive_HP.C5733A.000
09:18:35.841 [15245] <2> tapelib: wait_for_ltid, Mount, timeout 0
 
Next, ltid will actually get the tape mounted ...
 
(/usr/openv/volmgr/debug/ltid )
 
... this actually mounts the tape 
 
 
09:18:35.840 [25264] <4> LtidProcCmd: Pid=15245, Data.Pid=15245, Type=12, Param1=0, Param2=0, LongParam=0
09:18:35.840 [25264] <4> tpreq: User tape request: EVSN:TAPE03 RVSN: Drive:HP.C5733A.000 Path:/dev/rmt/0cbn AttachHost:
09:18:35.840 [25264] <4> IssueMount: Index = 0, pid =0, removemount = 0, signalopr = 1
09:18:35.840 [25264] <4> IssueMount: mounting on drive HP.C5733A.000 path /dev/rmt/0cbn
09:18:35.840 [25264] <4> IssueMount: Found drive HP.C5733A.000 at index 0.  Override path with /dev/rmt/0cbn, 
09:18:35.840 [25264] <4> IssueMount: Sending ROBOT_MOUNT request
09:18:35.840 [25264] <4> SendRobotReq: ROBOT_MOUNT request found
09:18:35.840 [25264] <4> SendRobotReq: Found drive name and path specified HP.C5733A.000: /dev/rmt/0cbn 
09:18:35.841 [25264] <2> SendRobotReq: LTID - Sent ROBOTIC request, Type=1, Param2=0
09:19:34.510 [25264] <2> ProcessRobotMsg: LTID - received ROBOT MESSAGE, Type=54, LongParam=0, Param1=0, Param2=0
09:19:34.510 [25264] <4> create_tpreq_file: symlink to path /dev/rmt/0cbn
09:19:34.623 [25264] <4> emmlib_UpdateMountStat: (0) UPDATE_MNT_STAT returned 0
09:19:34.623 [25264] <6> WriteEntry: Updating drive HP.C5733A.000 at path /dev/rmt/0cbn on attach host 
 
 
BPTM now ges on with writing the backup ...
 
09:19:35.131 [15245] <2> io_open: SCSI RESERVE
09:19:35.134 [15245] <2> io_open: report_attr, fl1 0x00000801, fl2 0x00000000
09:19:35.136 [15245] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_HP.C5733A.000 successfully opened (mode 2)
09:19:35.137 [15245] <2> write_backup: media id TAPE03 mounted on drive index 0, drivepath /dev/rmt/0cbn, drivename HP.C5733A.000, copy 1
09:19:35.138 [15245] <2> io_read_media_header: drive index 0, reading media header, buflen = 65536, buff = 0x627d40, copy 1
09:19:35.138 [15245] <2> io_ioctl: command (5)MTREW 1 from (bptm.c.8053) on drive index 0
09:19:35.150 [15245] <2> io_write_media_header: drive index 0, writing media header
09:19:35.150 [15245] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_HP.C5733A.000, from bptm.c.9293
09:19:35.151 [15245] <2> io_open: SCSI RESERVE
09:19:35.153 [15245] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_HP.C5733A.000 successfully opened (mode 2)
09:19:35.153 [15245] <2> io_ioctl: command (5)MTREW 1 from (bptm.c.9298) on drive index 0
09:19:35.562 [15245] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.9339) on drive index 0
09:19:46.562 [15245] <2> io_write_media_header: report_density, 0x24 [ UNKNOWN UNKNOWN]
09:19:46.562 [15245] <2> send_MDS_msg: VOL_UPDATE 0 40 TAPE03 4000046 *NULL* *NULL* 4 36
09:19:46.625 [15245] <2> emmlib_handleMessage: (0) CORBA call returned 0
09:19:46.626 [15245] <2> send_MDS_msg: MEDIADB 1 40 TAPE03 4000046 *NULL* 12 1226827110 1226827110 1227431910 0 0 0 0 0 5 0 0 1024 0 0 0
09:19:46.722 [15245] <2> emmlib_handleMessage: (0) CORBA call returned 0
09:19:46.723 [15245] <2> db_error_add_to_file: dberrorq.c:midnite = 1226793600
09:19:46.724 [15245] <4> write_backup: begin writing backup id maintest_1226827110, copy 1, fragment 1, to media id TAPE03 on drive index 0
09:19:46.725 [15245] <2> signal_parent: sending SIGUSR1 to bpbrm (pid = 15239)
 
 
So ... there you are - you should have enough info there to be able to find out, if the process stops at some point, where abouts this is, as you have example llines of what should happen.
 
Other thing, when running vxlogview, always use -d all  option.
 
Martin

 

Regards,  Martin
 
Setting Logs in NetBackup:
http://www.symantec.com/docs/TECH75805
 
cviniciusm's picture

Hello,

I'm trying staging using "multiple copies" feature on Exchange 2010 DAG (GRT + Dedup by MSDP) schedule.

I got:

"27/05/2013 22:36:56 - Error bpbrm(pid=1788) Granular backups must go to a disk based storage unit before moving to a removable media based storage unit

27/05/2013 22:37:00 - end writing

storage unit characteristics mismatched to request(154)"

The source copy was msdp storage unit; the secondary one was tape.

I'll try the reverse.