Backup Process

punbs · ‎05-15-2012

Help me out??

If i take some files backup using netbackup tool. how the process will execute. which are all services will help and how.

regards,

Puneeth

mph999 · ‎05-15-2012

Puneeth,

The troubleshooting guides give detaised info on the processes,

If a scheduled job, nbpem has alreadt obtained the policy info from bpdbm, via nbproxy, when it started, it therefore knows when to start the job.

nbpem commnicates with nbjm to start job

nbjm initiates backup job via bpjobd - job is added to jobs database, it should know appear as queued in the activity monitor.

nbjm requests resources from nbrb.

nbrb gets the resources (eg tapes/ drives/ storage units) from nbemm

nbemm marks these resourse as reserved.

nbrb tells nbjm that the resources are available

nbjm sends message to bppjobd and jobs goes Active in activity monitor

nbjm communicates to with the media server to start bpbrm

bpbrm starts bpbkar on the client

bpbrm starts bptm on the media server

bptm issues a scsi reserve to the drives, then issues a mount request to ltid

ltid forwards a robotic mount request to the robot via (for example ) tld. This sends a request to tldcd to communicate with the robot to load the tape. Once done, ltid updates nbemm and bptm

bptm can then open a path to the drive to start writing data

bpbkar send into about the files to bpbrm which communicates with bpdbm to update the NBU catalog

bpkar sends the files to be backed up to bptm, which sends it to memory (buffer). bptm sends the data from memory to the operatings system that writes it to tape.

when job complete, bpbrm sends job complete message to nbjm

nbjm updates bpjobd so activity monitor shows jobs as done.

nbjm also triggers the release of resources for completed jobs, notifying nbrb by writing in the job progress log. bptm starts job to unload drive

nbjm will report the job exit status to nbpem who will then recalculate the next due time of the job.

Regards,

Martin

Marianne · ‎05-15-2012

If you need a graphical view of the processes in Martin's excellent explanation, please have a look at Appendix A of the Troubleshooting Guide: http://www.symantec.com/docs/DOC3683

I have also added a pdf version.

Handy NetBackup Links

Yogesh9881 · ‎05-15-2012

But how you got this stuff ..? is it your own created ?

Marianne · ‎05-15-2012

No! I'm not that clever!

The advantage of working in this industry for 13 years is that you make friends in the right places!

A NBU trainer found it after I complained that process flow is no longer part of the NBU training. I asked that it be handed out to all trainees.

Handy NetBackup Links

mph999 · ‎05-15-2012

This is an example of a backup job logs at NBU 6.5.1

I've not bothered re-doing it for 7.x as this is 'close enough' and I've not had time.

It isn't every single log/step, but the main bits to give an overview of the main parts, in order of what happens.

NBPEM receives notification of immediate manual backup ...

11/16/08 09:18:28.860 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 6 [JobDefinition::setJobId] +++ ENTERING +++ : obj = 5b73e0 (JobDefinition.cpp:1314)

11/16/08 09:18:28.860 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 1 [JobDefinition::setJobId] setting jobid=75(JobDefinition.cpp:1315)

11/16/08 09:18:28.860 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 1 [JobDefinition::setJobId] jobid=75(JobDefinition.cpp:1330)

11/16/08 09:18:28.861 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 6 [JobDefinition::setJobId] --- EXITING --- : obj = 5b73e0 (JobDefinition.cpp:1314)

11/16/08 09:18:28.861 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 4 [JobScheduler::submitbackup] setup job definitions jobid=75, stream number=0, parent jobid=-1(JobScheduler.cpp:2251)

... retreives policy details ...

11/16/08 09:18:28.911 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 1 [?] >>>>>>>>>>>>BACKUP JOB>>>>>>>>>>>>>

11/16/08 09:18:28.912 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 1 [?] >> Start JOBID jobid=75 Parent id=-1 policy=test1 client=maintest schedule =Full

11/16/08 09:18:28.912 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 1 [?] >> stream # = 0 runonce = 0 try = 0 (SB) time = Sun Nov 16 09:18:28 2008

11/16/08 09:18:28.912 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 1 [?] >> window close time = Sun Nov 16 15:00:00 2008 bprdpid=0

11/16/08 09:18:28.912 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 1 [?] >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

11/16/08 09:18:28.913 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 6 [JobScheduler::printjinfo] +++ ENTERING +++ : obj = ffbff830 (JobScheduler.cpp:5306)

11/16/08 09:18:28.913 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] --------Job Submission Information-------------

11/16/08 09:18:28.913 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] Jobid, grpid, try = 75, 75, 1

11/16/08 09:18:28.913 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] Policy name = test1

11/16/08 09:18:28.914 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] Client type = 0

11/16/08 09:18:28.914 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] jobSubType = 0

11/16/08 09:18:28.914 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] proxyCopy = no

11/16/08 09:18:28.914 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] nasFiler = none

11/16/08 09:18:28.914 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] max job/policy = 2147483647

11/16/08 09:18:28.914 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] max job/client = 1

11/16/08 09:18:28.915 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] follow NFS mnts = no

11/16/08 09:18:28.915 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] client compress = no

11/16/08 09:18:28.915 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] client encrypt = 0

11/16/08 09:18:28.915 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] cross mount pts = no

11/16/08 09:18:28.915 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] priority = 0

11/16/08 09:18:28.915 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] overdue = 757935392

11/16/08 09:18:28.916 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] maxfragsize = 0

11/16/08 09:18:28.916 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] collectBmr = no

11/16/08 09:18:28.916 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] block incr = no

11/16/08 09:18:28.916 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] extsecurity = no

11/16/08 09:18:28.916 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] keyword =

11/16/08 09:18:28.916 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] ifrfr = no

11/16/08 09:18:28.917 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] streaming = no

11/16/08 09:18:28.917 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] backupCopy = 0

11/16/08 09:18:28.917 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] frozenImage = no

11/16/08 09:18:28.917 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] checkpoint = no

11/16/08 09:18:28.917 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] chk point interval= 0

11/16/08 09:18:28.917 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] pfi enabled = no

11/16/08 09:18:28.918 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] off host backup = no

11/16/08 09:18:28.918 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] use alt clnt = no

11/16/08 09:18:28.918 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] isVMWare = no

11/16/08 09:18:28.918 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] use data mvr = no

11/16/08 09:18:28.918 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] snap shot mthd =

11/16/08 09:18:28.919 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] monitor clnt job = no

11/16/08 09:18:28.919 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] progress log =

11/16/08 09:18:28.919 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] english logs = no

11/16/08 09:18:28.919 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] Ckpt Disable = false

11/16/08 09:18:28.919 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] isGranularRestore = false

11/16/08 09:18:28.919 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] client name = maintest

11/16/08 09:18:28.920 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] schedule name = Full

11/16/08 09:18:28.921 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] schedule type = 0

11/16/08 09:18:28.921 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] max mpx = 1

11/16/08 09:18:28.921 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] synthetic = no

11/16/08 09:18:28.921 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] fast recovery = no

11/16/08 09:18:28.921 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] isLifeCycle = no

11/16/08 09:18:28.922 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] dataClassName =

11/16/08 09:18:28.922 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] storageServiceName=

11/16/08 09:18:28.922 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] # copies = 0

11/16/08 09:18:28.922 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] minHoursPrepro = 0

11/16/08 09:18:28.922 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] streamDiscovery = no

11/16/08 09:18:28.922 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] filerDiscovery = no

11/16/08 09:18:28.923 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] bmrSave = no

11/16/08 09:18:28.923 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] stu 0 = maintest-4mm-robot-tl4-0 pool = Testpool shareGroup = *ANY* retention = 0 period = 604800 fail = No local = No

11/16/08 09:18:28.923 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] options = 0

11/16/08 09:18:28.923 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] namedResource = NONE

11/16/08 09:18:28.923 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] resourceSelection = 0

11/16/08 09:18:28.924 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] restartSelection = 0

11/16/08 09:18:28.924 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] diskFull = 0

11/16/08 09:18:28.924 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] last backup time = 0

11/16/08 09:18:28.924 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] snapshot time = 0

11/16/08 09:18:28.924 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] dump level = 0

11/16/08 09:18:28.925 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] bli backup = no

11/16/08 09:18:28.925 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] prevBlkIncrTime = 0

11/16/08 09:18:28.925 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] blkIincrFullTime = 0

11/16/08 09:18:28.925 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] user name = root

11/16/08 09:18:28.925 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] group name = root

11/16/08 09:18:28.925 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] stream number = 0

11/16/08 09:18:28.926 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] number of streams = 1

11/16/08 09:18:28.926 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] client verbose = no

11/16/08 09:18:28.926 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] tir type = 0

11/16/08 09:18:28.926 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] media mount timeout = 0

11/16/08 09:18:28.926 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] connectOptions = 16974338

11/16/08 09:18:28.926 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] estimated size = 0

11/16/08 09:18:28.927 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] estimated files = 0

11/16/08 09:18:28.927 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [parent_jobid=-1,clientname=maintest,type=4] 2 [?] opaquestring = -use_ofb -use_otm

11/16/08 09:18:28.927 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 6 [JobScheduler::printjinfo] --- EXITING --- : obj = ffbff830 (JobScheduler.cpp:5306)

... submits to queue

11/16/08 09:18:28.927 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 6 [SubmitQueue::StartJob] +++ ENTERING +++ : obj = 58a560 (SubmitQueue.cpp:85)

11/16/08 09:18:28.928 [Debug] NB 51216 nbpem 116 PID:25297 TID:1 File ID:116 [No context] 1 [SubmitQueue::StartJob] jobid=75 queued(SubmitQueue.cpp:89)

11/16/08 09:18:28.928 [Debug] NB 51216 nbpem 116 PID:25297 TID:4 File ID:116 [No context] 6 [SubmitQueue::handle_exception] +++ ENTERING +++ : obj = 58a560 (SubmitQueue.cpp:60)

11/16/08 09:18:28.929 [Debug] NB 51216 nbpem 116 PID:25297 TID:4 File ID:116 [No context] 6 [SubmitQueue::processQueue] +++ ENTERING +++ : obj = 58a560 (SubmitQueue.cpp:279)

11/16/08 09:18:28.929 [Debug] NB 51216 nbpem 116 PID:25297 TID:4 File ID:116 [No context] 6 [SubmitQueue::processMsgQue] +++ ENTERING +++ : obj = 58a560 (SubmitQueue.cpp:744)

11/16/08 09:18:28.929 [Debug] NB 51216 nbpem 116 PID:25297 TID:4 File ID:116 [No context] 6 [SubmitQueue::processMsgQue] --- EXITING --- : obj = 58a560 (SubmitQueue.cpp:744)

11/16/08 09:18:28.929 [Debug] NB 51216 nbpem 116 PID:25297 TID:4 File ID:116 [No context] 6 [SubmitQueue::processExResQue] +++ ENTERING +++ : obj = 58a560 (SubmitQueue.cpp:804)

11/16/08 09:18:28.929 [Debug] NB 51216 nbpem 116 PID:25297 TID:4 File ID:116 [No context] 6 [SubmitQueue::processExResQue] --- EXITING --- : obj = 58a560 (SubmitQueue.cpp:804)

11/16/08 09:18:28.930 [Debug] NB 51216 nbpem 116 PID:25297 TID:4 File ID:116 [No context] 6 [SubmitQueue::processStartQue] +++ ENTERING +++ : obj = 58a560 (SubmitQueue.cpp:322)

NBJM

****

nbpem send through details to nbjm about job

Initial link between the two processes seems to be the jobid ( jobid = 75 ).

11/16/08 09:18:28.933 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [JobManager_i::submitBackupJob] +++ ENTERING +++ : obj = 8ffde8 (JobManager_i.cpp:117)

11/16/08 09:18:28.934 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 1 [JobManager_i::submitBackupJob] (8ffde8) jobid=75, tryNumber=1, resubmitType=0, getMaxFreeSpace=false, isStdBackup=true, resourceSelection=0(JobManager_i.cpp:124)

11/16/08 09:18:28.934 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [JMUtility::dumpJobDefn] jobid=75 tryNumber=1 backupType=JTYPE_BACKUP jobSubType=0 jobGroupId=75 submissionType=JBACKTYPE_SCHEDULED jobid=75 policyName=test1 clientType=Standard maxJobsPerPolicy=2147483647 maxJobsPerClient=1 followNFSMounts=false clientCompress=false priority=0 clientEncrypt=0 crossMountPoints=false maxFragSize=0 blockIncr=false keyword= extSecInfo=false ifrfr=false streaming=false backupCopy=0 frozenImage=false numberOfCopies=0 checkpoint=false checkpointInterval=0 pfiEnabled=false offhostBackup=false useAltClient=false isVMWare=false useDataMover=false altClientName= monitorClientJob=false progressLogPath= englishLogs=false snapshotMethod= collectBMRInfo=false(JMUtility.cpp:877)

11/16/08 09:18:28.935 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [JMUtility::dumpJobDefn] jobid=75 dataClassificationName= storageServiceName= isLifeCycle=false isGranularRestore=false SchedRec (1) label=Full, type=0, maxMpx=1, frequency=86400, synthetic=false, fastRecovery=false ClientRec (1) hostname=maintest, hardware=Solaris, os=Solaris10 minHoursPrepro=0 streamDiscovery=false filerDiscovery=false bmrSave=false spsv2FeClientName= clientName=maintest catalogedName= schedName=Full schedtype=ST_FULL schedmaxMpx=1 schedsynthetic=false schedfastRecovery=false resourceSelection=STANDARD_RESOURCE restartResourceSelection=STANDARD_RESOURCE(JMUtility.cpp:926)

11/16/08 09:18:28.935 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [JMUtility::dumpJobDefn] jobid=75 requiredResources (copy 1) stuName=maintest-4mm-robot-tl4-0, poolName=Testpool, shareGroup=*ANY*, clientName=maintest, retention=0, retentionPeriod=604800, failOnError=false, useLocal=false lastSnapshotTime=0:00:00 lastBackupTime=0:00:00 overdueTime=757935392 dumpLevel=0 user=root group=root numOfStreams=1 streamNum=0 clientVerbose=false tirType=0 proxy=false nasFiler= frozenImageTime=0:00:00 opaqueString=-use_ofb -use_otm synchronous=false checkpointDisabled=false bliBackup=false prevBlkIncrTime=0:00:00 blkIncrFullTime=0:00:00 namedResource=NONE catalogBackup=false mediaMountTimeout=0:00:00 connectOptions=16974338 estimatedSize=0 estimatedFileCount=0 /etc/hosts(JMUtility.cpp:980)

11/16/08 09:18:28.936 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [DelayedBackupJob::~DelayedBackupJob] +++ ENTERING +++ : obj = 90ae70 (DelayedJob.cpp:50)

11/16/08 09:18:28.936 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [DelayedBackupJob::~DelayedBackupJob] --- EXITING --- : obj = 90ae70 (DelayedJob.cpp:50)

11/16/08 09:18:28.939 [Application] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] [Info] V-117-85 started backup job (jobid=75) for client maintest, policy test1, schedule Full

... few details including job attempt number ...

11/16/08 09:18:28.944 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::BackupJob] (960b20) job try=1, restartable=true, suspendable=false, resumable=false(BackupJob.cpp:206)

... job is added to job map

11/16/08 09:18:28.948 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 4 [JobMapper::createJob] (7206a0) job jobid=75 added to job map(JobMapper.cpp:714)

NBJM now starts to sort out resourses, starting something like this ...

11/16/08 09:18:28.953 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 6 [BackupJob::buildStuRequest] +++ ENTERING +++ : obj = 960b20 (BackupJob.cpp:715)

11/16/08 09:18:28.953 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 4 [getEmmJobType] NB jobtype=0, write=1, EMM jobtype=1(JMUtility.cpp:177)

11/16/08 09:18:28.953 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::buildStuRequest] (960b20) STU=maintest-4mm-robot-tl4-0, POOL=Testpool, RET LVL=0, LOCAL=false, CLIENT=maintest, JOB_TYPE=1, POLICY_TYPE=false, ESTIMATED_SIZE=0(BackupJob.cpp:754)

11/16/08 09:18:28.953 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::buildStuRequest] (960b20) SHAREGROUP=*ANY*(BackupJob.cpp:836)

11/16/08 09:18:28.954 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::buildStuRequest] (960b20) STUSUBTYPE=-1(BackupJob.cpp:847)

11/16/08 09:18:28.954 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::buildStuRequest] (960b20) capabilities.isNdmp=false, capabilities.isGcsCatalogBackup=false, capabilities.isCatalogBackup=false, capabilities.isVMWare=false, capabilities.isLifeCycle=false(BackupJob.cpp:859)

11/16/08 09:18:28.954 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 6 [BackupJob::buildStuRequest] --- EXITING --- : obj = 960b20 (BackupJob.cpp:715)

11/16/08 09:18:28.955 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::buildAndSubmitResourceRequestToRB] (960b20) max mpx=1(BackupJob.cpp:509)

11/16/08 09:18:28.955 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::buildAndSubmitResourceRequestToRB] (960b20) requesting counted resource(BackupJob.cpp:598)

11/16/08 09:18:28.955 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::buildAndSubmitResourceRequestToRB] (960b20) max jobs per client=1(BackupJob.cpp:614)

11/16/08 09:18:28.956 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::buildAndSubmitResourceRequestToRB] (960b20) max jobs per policy=2147483647, policy=test1(BackupJob.cpp:641)

11/16/08 09:18:28.956 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 6 [BackupJob::sendRequestToRB] +++ ENTERING +++ : obj = 960b20 (BackupJob.cpp:678)

... here we see a JMRequestID - this is traceable through to the next process - nbrb

11/16/08 09:18:28.956 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [JobMapper::getRequestId] +++ ENTERING +++ : obj = 7206a0 (JobMapper.cpp:81)

11/16/08 09:18:28.956 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 4 [JobMapper::getRequestId] (7206a0) JMRequestId={87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE}(JobMapper.cpp:85)

11/16/08 09:18:28.956 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [JobMapper::getRequestId] --- EXITING --- : obj = 7206a0 (JobMapper.cpp:81)

11/16/08 09:18:28.957 [Diagnostic] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 parentid=75] 4 V-117-56 [BackupJob::sendRequestToRB] requesting resources from RB for backup job (jobid=75)

Now we move into nbrb ...

NBRB

****

... from the JMRequestID in nbjm we can trace the first appearence of the job in nbrb

11/16/08 09:18:28.974 [Debug] NB 51216 nbrb 118 PID:25258 TID:5 File ID:118 [jobid=75] 1 [ResBroker_i::requestResources] received AllocationRequest: id={87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE} priority=0 secondPriority=757935392 userid=jobid=75 description=THE_BACKUP_JOB-75-{87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE} jobIdentifier=75

11/16/08 09:18:28.975 [Debug] NB 51216 nbrb 118 PID:25258 TID:5 File ID:118 [jobid=75] 1 [ResBroker_i::requestResources] RequestSeq:

Request=0 provider=MPXProvider resourcename=MpxRequest-75 MPXGroupRequest maxmpx=1

SubRequest=0 provider=DriveOperationProvider resourcename=maintest-4mm-robot-tl4-0 userSequence=0 RB::StorageUnitRequest { StorageUnitRequest { storageUnit=maintest-4mm-robot-tl4-0 mediaPool=Testpool retentionLevel=0 mustUseLocalMediaServer=no failOnError=no mpxRequired=no mustBeNdmp=no getMaxFreeSpace=no minFreeSpaceKBytes=0 usageType=1 client=maintest shareGroup=*ANY* } }

Request=1 provider=NamedResourceProvider resourcename=maintest.NBU_CLIENT.MAXJOBS.maintest CountedResourceRequest { max=1 }

Request=2 provider=NamedResourceProvider resourcename=maintest.NBU_POLICY.MAXJOBS.test1 CountedResourceRequest { max=2147483647 }

11/16/08 09:18:28.975 [Debug] NB 51216 nbrb 118 PID:25258 TID:5 File ID:118 [jobid=75] 2 [ResBroker_i::evaluateNow] scheduling evaluation immediately

11/16/08 09:18:28.976 [Debug] NB 51216 nbrb 118 PID:25258 TID:1 File ID:118 [No context] 4 [EvaluateNowTimerHelper::handle_timeout] evaluate now timeout triggered, will be doing evaluation

Evauation cycle starts ...

11/16/08 09:18:28.977 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [RBDoEvaluationCmd::execute] command: do evaluation

11/16/08 09:18:28.977 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 1 [ResBroker_i::doEvaluation] starting evaluation cycle

... nbrb connects to database

11/16/08 09:18:28.979 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 5 [RBDatabase::getConnectionHandle] Using database connection handle: 0

... releases connection to database and reports, in this instance, that there are no allocations to release

11/16/08 09:18:28.987 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 5 [RBDatabase::executeSQLStatement] Successfully executed SELECT AllocationID, AllocationType, ToBeReleased, Provider, ResourceName, UserAllocation, UserSequenceNumber, MasterServerName, GroupAllocationID, MDSAllocationKey, AllocationDataSize, AllocationData FROM RB_Allocation WHERE ToBeReleased = 1

11/16/08 09:18:28.989 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 5 [RBDatabase::releaseConnection] Releasing database connection handle: 0

11/16/08 09:18:28.990 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [ResBroker_i::release] getAllAllocationsToBeReleased: status=0, count=0

11/16/08 09:18:28.990 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [ResBroker_i::release] found no allocations to release

... next it gathers details it needs to pass to nbemm to be allocated resources

11/16/08 09:18:28.992 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 3 [ResBroker_i::mergeQueuedRequests] adding 1 new requests to AllocationRequest List

11/16/08 09:18:29.080 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMDriveCache::addDriveToCache] adding robotnum=0, drivetype=8, drivecount=1 to cache

11/16/08 09:18:29.080 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 5 [RBDatabase::getConnectionHandle] Using database connection handle: 0

11/16/08 09:18:29.081 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 5 [RBDatabase::getConnection] handle=0, m_hConn=ba3b28

11/16/08 09:18:29.081 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 5 [RBDatabase::executeSQLStatement] lodbcc=ba3b28

11/16/08 09:18:29.086 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 5 [RBDatabase::executeSQLStatement] Successfully executed SELECT MDSAllocationKey, MediaKey, DriveKey, Abstime, Delay, DriveState, DownStuCounts, DriveIsReusable, EjectUponUnload, PendingRequestWasAssigned, MediaRequestDelayAbsTime, ExternalFile, UserAssociatedDrive, Client, WaitingRequestID, RequeueState, UnloadType, Flags, Reallocating, PendingGuid, JobID, AllocationDataSize, AllocationData FROM RB_MDS_Allocation

11/16/08 09:18:29.089 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 5 [RBDatabase::releaseConnection] Releasing database connection handle: 0

11/16/08 09:18:29.471 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProviderMasterInfo::getSTUs] reading STU record: MasterServer=maintest, STU=maintest-4mm, OnDemandOnly=0

11/16/08 09:18:29.472 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProviderMasterInfo::getSTUs] reading STU record: MasterServer=maintest, STU=maintest-4mm-robot-tl4-0, OnDemandOnly=0

11/16/08 09:18:29.472 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProviderMasterInfo::getSTUs] reading STU record: MasterServer=maintest, STU=MediaDisk, OnDemandOnly=1

11/16/08 09:18:29.472 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProviderMasterInfo::getSTUs] reading STU record: MasterServer=maintest, STU=BasicDisk_U_1, OnDemandOnly=1

11/16/08 09:18:29.472 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProviderMasterInfo::getSTUs] reading STU record: MasterServer=maintest, STU=AdvancedDisk_Unit_2, OnDemandOnly=1

11/16/08 09:18:29.473 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 1 [EMMProvider::initialize] Robot not found in cache: maintest/-1. STU: maintest/maintest-4mm

11/16/08 09:18:29.511 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] EMMDriveCache::RobotMap:

11/16/08 09:18:29.512 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] (EMMDC::Robot robotNum=0 masterServer=maintest availableDrives=1)

11/16/08 09:18:29.512 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] EMMDriveCache::STUMap:

11/16/08 09:18:29.512 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] (EMMDC::STU name=AdvancedDisk_Unit_2 masterServer=maintest type=disk maxjobs=1 activejobs=0 robot=<NULL>)

11/16/08 09:18:29.513 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] (EMMDC::STU name=BasicDisk_U_1 masterServer=maintest type=disk maxjobs=1 activejobs=0 robot=<NULL>)

11/16/08 09:18:29.513 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] (EMMDC::STU name=MediaDisk masterServer=maintest type=disk maxjobs=1 activejobs=0 robot=<NULL>)

11/16/08 09:18:29.513 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] (EMMDC::STU name=maintest-4mm masterServer=maintest type=tape maxjobs=1 activejobs=0 robot=<NULL>)

11/16/08 09:18:29.514 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] (EMMDC::STU name=maintest-4mm-robot-tl4-0 masterServer=maintest type=tape maxjobs=1 activejobs=0 robot=(EMMDC::Robot robotNum=0 masterServer=maintest availableDrives=1))

11/16/08 09:18:29.514 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] EMMDriveCache::STUGroupMap:

11/16/08 09:18:29.514 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 4 [EMMProvider::initialize] (EMMDC::STUGroup name=__ANY__ masterServer=maintest STUList=(EMMDC::STUList numElements=2 maintest-4mm maintest-4mm-robot-tl4-0))

... here we see nbrb checking we've not hit any limits ...

11/16/08 09:18:29.547 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [CountedProvider::allocate] created and reserved resource maintest.NBU_CLIENT.MAXJOBS.maintest (current_ref_count=1, max_ref_count=1)

11/16/08 09:18:29.547 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [CountedProvider::allocate] created and reserved resource maintest.NBU_POLICY.MAXJOBS.test1 (current_ref_count=1, max_ref_count=2147483647)

... nbrb now contacts mds to get "physical" resources

11/16/08 09:18:29.548 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [EMMProvider::allocate(generic)] Resources available for maintest/maintest-4mm-robot-tl4-0. Sending requestId={87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE} to MDS

MDS

***

... gets details of requirements

... first thing is to connect to database ....

11/16/08 09:18:29.927 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [BEGIN_MDS_DB_TRANSACTION] attempting to get database connection

11/16/08 09:18:29.927 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [BEGIN_MDS_DB_TRANSACTION] got database connection

11/16/08 09:18:29.928 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [BEGIN_MDS_DB_TRANSACTION] attempting to start database transaction

11/16/08 09:18:29.930 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [BEGIN_MDS_DB_TRANSACTION] started database transaction

... here it seems to be sorting out speifications of requirments ...

11/16/08 09:18:30.052 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_robot_num2type] robot_num = 0

11/16/08 09:18:30.059 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_robot_num2type] robot_type = 7

11/16/08 09:18:30.059 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_density_type2md_type_names] density_type = 12

11/16/08 09:18:30.073 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_density_type2md_type_names] media_type_name = NetBackup 4MM, drive_type_name = NetBackup 4MM

11/16/08 09:18:30.073 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_mediatypename2flags] media_type_name = NetBackup 4MM

11/16/08 09:18:30.079 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_mediatypename2flags] media_type_flags = 0

... mds makes some allocations ...

11/16/08 09:18:30.315 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [get_storage_unit_attributes] name = maintest-4mm-robot-tl4-0

11/16/08 09:18:30.316 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [get_storage_unit_attributes] master_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.337 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_stu_resources] alloc_res_env_t: job_type = 1, capability_flags = 0, ndmp_ts_name = , ndmp_ts_key = 0, stu_name = maintest-4mm-robot-tl4-0, media_robot_num = 0, media_robot_type = 7, drive_robot_num = 0, drive_robot_type = 7, media_key = 4000046, media_type_flags = 0, drive_key = 2000004, drive_path = /dev/rmt/0cbn, cur_time = 1226827110, retlevel = 0, pool_name = Testpool, pool_num = 5, scratch_pool_name = Scratch, partner_key = 0, partner_reserved_state = 0, app_type = 0, disk_volume_key = 0, FT pipe_key = 0, active_fat_pipe_key = 0, server_group_key = 7000002, scsi_res_type = 1, server_state_flags = 1, modify_device_flag_bits = 0, dmp_path = , dmp_key = 0, whost_key = 1000002

11/16/08 09:18:30.338 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_stu_resources] master_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.338 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_stu_resources] media_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.338 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_stu_resources] ld_alloc - alloc_t: key = 0, job_type = 0, capability_flags = 0, master_server_name = , master_server_key = 0, media_server_name = , media_server_key = 0, ndmp_ts_name = , ndmp_ts_key = 0, stu_name = , media_robot_num = 0, media_robot_type = 0, drive_robot_num = 0, drive_robot_type = 0, media_key = 0, drive_key = 0, drive_path = , disk_volume_key = 0, disk_mount_point_key = 0, fat_pipe_key = 0, scsi_res_type = 0, server_state_flags = 0

11/16/08 09:18:30.338 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_stu_resources] stu_type = 2, prev_stu_name = , cur_alloc_key = 0, prev_pend_media_key = 0, alloc_type = 0, pend_request = 0, scratch_media = 0, scratch_pool_media = 1, mounted_media = 0, fake_load = 0, create_mount_point = 0, up_mount_point_users = 0, allocate_fat_pipe = 0

11/16/08 09:18:30.339 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_resources] act_flags = 9106944, act_flags2 = 0, prev_stu_name = , update_alloc_key = 0, prev_alloc_key = 0, prev_pend_media_key = 0, prev_pend_media_type_flags = 0

11/16/08 09:18:30.339 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_resources] env - alloc_res_env_t: job_type = 1, capability_flags = 0, ndmp_ts_name = , ndmp_ts_key = 0, stu_name = maintest-4mm-robot-tl4-0, media_robot_num = 0, media_robot_type = 7, drive_robot_num = 0, drive_robot_type = 7, media_key = 4000046, media_type_flags = 0, drive_key = 2000004, drive_path = /dev/rmt/0cbn, cur_time = 1226827110, retlevel = 0, pool_name = Testpool, pool_num = 5, scratch_pool_name = Scratch, partner_key = 0, partner_reserved_state = 0, app_type = 0, disk_volume_key = 0, FT pipe_key = 0, active_fat_pipe_key = 0, server_group_key = 7000002, scsi_res_type = 1, server_state_flags = 1, modify_device_flag_bits = 0, dmp_path = , dmp_key = 0, whost_key = 1000002

11/16/08 09:18:30.339 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_resources] master_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.340 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_resources] media_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.340 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [alloc_resources] ld_alloc - alloc_t: key = 0, job_type = 0, capability_flags = 0, master_server_name = , master_server_key = 0, media_server_name = , media_server_key = 0, ndmp_ts_name = , ndmp_ts_key = 0, stu_name = , media_robot_num = 0, media_robot_type = 0, drive_robot_num = 0, drive_robot_type = 0, media_key = 0, drive_key = 0, drive_path = , disk_volume_key = 0, disk_mount_point_key = 0, fat_pipe_key = 0, scsi_res_type = 0, server_state_flags = 0

11/16/08 09:18:30.341 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_alloc_media] media_key = 4000046, alloc_state = 1

11/16/08 09:18:30.388 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_alloc_media] allocated media

11/16/08 09:18:30.388 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_assign_media] media_key = 4000046, media_type_flags = 0, retlevel = 0, app_type = 0, server_group_key = 7000002, master_serv_key = 1000002, whost_key = 1000002

11/16/08 09:18:30.432 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_assign_media] assigned media

11/16/08 09:18:30.433 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_pool_info] media_key = 4000046, media_type_flags = 0, pool_name = Testpool, scr_pool_name = Scratch, pool_num = 5

11/16/08 09:18:30.474 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_pool_info] updated pool name

11/16/08 09:18:30.474 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_link_media_drive] media_key = 4000046, media_type_flags = 0, drive_key = 2000004

11/16/08 09:18:30.513 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_link_media_drive] linked drive with media

11/16/08 09:18:30.514 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_alloc_drive] drive_key = 2000004, alloc_state = 1

11/16/08 09:18:30.514 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_alloc_drive] media_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.522 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_alloc_drive] allocated drive

11/16/08 09:18:30.522 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_set_active_path] drive_key = 2000004, ndmp_host_key = 0, path = /dev/rmt/0cbn, all_paths_on_media_serv = 0

11/16/08 09:18:30.523 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_set_active_path] media_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.529 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_set_active_path] set active path

11/16/08 09:18:30.529 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_up_stu_cnts] stu_name = maintest-4mm-robot-tl4-0

11/16/08 09:18:30.530 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_up_stu_cnts] master_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.551 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_up_stu_cnts] upped stu counts

11/16/08 09:18:30.551 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_add_alloc_rec] dmp_key = 0

11/16/08 09:18:30.559 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_get_identity_var] alloc_key = 40

11/16/08 09:18:30.560 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [sql_update_add_alloc_rec] added allocation record, alloc_key = 40

... closes connections to database

11/16/08 09:18:30.560 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [END_MDS_DB_TRANSACTION] cur_err = 0, m_dbconn_stat = 0, m_dberr_stat = 0, m_closed_db_trx = 0

11/16/08 09:18:30.564 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [END_MDS_DB_TRANSACTION] committed database transaction

... here it is worth noting the line " ... fill_bsr] ALLOCATION: key = 40" This allocation key is traceable later on in nbrb

11/16/08 09:18:30.564 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [insert_into_alloc_lists] media_key = 4000046, drive_key = 2000004

11/16/08 09:18:30.565 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [add_to_key_seq] adding, key = 4000046

11/16/08 09:18:30.565 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [add_to_key_seq] adding, key = 2000004

11/16/08 09:18:30.565 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_stu_mds_rb_env] pend_request = 0, si_flags = 32

11/16/08 09:18:30.565 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [fill_bsr] ALLOCATION: key = 40, media server = maintest, mds_flags = 0, scsi_protection = 1, preempt_reservation = 0, preempted_ms_key = 0

11/16/08 09:18:30.566 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [fill_bsr] MEDIA: id = TAPE03, key = 4000046

11/16/08 09:18:30.566 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [fill_bsr] DRIVE: name = HP.C5733A.000, path = /dev/rmt/0cbn, key = 2000004, ndmp_host_key = 0

11/16/08 09:18:30.566 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [fill_bsr] STU: name = maintest-4mm-robot-tl4-0, master server = maintest

11/16/08 09:18:30.566 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [fill_bsr] DISKGROUP: id = *NULL*, key = 0

11/16/08 09:18:30.566 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [fill_bsr] DISKVOLUME: media_id = *NULL*, key = 0

11/16/08 09:18:30.566 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [fill_bsr] DISKMOUNTPOINT: mount_point = *NULL*, key = 0

11/16/08 09:18:30.567 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [fill_bsr] FTPIPE: pipe_id = 0

11/16/08 09:18:30.567 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_bsr] MEDIADB 1 40 TAPE03 4000046 ------ 12 1226827110 0 0 0 0 0 0 0 5 0 0 0 0 0 0

11/16/08 09:18:30.567 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_bsr] VOLUME 1 TAPE03 4000046 -------- Testpool *NULL* *NULL* 9 7 0 4 0 {00000000-0000-0000-0000-000000000000} 0

11/16/08 09:18:30.567 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_bsr] 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

11/16/08 09:18:30.567 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_bsr] STORAGE 1 maintest-4mm-robot-tl4-0 12 1048576 2 1 0 0 maintest maintest *NULL*

11/16/08 09:18:30.568 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_bsr] DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*

11/16/08 09:18:30.568 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_bsr] DISKVOLUME 0 6 *NULL* 6 *NULL* 0

11/16/08 09:18:30.568 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_bsr] DISKMOUNTPOINT 0 6 *NULL*

11/16/08 09:18:30.568 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [fill_bsr] FTRANS 0 0 6 *NULL* 6 *NULL* 0 0 0

11/16/08 09:18:30.572 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 2 [allocateTwin] Media_Drive_Record: MediaServer = maintest, MediaServerVersion = 650000, MediaServerClusterName = , MediaKey = 4000046, MediaId = TAPE03, DriveKey = 2000004, DriveName = HP.C5733A.000, PrimaryPath = /dev/rmt/0cbn, SerialNumber = 0000730089, PoolName = Testpool, RobotNum = 0, RobotType = 7, MediaTypeName = NetBackup 4MM, DriveTypeName = NetBackup 4MM, NdmpControlHost = , NdmpUserName = , NdmpPassword = , NdmpPasswordKey = , NdmpClientUserName = , NdmpClientPassword = , NdmpClientPasswordKey = , RetentionLevel = 0, PolicyType = 2, JobType = 1, MasterServer = maintest

11/16/08 09:18:30.574 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [allocateTwin] alloc_med_list = 4000046

11/16/08 09:18:30.574 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [allocateTwin] alloc_drv_list = 2000004

11/16/08 09:18:30.575 [Debug] NB 51216 mds 143 PID:25255 TID:9 File ID:111 [jobid=75] 1 [allocateTwin] EXIT STATUS = 0 (EMM_ERROR_Success, Success)

MDS

***

There are multiply lines similar to this in MDS, but this seem to be where the "MDS allocations in EMM: " entry in the nbrbutil -dump comand output is from ...

11/16/08 09:18:30.608 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [jobid=75] 2 [alloc_resources] act_flags = 33554432, act_flags2 = 0, prev_stu_name = , update_alloc_key = 0, prev_alloc_key = 0, prev_pend_media_key = 0, prev_pend_media_type_flags = 0

11/16/08 09:18:30.608 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [jobid=75] 2 [alloc_resources] env - alloc_res_env_t: job_type = 0, capability_flags = 0, ndmp_ts_name = , ndmp_ts_key = 0, stu_name = maintest-4mm-robot-tl4-0, media_robot_num = 0, media_robot_type = 0, drive_robot_num = 0, drive_robot_type = 0, media_key = 0, media_type_flags = 0, drive_key = 0, drive_path = , cur_time = 1226827110, retlevel = 0, pool_name = , pool_num = 0, scratch_pool_name = , partner_key = 0, partner_reserved_state = 0, app_type = 0, disk_volume_key = 0, FT pipe_key = 0, active_fat_pipe_key = 0, server_group_key = 0, scsi_res_type = 0, server_state_flags = 0, modify_device_flag_bits = 0, dmp_path = , dmp_key = 0, whost_key = 0

11/16/08 09:18:30.609 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [jobid=75] 2 [alloc_resources] master_serv - host_info_t: key = 1000002, parent_key = 1000002, fqname = maintest, state = 14, nbversion = 650000, nbtype = 3, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 247, raw_host_key = 1000002, raw_host_name = maintest, rank = 3

11/16/08 09:18:30.609 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [jobid=75] 2 [alloc_resources] media_serv - host_info_t: key = 0, parent_key = 0, fqname = , state = 0, nbversion = 0, nbtype = 0, cluster_key = 0, cluster_fqname = , active_node_key = 0, flags = 0, raw_host_key = 0, raw_host_name = , rank = 0

11/16/08 09:18:30.609 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [jobid=75] 2 [alloc_resources] ld_alloc - alloc_t: key = 0, job_type = 0, capability_flags = 0, master_server_name = , master_server_key = 0, media_server_name = , media_server_key = 0, ndmp_ts_name = , ndmp_ts_key = 0, stu_name = , media_robot_num = 0, media_robot_type = 0, drive_robot_num = 0, drive_robot_type = 0, media_key = 0, drive_key = 0, drive_path = , disk_volume_key = 0, disk_mount_point_key = 0, fat_pipe_key = 0, scsi_res_type = 0, server_state_flags = 0

... lets now pop back to nbrb ...

NBRB

****

I noticed this line ...

11/16/08 09:18:30.665 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 5 [RBDatabase::executeSQLStatement] Successfully executed DELETE RB_MDS_Allocation WHERE MDSAllocationKey = 40

.. although the allocation key matches the one in MDS, I haven't worked out quite why it's deleting resources at this point ...

Just a few lines later we actually see something recogniseable coming from MDS ...

11/16/08 09:18:30.682 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 4 [EMMProvider::setDriveAllocated] persistDriveInfo: status=0, DriveInfo=DriveInfo: allocationKey=40 driveName=HP.C5733A.000 driveKey=2000004 STU=maintest-4mm-robot-tl4-0 mediaServer=maintest mediaId=TAPE03 abstime=0 delay=0 state=inuse driveIsReusable=1 ejectUponUnload=0 jobtype=1 pendingRequestWasAssigned=0 requeueState=0 unloadType=0 flags=0 reallocating=0 deallocating=3 mediaRequestDelayAbsTime=0 externalFile= waitingRequest={00000000-0000-0000-0000-000000000000} pendingGuid={00000000-0000-0000-0000-000000000000} waitingAllocation=0

... following lines I thought I'd better include ,,,

11/16/08 09:18:30.682 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 4 [DMSAccess::isMountableDiskVolume] mdsrbenv.isDiskVolume=false

11/16/08 09:18:30.682 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 2 [EMMProvider::allocate(StorageUnit)] stu allocated: STU=maintest-4mm-robot-tl4-0, allocationKey=40

11/16/08 09:18:30.683 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 4 [EMMDriveCache::Robot::decrementDriveCount] Removing drive of type 8 from cache

11/16/08 09:18:30.683 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 4 [MPXProvider::allocateOne] saved 1 original requests

11/16/08 09:18:30.684 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [MPXProvider::allocateOne] created MPX group (mpxid={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE}, masterServer= maintest, max_mpx=1, jmBirthTime=1226681069)

11/16/08 09:18:30.684 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [ProviderManager::allocate] provider MPXProvider returned Allocation Granted for requestId={87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE} (userid=jobid=75)

11/16/08 09:18:30.684 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 4 [ProviderManager::persistOneAllocation] persisting allocation (id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE})

Next part of interest we see ...

11/16/08 09:18:30.708 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 4 [CountedProvider::persistCountAllocation] createOrUpdateNamedResource: name=maintest.NBU_POLICY.MAXJOBS.test1, max=2147483647, current=1, status=0

11/16/08 09:18:30.708 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 4 [ProviderManager::persistOneAllocation] persisting allocation (id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE})

11/16/08 09:18:30.709 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 4 [ProviderManager::persistOneAllocation] persisting allocation (id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE})

11/16/08 09:18:30.709 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [ResBroker_i::passOne] resources found for request, requestId={87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE}, userid=jobid=75

11/16/08 09:18:30.709 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [ResBroker_i::passOne] allocation: (Allocation: id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE} provider=NamedResourceProvider resourcename=maintest.NBU_CLIENT.MAXJOBS.maintest masterserver=maintest groupid={00000000-0000-0000-0000-000000000000} userSequence=-1 userid="jobid=75" unknown allocation data object)

11/16/08 09:18:30.710 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [ResBroker_i::passOne] allocation: (Allocation: id={88D62BBE-1DD2-11B2-B5AB-0003BA5C7FEE} provider=NamedResourceProvider resourcename=maintest.NBU_POLICY.MAXJOBS.test1 masterserver=maintest groupid={00000000-0000-0000-0000-000000000000} userSequence=-1 userid="jobid=75" unknown allocation data object)

11/16/08 09:18:30.710 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [ResBroker_i::passOne] allocation: (Allocation: id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE} provider=MPXProvider resourcename=anMPXGroup masterserver=maintest groupid={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE} userSequence=-1 userid="jobid=75" (MPXGroupAllocation: groupId={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE}))

11/16/08 09:18:30.711 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [ResBroker_i::passOne] allocation: (Allocation: id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE} provider=MPXProvider resourcename=maintest-4mm-robot-tl4-0 masterserver=maintest groupid={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE} userSequence=0 userid="jobid=75" (Media_Drive_Allocation_Record: allocationKey=40 (Media_Drive_Record: MediaKey=4000046 MediaId=TAPE03 MediaServer=maintest DriveKey=2000004 DriveName=HP.C5733A.000 PrimaryPath=/dev/rmt/0cbn PoolName=Testpool RobotNum=0 RobotType=7 MediaTypeName=NetBackup 4MM DriveTypeName=NetBackup 4MM NdmpControlHost= RetentionLevel=0 PolicyType=2 JobType=1 MasterServer=maintest) (Storage_Unit_Record: STU=maintest-4mm-robot-tl4-0 STUType=2 MasterServer=maintest MediaServer=maintest RobotType=7 RobotNumber=0 Density=12 OnDemandOnly=0 ConcurrentJobs=1 ActiveJobs=0 MaxMultiplexing=1 NdmpAttachHost= AbsolutePath=) (Bptm_Strings_Record: 0="MEDIADB 1 40 TAPE03 4000046 ------ 12 1226827110 0 0 0 0 0 0 0 5 0 0 0 0 0 0" 1="VOLUME 1 TAPE03 4000046 -------- Testpool *NULL* *NULL* 9 7 0 4 0 {00000000-0000-0000-0000-000000000000} 0" 2="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" 3="STORAGE 1 maintest-4mm-robot-tl4-0 12 1048576 2 1 0 0 maintest maintest *NULL*" 4="DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*" 5="DISKVOLUME 0 6 *NULL* 6 *NULL* 0" 6="DISKMOUNTPOINT 0 6 *NULL*" 7="FTRANS 0 0 6 *NULL* 6 *NULL* 0 0 0" ) TpReqFileName=) useFatPipeTransport=false diskPath= diskGroupName= storageServerType= diskGroupStorageServerName= failureCode=0)

These are the entries that are found in the Allocations part of the nbrbutil -dump command output

Then we see some detail for the client ...

11/16/08 09:18:30.798 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 2 [CallbackQueue::notifyClientAvailable] queue notify client for resourcesAvailable (requestId={87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE}, userid=jobid=75)

11/16/08 09:18:30.798 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 6 [CorbaCall] +++ ENTERING +++ : obj = bfb660 (ResCallbackQueue.cpp:1158)

11/16/08 09:18:30.799 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 6 [CorbaCall] --- EXITING --- : obj = bfb660 (ResCallbackQueue.cpp:1158)

11/16/08 09:18:30.799 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 6 [JMCorbaCall] +++ ENTERING +++ : obj = bfb660 (ResCallbackQueue.cpp:601)

11/16/08 09:18:30.799 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 6 [JMCorbaCall] --- EXITING --- : obj = bfb660 (ResCallbackQueue.cpp:601)

11/16/08 09:18:30.799 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 6 [notifyClientAvailable] +++ ENTERING +++ : obj = bfb660 (ResCallbackQueue.cpp:940)

11/16/08 09:18:30.800 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 6 [notifyClientAvailable] --- EXITING --- : obj = bfb660 (ResCallbackQueue.cpp:940)

Back now to NBJM ...

... nbrb has passed allocation details back to nbjm as we can see ...

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 created backup image header in database

11/16/08 09:18:30.855 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=75 parentid=75] 6 [BackupJob::qImageNew] +++ ENTERING +++ : obj = 960b20 (BackupJob.cpp:1486)

11/16/08 09:18:30.855 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 4 [JobMapper::openParentJob] (7206a0) specified job is a parent job(JobMapper.cpp:222)

11/16/08 09:18:30.855 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::qImageNew] (960b20) policy=test1birthtime=1226827110(BackupJob.cpp:1503)

11/16/08 09:18:30.856 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::getFirstCopyJobid] (960b20) first copy jobid=75(BackupJob.cpp:2830)

11/16/08 09:18:30.856 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 1 [CallbackQueue::queueRequest] queueing NBProxyCreateImage : jobid=75, birthtime=1226827110, hostname=maintest, status=0, policy=test1, schedule=Full, clientType=0, scheduleType=0, retentionLevel=0, streamNumber=0, backupCopType=0, ifrfr=false, extSecInfo=false, synthetic=false, mpxBackup=false, clientCompress=false, clientEncrypt=0, tirType=0, pfiType=0, dumpLevel=0, keyword=, parentPolicyName=, parentScheduleType=0, parentBithtime0, snapTime=0, lastIncr=0, lastFull=0, dataClassificationName=, storageServiceName= NBProxyCallback : jobid=75 -- retry count=3(CallbackQueue.cpp:1212)

11/16/08 09:18:30.856 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=75 parentid=75] 4 [BackupJob::qImageNew] (960b20) awaiting proxy response to createImageFile(BackupJob.cpp:1578)

11/16/08 09:18:30.857 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=75 parentid=75] 6 [BackupJob::qImageNew] --- EXITING --- : obj = 960b20 (BackupJob.cpp:1486)

and we see confirmation that NBRB has completed the allocation ...

11/16/08 09:18:30.939 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [No context] 2 [ResBroker_i::doEvaluation] after resource evaluation: 0 requests remain, 1 just allocated

BPTM

****

bptm having made checks, host names etc... requests details of allocationed resources from bpjm

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

09:18:34.574 [15245] <2> logResourceReq: req.versionId : 1

09:18:34.574 [15245] <2> logResourceReq: req.jobId : -1226681332

09:18:34.574 [15245] <2> logResourceReq: req.startedViaJobManager : true

09:18:34.574 [15245] <2> logResourceReq: req.consumer : true

09:18:34.575 [15245] <2> logResourceReq: InitialSTUSelect -

09:18:34.576 [15245] <2> logResourceReq: reqNum : 0

09:18:34.576 [15245] <2> logResourceReq: preferredMediaServer :

09:18:34.576 [15245] <2> logResourceReq: requiredMediaServer : maintest

09:18:34.576 [15245] <2> logResourceReq: storageUnit : maintest-4mm-robot-tl4-0

09:18:34.576 [15245] <2> logResourceReq: mustBeNdmp : false

09:18:34.576 [15245] <2> logResourceReq: getMaxFreeSpace : false

09:18:34.577 [15245] <2> logResourceReq: mediaPool : Testpool

09:18:34.578 [15245] <2> logResourceReq: shareGroup :

09:18:34.578 [15245] <2> logResourceReq: retentionLevel : 0

09:18:34.578 [15245] <2> logResourceReq: mustUseLocalMediaServer : false

09:18:34.579 [15245] <2> logResourceReq: failOnError : false

09:18:34.579 [15245] <2> logResourceReq: mpxRequired : false

09:18:34.579 [15245] <2> logResourceReq: client : maintest

09:18:34.579 [15245] <2> logResourceReq: usageType : 1

Looking now in NBJM ...

We can see a responce that seems to match the request from BPTM

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)

BPTM

****

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

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

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)

09:19:46.725 [15245] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: 0 twin_is_disk 0 delay_brm: 0

09:19:46.732 [15245] <2> write_data: absolute block position prior to writing backup header(s) is 2, copy 1

09:19:46.732 [15245] <2> io_write_back_header: drive index 0, maintest_1226827110, file num = 1, mpx_headers = 0, copy 1

09:19:46.733 [15245] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 1

09:19:46.734 [15245] <2> write_data: first write, twin_index: 0 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0

09:19:46.734 [15245] <2> write_data: received first buffer (32768 bytes), begin writing data

09:19:46.737 [15245] <2> write_data: writing short block, 32768 bytes, remainder 0

09:19:46.737 [15245] <2> write_data: waited for full buffer 0 times, delayed 0 times

09:19:46.737 [15245] <2> write_backup: write_data() returned, exit_status = 0, CINDEX = 0, TWIN_INDEX = 0, backup_status = 0

09:19:46.738 [15245] <2> write_backup: tp.tv_sec = 1226827186, stp.tv_sec = 1226827186, tp.tv_usec = 737380, stp.tv_usec = 734023, et = 3, mpx_total_kbytes[TWIN_INDEX = 0] = 32

09:19:46.738 [15245] <2> io_terminate_tape: writing empty backup header, drive index 0, copy 1

09:19:46.738 [15245] <2> io_ioctl: command (0)MTWEOF 1 from (bptm.c.8598) on drive index 0

09:19:49.288 [15245] <2> io_write_back_header: drive index 0, empty_file, file num = 2, mpx_headers = 0, copy 1

09:19:49.289 [15245] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_HP.C5733A.000, from bptm.c.8716

09:19:49.865 [15245] <2> io_terminate_tape: absolute block position prior to writing empty header is 5, copy 1

09:19:49.865 [15245] <2> io_terminate_tape: block position check: actual 5, expected 5

This is interesting - bptm sends a message to MDS ...

09:19:49.865 [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 5 0

MDS

***

This seems to be the activity in MDS at that point ...

11/16/08 09:19:49.867 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 1 [handleMessage] INITIATING:

11/16/08 09:19:49.867 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 1 [handleMessage] got message: MEDIADB 1 40 TAPE03 4000046 *NULL* 12 1226827110 1226827110 1227431910 0 0 0 0 0 5 0 0 1024 0 5 0

11/16/08 09:19:49.868 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [BEGIN_MDS_DB_TRANSACTION] attempting to get database connection

11/16/08 09:19:49.869 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [BEGIN_MDS_DB_TRANSACTION] got database connection

11/16/08 09:19:49.870 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [BEGIN_MDS_DB_TRANSACTION] attempting to start database transaction

11/16/08 09:19:49.872 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [BEGIN_MDS_DB_TRANSACTION] started database transaction

11/16/08 09:19:49.872 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [sql_get_alloc_info] alloc_key = 40

11/16/08 09:19:49.880 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [sql_get_alloc_info] alloc - alloc_t: key = 40, job_type = 1, capability_flags = 0, master_server_name = maintest, master_server_key = 1000002, media_server_name = maintest, media_server_key = 1000002, ndmp_ts_name = , ndmp_ts_key = 0, stu_name = maintest-4mm-robot-tl4-0, media_robot_num = 0, media_robot_type = 7, drive_robot_num = 0, drive_robot_type = 7, media_key = 4000046, drive_key = 2000004, drive_path = /dev/rmt/0cbn, disk_volume_key = 0, disk_mount_point_key = 0, fat_pipe_key = 0, scsi_res_type = 1, server_state_flags = 1

11/16/08 09:19:49.881 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [sql_get_media_info_by_key] media_key = 4000046

11/16/08 09:19:49.895 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [sql_density_name2type] density_name = NBU 4MM

11/16/08 09:19:49.903 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [sql_density_name2type] density type = 12

11/16/08 09:19:49.903 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [sql_get_media_info_by_key] med - media_t: id = TAPE03, key = 4000046, partner_key = 0, ass_time = 1226827110, alloc_state = 1, pool_name = Testpool, pool_num = 5, robot_num = 0, robot_type = 7, type_name = NetBackup 4MM, density_name = NBU 4MM, status = 0, conflicts = 0, drive_key = 2000004, last_whost_key = 1000002, master_server_key = 1000002, server_group_key = 7000002

11/16/08 09:19:49.904 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [sql_update_media_db_info] media_key = 4000046, ass_time = 1226827110, wrt_time = 1226827110, exp_time = 1227431910, res_time = 0, kbytes = 0.000000, nimages = 0, vimages = 0, retlevel = 0, nrestores = 0, status = 0, hsize = 1024, ssize = 0, loffset = 5.000000, psize = 0.000000

11/16/08 09:19:49.947 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [sql_update_media_db_info] updated media record, media_key = 4000046

11/16/08 09:19:49.947 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [END_MDS_DB_TRANSACTION] cur_err = 0, m_dbconn_stat = 0, m_dberr_stat = 0, m_closed_db_trx = 0

11/16/08 09:19:49.951 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [END_MDS_DB_TRANSACTION] committed database transaction

11/16/08 09:19:49.951 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [END_MDS_DB_TRANSACTION] cur_err = 0, m_dbconn_stat = 0, m_dberr_stat = 0, m_closed_db_trx = 1

11/16/08 09:19:49.951 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 2 [END_MDS_DB_TRANSACTION] database transaction has already been closed

11/16/08 09:19:49.952 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 1 [handleMessage] EXIT INFO:

11/16/08 09:19:49.952 [Debug] NB 51216 mds 143 PID:25255 TID:1 File ID:111 [No context] 1 [handleMessage] EXIT STATUS = 0 (EMM_ERROR_Success, Success)

Back to BPTM

09:19:49.954 [15245] <2> emmlib_handleMessage: (0) CORBA call returned 0

09:19:49.955 [15245] <2> io_open: SCSI RESERVE

09:19:49.957 [15245] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_HP.C5733A.000 successfully opened (mode 0)

09:19:49.957 [15245] <2> io_ioctl: command (2)MTBSF 2 from (bptm.c.8873) on drive index 0

09:19:56.908 [15245] <2> io_ioctl: command (1)MTFSF 1 from (bptm.c.8875) on drive index 0

09:19:56.910 [15245] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_HP.C5733A.000, from bptm.c.8881

09:19:56.912 [15245] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from io_terminate_tape)

09:19:56.912 [15245] <2> write_backup_update_frags: ************** Fragment 1: *******************

09:19:56.912 [15245] <2> write_backup_update_frags: ++++ total image kbytes so far = 32 ++++

`

09:19:56.912 [15245] <2> write_backup_update_frags: ++++ fragment_num = 1 ++++

09:19:56.912 [15245] <2> write_backup_update_frags: copy_num = 1

09:19:56.912 [15245] <2> write_backup_update_frags: Kbytes = 32

09:19:56.912 [15245] <2> write_backup_update_frags: remainder = 0

09:19:56.912 [15245] <2> write_backup_update_frags: id = TAPE03

09:19:56.912 [15245] <2> write_backup_update_frags: file_num = 1

09:19:56.912 [15245] <2> write_backup_update_frags: block_size = 65536

09:19:56.912 [15245] <2> write_backup_update_frags: offset = 2

09:19:56.913 [15245] <2> write_backup_update_frags: ******************************************************

... and eventually we see ...

09:19:57.466 [15245] <2> bptm: EXITING with status 0 <----------

NBJM prepares to releases resources ...

11/16/08 09:19:59.984 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 reqid=0] 6 [ExportedResourceMgr::~ExportedResourceMgr] +++ ENTERING +++ : obj = 9306b8 (ExportedResourceMgr.cpp:83)

11/16/08 09:19:59.984 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::addToReleaseList] +++ ENTERING +++ : obj = 930990 (ExportedResource.cpp:243)

11/16/08 09:19:59.984 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::addToReleaseList] --- EXITING --- : obj = 930990 (ExportedResource.cpp:243)

11/16/08 09:19:59.984 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResourceCounted::~ExportedResourceCounted] +++ ENTERING +++ : obj = 930990 (ExportedResource.cpp:359)

11/16/08 09:19:59.984 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 4 [ExportedResourceCounted::~ExportedResourceCounted] CountedResource=maintest.NBU_CLIENT.MAXJOBS.maintest exportable = 1 requestId = {87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE} JMowned = 1 Allocation -- id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE}, usn=-1, groupId={00000000-0000-0000-0000-000000000000}, provider=NamedResourceProvider, resourcename=maintest.NBU_CLIENT.MAXJOBS.maintest, userAllocationId=jobid=75, masterServer=maintest(ExportedResource.cpp:360)

11/16/08 09:19:59.985 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResourceCounted::~ExportedResourceCounted] --- EXITING --- : obj = 930990 (ExportedResource.cpp:359)

11/16/08 09:19:59.985 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::~ExportedResource] +++ ENTERING +++ : obj = 930990 (ExportedResource.cpp:58)

11/16/08 09:19:59.985 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::~ExportedResource] --- EXITING --- : obj = 930990 (ExportedResource.cpp:58)

11/16/08 09:19:59.986 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::addToReleaseList] +++ ENTERING +++ : obj = 931070 (ExportedResource.cpp:243)

11/16/08 09:19:59.986 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::addToReleaseList] --- EXITING --- : obj = 931070 (ExportedResource.cpp:243)

11/16/08 09:19:59.986 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResourceCounted::~ExportedResourceCounted] +++ ENTERING +++ : obj = 931070 (ExportedResource.cpp:359)

11/16/08 09:19:59.986 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 4 [ExportedResourceCounted::~ExportedResourceCounted] CountedResource=maintest.NBU_POLICY.MAXJOBS.test1 exportable = 1 requestId = {87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE} JMowned = 1 Allocation -- id={88D62BBE-1DD2-11B2-B5AB-0003BA5C7FEE}, usn=-1, groupId={00000000-0000-0000-0000-000000000000}, provider=NamedResourceProvider, resourcename=maintest.NBU_POLICY.MAXJOBS.test1, userAllocationId=jobid=75, masterServer=maintest(ExportedResource.cpp:360)

11/16/08 09:19:59.987 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResourceCounted::~ExportedResourceCounted] --- EXITING --- : obj = 931070 (ExportedResource.cpp:359)

11/16/08 09:19:59.987 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::~ExportedResource] +++ ENTERING +++ : obj = 931070 (ExportedResource.cpp:58)

11/16/08 09:19:59.987 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::~ExportedResource] --- EXITING --- : obj = 931070 (ExportedResource.cpp:58)

11/16/08 09:19:59.987 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::addToReleaseList] +++ ENTERING +++ : obj = 945d20 (ExportedResource.cpp:243)

11/16/08 09:19:59.987 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::addToReleaseList] --- EXITING --- : obj = 945d20 (ExportedResource.cpp:243)

11/16/08 09:19:59.988 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResourceMpxGroup::~ExportedResourceMpxGroup] +++ ENTERING +++ : obj = 945d20 (ExportedResource.cpp:421)

11/16/08 09:19:59.988 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 4 [ExportedResourceMpxGroup::~ExportedResourceMpxGroup] MpxGroupResource={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE} exportable = 1 requestId = {87CE81DA-1DD2-11B2-8C8B-0003BA5C7FEE} JMowned = 1 Allocation -- id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE}, usn=-1, groupId={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE}, provider=MPXProvider, resourcename=anMPXGroup, userAllocationId=jobid=75, masterServer=maintest(ExportedResource.cpp:422)

11/16/08 09:19:59.988 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResourceMpxGroup::~ExportedResourceMpxGroup] --- EXITING --- : obj = 945d20 (ExportedResource.cpp:421)

11/16/08 09:19:59.988 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::~ExportedResource] +++ ENTERING +++ : obj = 945d20 (ExportedResource.cpp:58)

11/16/08 09:19:59.989 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 6 [ExportedResource::~ExportedResource] --- EXITING --- : obj = 945d20 (ExportedResource.cpp:58)

11/16/08 09:19:59.989 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 1 [CallbackQueue::queueRequest] queueing RB RBrelease : id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE} id={88D62BBE-1DD2-11B2-B5AB-0003BA5C7FEE} id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE} -- retry count=-1(CallbackQueue.cpp:1212)

11/16/08 09:19:59.989 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 4 [CallbackQueue::queueRequest] (8c0a60) triggering callback queue processing(CallbackQueue.cpp:1226)

11/16/08 09:19:59.990 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [jobid=75 reqid=0] 6 [ExportedResourceMgr::~ExportedResourceMgr] --- EXITING --- : obj = 9306b8 (ExportedResourceMgr.cpp:83)

NBRB

****

Releases resources ...

11/16/08 09:20:00.076 [Debug] NB 51216 nbrb 118 PID:25258 TID:4 File ID:118 [No context] 1 [ResBroker_i::release(id)] received release: id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE}

11/16/08 09:20:00.130 [Debug] NB 51216 nbrb 118 PID:25258 TID:4 File ID:118 [No context] 4 [ResBroker_i::release(id)] markAllocationToBeReleased: id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE}, status=0

11/16/08 09:20:00.131 [Debug] NB 51216 nbrb 118 PID:25258 TID:4 File ID:118 [No context] 1 [ResBroker_i::release(id)] received release: id={88D62BBE-1DD2-11B2-B5AB-0003BA5C7FEE}

11/16/08 09:20:00.190 [Debug] NB 51216 nbrb 118 PID:25258 TID:4 File ID:118 [No context] 4 [ResBroker_i::release(id)] markAllocationToBeReleased: id={88D62BBE-1DD2-11B2-B5AB-0003BA5C7FEE}, status=0

11/16/08 09:20:00.190 [Debug] NB 51216 nbrb 118 PID:25258 TID:4 File ID:118 [No context] 1 [ResBroker_i::release(id)] received release: id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE}

11/16/08 09:20:00.210 [Debug] NB 51216 nbrb 118 PID:25258 TID:4 File ID:118 [No context] 4 [ResBroker_i::release(id)] markAllocationToBeReleased: id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE}, status=0

11/16/08 09:20:00.231 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [ResBroker_i::releaseOne] releasing allocation id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE}

11/16/08 09:20:00.231 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [ResBroker_i::releaseOne] releasing allocation (Allocation: id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE} provider=NamedResourceProvider resourcename=maintest.NBU_CLIENT.MAXJOBS.maintest masterserver=maintest groupid={00000000-0000-0000-0000-000000000000} userSequence=-1 userid="jobid=75" unknown allocation data object)

11/16/08 09:20:00.231 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [ProviderManager::release] releasing allocation (id={88D62B46-1DD2-11B2-B10D-0003BA5C7FEE})

11/16/08 09:20:00.281 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [ResBroker_i::releaseOne] releasing allocation id={88D62BBE-1DD2-11B2-B5AB-0003BA5C7FEE}

11/16/08 09:20:00.282 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [ResBroker_i::releaseOne] releasing allocation (Allocation: id={88D62BBE-1DD2-11B2-B5AB-0003BA5C7FEE} provider=NamedResourceProvider resourcename=maintest.NBU_POLICY.MAXJOBS.test1 masterserver=maintest groupid={00000000-0000-0000-0000-000000000000} userSequence=-1 userid="jobid=75" unknown allocation data object)

11/16/08 09:20:00.282 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [ProviderManager::release] releasing allocation (id={88D62BBE-1DD2-11B2-B5AB-0003BA5C7FEE})

11/16/08 09:20:00.351 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 1 [ResBroker_i::releaseOne] releasing allocation id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE}

11/16/08 09:20:00.352 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [ResBroker_i::releaseOne] releasing allocation (Allocation: id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE} provider=MPXProvider resourcename=anMPXGroup masterserver=maintest groupid={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE} userSequence=-1 userid="jobid=75" (MPXGroupAllocation: groupId={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE}))

11/16/08 09:20:00.352 [Debug] NB 51216 nbrb 118 PID:25258 TID:10 File ID:118 [jobid=75] 3 [ProviderManager::release] releasing allocation (id={88D60F76-1DD2-11B2-903B-0003BA5C7FEE})

Back to NBJM ...

11/16/08 09:20:00.366 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=0 reqid=-1226681332] 6 [ExportedResourceMgr::~ExportedResourceMgr] +++ ENTERING +++ : obj = 9341b8 (ExportedResourceMgr.cpp:83)

11/16/08 09:20:00.366 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 1 [ExportedResourceMediaDrive::getReleaseDelayCallback] no release delay specified for 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:1216)

11/16/08 09:20:00.367 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResource::addToReleaseList] +++ ENTERING +++ : obj = 857b10 (ExportedResource.cpp:243)

11/16/08 09:20:00.367 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 4 [ExportedResourceMediaDrive::getName] (857b10) null tpreq file name(ExportedResource.cpp:1183)

11/16/08 09:20:00.367 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResource::addToReleaseList] --- EXITING --- : obj = 857b10 (ExportedResource.cpp:243)

11/16/08 09:20:00.367 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResourceMediaDrive::~ExportedResourceMediaDrive] +++ ENTERING +++ : obj = 857b10 (ExportedResource.cpp:1439)

11/16/08 09:20:00.368 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 4 [ExportedResourceMediaDrive::~ExportedResourceMediaDrive] 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:1440)

11/16/08 09:20:00.368 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResourceMediaDrive::~ExportedResourceMediaDrive] --- EXITING --- : obj = 857b10 (ExportedResource.cpp:1439)

11/16/08 09:20:00.369 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResource::~ExportedResource] +++ ENTERING +++ : obj = 857b10 (ExportedResource.cpp:58)

11/16/08 09:20:00.369 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 6 [ExportedResource::~ExportedResource] --- EXITING --- : obj = 857b10 (ExportedResource.cpp:58)

11/16/08 09:20:00.369 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 1 [CallbackQueue::queueRequest] queueing RB RBrelease : id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE} -- retry count=-1(CallbackQueue.cpp:1212)

11/16/08 09:20:00.369 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [No context] 4 [CallbackQueue::queueRequest] (8c0a60) triggering callback queue processing(CallbackQueue.cpp:1226)

11/16/08 09:20:00.370 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [jobid=0 reqid=-1226681332] 6 [ExportedResourceMgr::~ExportedResourceMgr] --- EXITING --- : obj = 9341b8 (ExportedResourceMgr.cpp:83)

NBJM sends release resources to NBRB ...

11/16/08 09:20:00.376 [Debug] NB 51216 nbjm 117 PID:25292 TID:4 File ID:117 [No context] 1 [CallbackQueue::handle_input] sending RB RBrelease : id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE}(CallbackQueue.cpp:1328)

NBRB

****

and then back to NBRB ...

11/16/08 09:20:00.378 [Debug] NB 51216 nbrb 118 PID:25258 TID:1 File ID:118 [No context] 1 [ResBroker_i::release(id)] received release: id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE}

11/16/08 09:20:00.438 [Debug] NB 51216 nbrb 118 PID:25258 TID:1 File ID:118 [No context] 4 [ResBroker_i::release(id)] markAllocationToBeReleased: id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE}, status=0

11/16/08 09:20:02.093 [Debug] NB 51216 nbrb 118 PID:25258 TID:9 File ID:118 [jobid=75] 1 [ResBroker_i::releaseOne] releasing allocation id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE}

11/16/08 09:20:02.094 [Debug] NB 51216 nbrb 118 PID:25258 TID:9 File ID:118 [jobid=75] 3 [ResBroker_i::releaseOne] releasing allocation (Allocation: id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE} provider=MPXProvider resourcename=maintest-4mm-robot-tl4-0 masterserver=maintest groupid={88D601FC-1DD2-11B2-9FD3-0003BA5C7FEE} userSequence=0 userid="jobid=75" (Media_Drive_Allocation_Record: allocationKey=40 (Media_Drive_Record: MediaKey=4000046 MediaId=TAPE03 MediaServer=maintest DriveKey=2000004 DriveName=HP.C5733A.000 PrimaryPath=/dev/rmt/0cbn PoolName=Testpool RobotNum=0 RobotType=7 MediaTypeName=NetBackup 4MM DriveTypeName=NetBackup 4MM NdmpControlHost= RetentionLevel=0 PolicyType=2 JobType=1 MasterServer=maintest) (Storage_Unit_Record: STU=maintest-4mm-robot-tl4-0 STUType=2 MasterServer=maintest MediaServer=maintest RobotType=7 RobotNumber=0 Density=12 OnDemandOnly=0 ConcurrentJobs=1 ActiveJobs=0 MaxMultiplexing=1 NdmpAttachHost= AbsolutePath=) (Bptm_Strings_Record: 0="MEDIADB 1 40 TAPE03 4000046 ------ 12 1226827110 0 0 0 0 0 0 0 5 0 0 0 0 0 0" 1="VOLUME 1 TAPE03 4000046 -------- Testpool *NULL* *NULL* 9 7 0 4 0 {00000000-0000-0000-0000-000000000000} 0" 2="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" 3="STORAGE 1 maintest-4mm-robot-tl4-0 12 1048576 2 1 0 0 maintest maintest *NULL*" 4="DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*" 5="DISKVOLUME 0 6 *NULL* 6 *NULL* 0" 6="DISKMOUNTPOINT 0 6 *NULL*" 7="FTRANS 0 0 6 *NULL* 6 *NULL* 0 0 0" ) TpReqFileName=))

11/16/08 09:20:02.094 [Debug] NB 51216 nbrb 118 PID:25258 TID:9 File ID:118 [jobid=75] 3 [ProviderManager::release] releasing allocation (id={88C672F0-1DD2-11B2-B352-0003BA5C7FEE})

NBJM

****

Sends commands to bptm to eject ...

11/16/08 09:20:11.573 [Debug] NB 51216 nbjm 117 PID:25292 TID:6 File ID:117 [[V-1-41 Unable to load the localized string for this log message. Locale=C; TextId=301; DefaultMsg=]] 4 [BPTMComm::startBptm] (859b50) sending cmd=/usr/openv/netbackup/bin/bptm bptm -unload -dn HP.C5733A.000 -dp /dev/rmt/0cbn -dk 2000004 -m TAPE03 -mk 4000046 -mds 8 -alocid 40 -jobid -1226681333 -jm(BPTMComm.cpp:356)

BPTM

****

Eject process ...

09:19:57.239 [15245] <2> send_MDS_msg: MEDIADB 1 40 TAPE03 4000046 *NULL* 12 1226827110 1226827110 1227431910 0 32 1 1 0 5 0 0 1024 0 5 0

09:20:12.475 [15329] <4> bptm: emmserver_name = maintest

09:20:12.475 [15329] <4> bptm: emmserver_port = 1556

09:20:12.593 [15329] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD

NBJM

****

NBJM notes the PID of the bptm process that ejects ...

11/16/08 09:20:12.642 [Debug] NB 51216 nbjm 117 PID:25292 TID:3 File ID:117 [[V-1-41 Unable to load the localized string for this log message. Locale=C; TextId=301; DefaultMsg=]] 4 [BPTMComm::handleMsg] (859b50) BPTM pid=15329(BPTMComm.cpp:452)

BPTM

****

09:20:12.717 [15329] <2> nbjm_media_request: Job control returned to BPTM

09:20:12.718 [15329] <2> drivename_open: Called with Create 1, file HP.C5733A.000

09:20:12.718 [15329] <2> drivename_lock: lock established

09:20:12.719 [15329] <4> create_tpreq_file: symlink to path /dev/rmt/0cbn

09:20:12.720 [15329] <2> drivename_write: Called with mode 2

09:20:12.723 [15329] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)

09:20:12.724 [15329] <2> really_tpunmount: tpunmount'ing /usr/openv/netbackup/db/media/tpreq/drive_HP.C5733A.000

09:20:13.593 [15329] <2> tapelib: wait_for_ltid, UnMount, timeout 1800

LTID

****

09:20:13.120 [25264] <4> LtidProcCmd: Pid=15329, Data.Pid=15329, Type=12, Param1=0, Param2=0, LongParam=0

09:20:13.120 [25264] <4> tpunmount_withMntPtr: drive has been assigned

09:20:13.120 [25264] <4> add_unload_to_queue: Unload for media id TAPE03 added to queue (PID 15329, OP 2)

09:20:13.121 [25264] <2> SendRobotReq: LTID - Sent ROBOTIC request, Type=3, Param2=0

09:20:13.121 [25264] <6> WriteEntry: Updating drive HP.C5733A.000 at path /dev/rmt/0cbn on attach host

09:20:13.157 [25264] <2> update_drive: (0) Inputs: MediaServer = < maintest >, NdmpHost = < >, DriveName = < HP.C5733A.000 >, DrivePath = < /dev/rmt/0cbn >

09:20:13.157 [25264] <4> update_drive: (0) *******drive_status*******

09:20:13.157 [25264] <4> drive_status: (0) DriveStatus = 2

09:20:13.157 [25264] <4> drive_status: (0) SavedModeBits = 8192

09:20:13.157 [25264] <4> drive_status: (0) AccessMode = 82

09:20:13.157 [25264] <4> drive_status: (0) Flags = 0x00000030

09:20:13.157 [25264] <4> drive_status: (0) OprComment = *NULL*

09:20:13.157 [25264] <4> drive_status: (0) SerialNum = 0000730089

09:20:13.157 [25264] <4> drive_status: (0) InquiryInfo = HP C5733A H312

09:20:13.369 [25264] <4> update_drive: (0) UpdateDrive returned 0x0

09:20:13.369 [25264] <4> emmlib_GetDriveByName: (0) Machine < maintest >, Drive < HP.C5733A.000 >

09:20:13.446 [25264] <4> emmlib_GetDriveByName: (0) *******drive_status*******

09:20:13.446 [25264] <4> drive_status: (0) DeviceIndex = 0

09:20:13.446 [25264] <4> drive_status: (0) OccupyIndex = 0

09:20:13.446 [25264] <4> drive_status: (0) OprCount = 0

09:20:13.446 [25264] <4> drive_status: (0) DriveStatus = 2

09:20:13.446 [25264] <4> drive_status: (0) SavedModeBits = 8192

09:20:13.446 [25264] <4> drive_status: (0) DriveType = 8

09:20:13.446 [25264] <4> drive_status: (0) AccessMode = 82

09:20:13.446 [25264] <4> drive_status: (0) RobotType = 7

09:20:13.446 [25264] <4> drive_status: (0) RobotNum = 0

09:20:13.446 [25264] <4> drive_status: (0) Loc1 = 1

09:20:13.446 [25264] <4> drive_status: (0) Loc5 = 0

09:20:13.446 [25264] <4> drive_status: (0) Flags = 0x02000000

09:20:13.447 [25264] <4> drive_status: (0) DeviceFlags2 = 0x00000000

09:20:13.447 [25264] <4> drive_status: (0) PathFlags2 = 0x00000000

09:20:13.447 [25264] <4> drive_status: (0) TimeMounted = 0

09:20:13.447 [25264] <4> drive_status: (0) TotalTime = 14951

09:20:13.447 [25264] <4> drive_status: (0) CleanFreq = 0

09:20:13.447 [25264] <4> drive_status: (0) LastCleanTime = 0

09:20:13.447 [25264] <4> drive_status: (0) TapeAlert1 = 0

09:20:13.447 [25264] <4> drive_status: (0) TapeAlert2 = 0

09:20:13.447 [25264] <4> drive_status: (0) LastDaCallTime = 0

09:20:13.447 [25264] <4> drive_status: (0) ApplicationType = 0

09:20:13.447 [25264] <4> drive_status: (0) DrivePath = /dev/rmt/0cbn

09:20:13.447 [25264] <4> drive_status: (0) SerialNum = 0000730089

09:20:13.447 [25264] <4> drive_status: (0) AsciiName = HP.C5733A.000

09:20:13.447 [25264] <4> drive_status: (0) InquiryInfo = HP C5733A H312

09:20:13.447 [25264] <4> drive_status: (0) MhAssignHost = maintest.uklab.veritas.com

09:20:13.447 [25264] <4> drive_status: (0) MediaServer = maintest

09:20:13.447 [25264] <4> drive_status: (0) reason = 8388673

09:20:13.447 [25264] <2> update_drive: (0) Inputs: MediaServer = < maintest >, NdmpHost = < >, DriveName = < HP.C5733A.000 >, DrivePath = < /dev/rmt/0cbn >

09:20:13.448 [25264] <4> update_drive: (0) *******drive_status*******

09:20:13.448 [25264] <4> drive_status: (0) TotalTime = 14990

09:20:13.593 [25264] <4> update_drive: (0) UpdateDrive returned 0x0

09:20:38.800 [25264] <4> LtidProcCmd: Pid=25280, Data.Pid=25280, Type=56, Param1=0, Param2=0, LongParam=0

09:20:38.800 [25264] <4> LtidProcCmd: Sending UNLOAD DONE msg to BPTM (dev 0, PID 15329)

09:20:38.800 [25264] <4> send_request_answer: Pid=15329, Type=0, ReturnType=12, DataType=0, MsgRes.SC=0

BPTM

****

09:20:38.870 [15329] <4> create_tpreq_file: symlink to path /dev/rmt/0cbn

09:20:38.873 [15329] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)

09:20:38.874 [15329] <2> tapealert_and_release: SCSI RELEASE

09:20:38.875 [15329] <2> drivename_unlock: unlocked

09:20:38.875 [15329] <2> drivename_close: Called for file HP.C5733A.000

09:20:38.875 [15329] <2> drivename_remove: Called

09:20:38.875 [15329] <2> main: Sending [EXIT STATUS 0] to NBJM

NBRM

****

NBRB sent to MDS to deallocate ressources ...

11/16/08 09:20:39.436 [Debug] NB 51216 nbrb 118 PID:25258 TID:9 File ID:118 [No context] 4 [EMMProvider::doDeAllocate] getMDSAllocation: status=0, allocationKey=40

11/16/08 09:20:39.723 [Debug] NB 51216 nbrb 118 PID:25258 TID:9 File ID:118 [No context] 4 [EMMProvider::doDeAllocate] deallocate returns 0

11/16/08 09:20:39.730 [Debug] NB 51216 nbrb 118 PID:25258 TID:9 File ID:118 [No context] 4 [EMMProvider::doDeAllocate] updateMDSAllocationDownStuCounts: status=0, allocationKey=40

Martin

punbs · ‎05-16-2012

thq vry much...

one basic thing i need to confirm, in any tool or windows end.if i fire a backup, how it will captured in media as a archive file and what are all files created along with that and how it will be helpfull.

explain me in general syntax...

regards,

punbs

Baski · ‎05-16-2012

Excellent job Martin. Even I thought the same way, but no time.

Good Job

Marianne · ‎05-16-2012

You need to explain your question please:

one basic thing i need to confirm, in any tool or windows end.if i fire a backup, how it will captured in media as a archive file and what are all files created along with that and how it will be helpfull.

Do you need to know what log files will be created?

If so, studying the process flow diagram will help you understand which process runs where (master, server, client). Understanding the process flow diagram will help you pinpoint where failure took place in the process. The log that goes with the process name can be looked at on the particular machine - master, media or client.

You can read through the Logging section of the Troubleshooting Guide to understand the difference between unified and legacy logs.

I have posted a VERY BASIC explanation of legacy logs over here: https://www-secure.symantec.com/connect/forums/how-use-logs#comment-6505511

Most day-to-day problems can be traced with legacy logs.

Handy NetBackup Links

mph999 · ‎05-17-2012

The files are written to the tape using a tar format. This is the 'netbackup' tar command, but is very similar to the os tar.

I am not sure how this is helpful, the files are on the tape, there is nothing you can do with them, apart from read them. The format is not too important.

This is an explanation of how the files are contained on the tape ...

MH = Media Header

TM = Tape Mark

BH = Backup Header

EH = Empty header

This example was from a 4mm type tape, I think for LTO (for example) the TM/ EH are slighly different at the end, but I haven't bothered 'testing' this so I am not 100% certain.

If you write data to disk, as opposed to tape, a num,ber of files are created

Example :

womble_1336120226_C1_F1.1336120226.img

womble_1336120226_C1_F1.1336120226.info

womble_1336120226_C1_HDR.1336120226.img

womble_1336120226_C1_HDR.1336120226.info

These are the 'tar' file equivelent on disk - but again, you cannot edit or do anything with these files, so the details are not too important.

NOTE - Symantec support might need to look at these files for troubleshooting, but from the position of just running the backups, this is not needed.

Martin

mph999 · ‎05-17-2012

Thanks, yes, it did take a while ...

mph999 · ‎05-17-2012

Adding to Mariannes outstanding post ...

Details about VX logs ...

I personally expect any backup admin to be able to carry out the steps, in this technote and understand them.

http://www.symantec.com/docs/TECH75805

Martin

VOX

Backup Process