Netbackup SLP Duplication Stuck at mounting

[Brentos]

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

[RamNagalla]

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]

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]

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.

[RamNagalla]

 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]

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

[RamNagalla]

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

[Brentos]

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]

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.

[mph999]

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

[cviniciusm]

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.