Hi, I use a vault to eject tapes at the end of the week, it failed last week and I ejected the tapes manually, I have restarted everything including the tape library, but the vault has failed this week as well. I am logging the issue with the tape library supplier as well asI'm not sure where the fault is, but is anyone able to give me any help? The details from the jobs look like this: 26/07/2013 13:17:10 - vault waiting for global lock 26/07/2013 13:17:10 - requesting resource appnbu-v.NBVAULT.MAXJOBS 26/07/2013 13:17:22 - granted resource appnbu-v.NBVAULT.MAXJOBS 26/07/2013 13:17:24 - vault global lock acquired 26/07/2013 13:17:24 - vault waiting for session ID lock 26/07/2013 13:17:24 - requesting resource appnbu-v.VAULT_CREATE_SESSION_ID.LOCK_TLD(0)_ONSITETAPES 26/07/2013 13:17:28 - granted resource appnbu-v.VAULT_CREATE_SESSION_ID.LOCK_TLD(0)_ONSITETAPES 26/07/2013 13:17:29 - vault session ID lock acquired 26/07/2013 13:17:29 - vault session ID lock released 26/07/2013 13:32:53 - duplication skipped 26/07/2013 13:32:53 - vault waiting for assign slot lock 26/07/2013 13:32:53 - requesting resource appnbu-v.VAULT_ASSIGN_SLOT.LOCK_TLD(0)_OnsiteTapes 26/07/2013 13:32:58 - granted resource appnbu-v.VAULT_ASSIGN_SLOT.LOCK_TLD(0)_OnsiteTapes 26/07/2013 13:32:58 - vault assign slot lock acquired 26/07/2013 13:33:00 - vault assign slot lock released 26/07/2013 13:33:00 - catalog backup skipped 26/07/2013 13:33:00 - vault waiting for assign slot lock 26/07/2013 13:33:00 - requesting resource appnbu-v.VAULT_ASSIGN_SLOT.LOCK_TLD(0)_OnsiteTapes 26/07/2013 13:33:10 - granted resource appnbu-v.VAULT_ASSIGN_SLOT.LOCK_TLD(0)_OnsiteTapes 26/07/2013 13:33:11 - vault assign slot lock acquired 26/07/2013 13:33:11 - vault assign slot lock released 26/07/2013 13:33:12 - before eject, waiting for media to be unmounted; sleeping for 180 seconds 26/07/2013 13:36:12 - starting eject operation 26/07/2013 13:36:12 - begin Eject/Report 26/07/2013 13:36:12 - connecting 26/07/2013 13:36:12 - connected; connect time: 00:00:00 26/07/2013 13:36:12 - vault waiting for eject lock 26/07/2013 13:36:12 - requesting resource appnbu-v.VAULT_EJECT.LOCK_0 26/07/2013 13:36:17 - granted resource appnbu-v.VAULT_EJECT.LOCK_0 26/07/2013 13:36:18 - vault eject lock acquired 26/07/2013 13:36:18 - suspend media for this session: failed to suspend 1 of 52 media at eject time 26/07/2013 13:36:18 - starting eject of 52 media 26/07/2013 13:40:34 - eject complete with status 287. 0 of 52 media ejected 26/07/2013 13:40:34 - vault eject lock released 26/07/2013 13:58:35 - vault global lock released vault eject failed(287) And in the problem reports I see this: 26/07/2013 13:32:37 MasterCluster Error 0 Retrieve <16> vltrun@main Vault Session FAILED [PRFL=0/OnsiteTapes/WeeklyEject SID=331 JID=2518878 EC=287] 26/07/2013 13:32:37 MasterCluster Error 0 Retrieve <16> vltrun@main FAILed NB_EC=287 NB_MSG=vault eject failed 26/07/2013 13:36:18 MasterCluster Error 0 Retrieve <16> vltrun@SuspendMedia^332: Suspend FAILed MEDIA=000726, HOST=appnbu-v. EMM Err=2001049 ( Media is already allocated ) 26/07/2013 13:36:18 MasterCluster Error 0 Retrieve <16> vltrun@SuspendMedia^332 FAILed MM_EC=199 MM_MSG=the media is allocated for use 26/07/2013 13:36:18 MasterCluster Error 0 Retrieve <16> vltrun@SuspendMedia^332: Leaving with DMN=2 SC=199 26/07/2013 13:36:18 MasterCluster Error 0 Retrieve <16> vltrun@VaultRobot::suspendMediaToEject()^332: suspend failed for media 000726, ignoring... 26/07/2013 13:36:18 MasterCluster Error 0 Retrieve <16> vltrun@VaultRobot::suspendMediaToEject()^332 FAILed NB_EC=97 NB_MSG=requested media id is in use, cannot process request 26/07/2013 13:36:18 MasterCluster Error 0 Retrieve <16> vltrun@VaultRobot::suspendMediaToEject()^332: Leaving with DMN=1 SC=97 26/07/2013 13:36:18 MasterCluster Error 0 Retrieve <16> vltrun@VaultScsiRobot::doEject()^332: there was a problem in doing suspending media to eject returned 97 26/07/2013 13:36:18 MasterCluster Error 0 Retrieve <16> vltrun@VaultScsiRobot::doEject()^332 FAILed NB_EC=335 NB_MSG=failure occurred while suspending media for eject 26/07/2013 13:36:32 MasterCluster Error 0 Retrieve <16> vltrun@VaultScsiRobot::doStartEject()^332: Executing command: "C:\Program Files\Veritas\Volmgr\bin\vmchange.exe" -res -multi_eject -sc -rn 0 -rt tld -rh appnbu-v -vh appnbu-v -v --- -ml 000245:000256:000273:000276 26/07/2013 13:40:20 MasterCluster Error 0 Retrieve <16> vltrun@VaultScsiRobot::doStartEject()^332: Eject Failed 26/07/2013 13:40:34 MasterCluster Error 0 Retrieve <16> vltrun@VaultScsiRobot::doEject()^332: There are problems in doing eject, returned 287 26/07/2013 13:40:34 MasterCluster Error 0 Retrieve <16> vltrun@VaultScsiRobot::doEject()^332: Leaving with DMN=1 SC=335 26/07/2013 13:40:34 MasterCluster Error 0 Retrieve <16> vltrun@VltSession::lock_and_operate^332 OP_STEP=eject_media FAILED 26/07/2013 13:40:34 MasterCluster Error 0 Retrieve <16> vltrun@VltSession::lock_and_operate^332 FAILed NB_EC=287 NB_MSG=vault eject failed 26/07/2013 13:40:34 MasterCluster Error 0 Retrieve <16> vltrun@VltSession::lock_and_operate^332: Leaving with DMN=1 SC=287 Any help would be much appriciated Thanks Katie

One of the messages I saw in the full detail.log that you sent me suggested that the issue 'could' be with the robot inventory being out-of-date. I say could, as with NBU a given error may have multiple causes, however it is sensible to try the 'most obvious' first. From waat I saw, vault did try to eject a number of tapes using a standard NBU command, so for at least some of the tapes it would appear the issue is not vault itself. Vault really only runs NBU commands (to do the dups, catalog backup and ejects, and so providing it gets as far as these commands, it pretty much clears vault as being the cause. Martin

Forum Discussion

Katiebee

Level 4

12 years ago

Vault failing Netbackup 7.1

Hi,

I use a vault to eject tapes at the end of the week, it failed last week and I ejected the tapes manually, I have restarted everything including the tape library, but the vault has failed this week as well. I am logging the issue with the tape library supplier as well asI'm not sure where the fault is, but is anyone able to give me any help?

The details from the jobs look like this:

26/07/2013 13:17:10 - vault waiting for global lock
26/07/2013 13:17:10 - requesting resource appnbu-v.NBVAULT.MAXJOBS
26/07/2013 13:17:22 - granted resource appnbu-v.NBVAULT.MAXJOBS
26/07/2013 13:17:24 - vault global lock acquired
26/07/2013 13:17:24 - vault waiting for session ID lock
26/07/2013 13:17:24 - requesting resource appnbu-v.VAULT_CREATE_SESSION_ID.LOCK_TLD(0)_ONSITETAPES
26/07/2013 13:17:28 - granted resource appnbu-v.VAULT_CREATE_SESSION_ID.LOCK_TLD(0)_ONSITETAPES
26/07/2013 13:17:29 - vault session ID lock acquired
26/07/2013 13:17:29 - vault session ID lock released
26/07/2013 13:32:53 - duplication skipped
26/07/2013 13:32:53 - vault waiting for assign slot lock
26/07/2013 13:32:53 - requesting resource appnbu-v.VAULT_ASSIGN_SLOT.LOCK_TLD(0)_OnsiteTapes
26/07/2013 13:32:58 - granted resource appnbu-v.VAULT_ASSIGN_SLOT.LOCK_TLD(0)_OnsiteTapes
26/07/2013 13:32:58 - vault assign slot lock acquired
26/07/2013 13:33:00 - vault assign slot lock released
26/07/2013 13:33:00 - catalog backup skipped
26/07/2013 13:33:00 - vault waiting for assign slot lock
26/07/2013 13:33:00 - requesting resource appnbu-v.VAULT_ASSIGN_SLOT.LOCK_TLD(0)_OnsiteTapes
26/07/2013 13:33:10 - granted resource appnbu-v.VAULT_ASSIGN_SLOT.LOCK_TLD(0)_OnsiteTapes
26/07/2013 13:33:11 - vault assign slot lock acquired
26/07/2013 13:33:11 - vault assign slot lock released
26/07/2013 13:33:12 - before eject, waiting for media to be unmounted; sleeping for 180 seconds
26/07/2013 13:36:12 - starting eject operation
26/07/2013 13:36:12 - begin Eject/Report
26/07/2013 13:36:12 - connecting
26/07/2013 13:36:12 - connected; connect time: 00:00:00
26/07/2013 13:36:12 - vault waiting for eject lock
26/07/2013 13:36:12 - requesting resource appnbu-v.VAULT_EJECT.LOCK_0
26/07/2013 13:36:17 - granted resource appnbu-v.VAULT_EJECT.LOCK_0
26/07/2013 13:36:18 - vault eject lock acquired
26/07/2013 13:36:18 - suspend media for this session: failed to suspend 1 of 52 media at eject time
26/07/2013 13:36:18 - starting eject of 52 media
26/07/2013 13:40:34 - eject complete with status 287. 0 of 52 media ejected
26/07/2013 13:40:34 - vault eject lock released
26/07/2013 13:58:35 - vault global lock released
vault eject failed(287)

And in the problem reports I see this:

26/07/2013	13:32:37	MasterCluster	Error	Retrieve	<16> vltrun@main Vault Session FAILED [PRFL=0/OnsiteTapes/WeeklyEject SID=331 JID=2518878 EC=287]
26/07/2013	13:32:37	MasterCluster	Error	Retrieve	<16> vltrun@main FAILed NB_EC=287 NB_MSG=vault eject failed
26/07/2013	13:36:18	MasterCluster	Error	Retrieve	<16> vltrun@SuspendMedia^332: Suspend FAILed MEDIA=000726, HOST=appnbu-v. EMM Err=2001049 ( Media is already allocated )
26/07/2013	13:36:18	MasterCluster	Error	Retrieve	<16> vltrun@SuspendMedia^332 FAILed MM_EC=199 MM_MSG=the media is allocated for use
26/07/2013	13:36:18	MasterCluster	Error	Retrieve	<16> vltrun@SuspendMedia^332: Leaving with DMN=2 SC=199
26/07/2013	13:36:18	MasterCluster	Error	Retrieve	<16> vltrun@VaultRobot::suspendMediaToEject()^332: suspend failed for media 000726, ignoring...
26/07/2013	13:36:18	MasterCluster	Error	Retrieve	<16> vltrun@VaultRobot::suspendMediaToEject()^332 FAILed NB_EC=97 NB_MSG=requested media id is in use, cannot process request
26/07/2013	13:36:18	MasterCluster	Error	Retrieve	<16> vltrun@VaultRobot::suspendMediaToEject()^332: Leaving with DMN=1 SC=97
26/07/2013	13:36:18	MasterCluster	Error	Retrieve	<16> vltrun@VaultScsiRobot::doEject()^332: there was a problem in doing suspending media to eject returned 97
26/07/2013	13:36:18	MasterCluster	Error	Retrieve	<16> vltrun@VaultScsiRobot::doEject()^332 FAILed NB_EC=335 NB_MSG=failure occurred while suspending media for eject
26/07/2013	13:36:32	MasterCluster	Error	Retrieve	<16> vltrun@VaultScsiRobot::doStartEject()^332: Executing command: "C:\Program Files\Veritas\Volmgr\bin\vmchange.exe" -res -multi_eject -sc -rn 0 -rt tld -rh appnbu-v -vh appnbu-v -v --- -ml 000245:000256:000273:000276
26/07/2013	13:40:20	MasterCluster	Error	Retrieve	<16> vltrun@VaultScsiRobot::doStartEject()^332: Eject Failed
26/07/2013	13:40:34	MasterCluster	Error	Retrieve	<16> vltrun@VaultScsiRobot::doEject()^332: There are problems in doing eject, returned 287
26/07/2013	13:40:34	MasterCluster	Error	Retrieve	<16> vltrun@VaultScsiRobot::doEject()^332: Leaving with DMN=1 SC=335
26/07/2013	13:40:34	MasterCluster	Error	Retrieve	<16> vltrun@VltSession::lock_and_operate^332 OP_STEP=eject_media FAILED
26/07/2013	13:40:34	MasterCluster	Error	Retrieve	<16> vltrun@VltSession::lock_and_operate^332 FAILed NB_EC=287 NB_MSG=vault eject failed
26/07/2013	13:40:34	MasterCluster	Error	Retrieve	<16> vltrun@VltSession::lock_and_operate^332: Leaving with DMN=1 SC=287

Any help would be much appriciated

Thanks

Katie

Windows Server (2003-2008)

mph999
12 years ago
One of the messages I saw in the full detail.log that you sent me suggested that the issue 'could' be with the robot inventory being out-of-date.

I say could, as with NBU a given error may have multiple causes, however it is sensible to try the 'most obvious' first.

From waat I saw, vault did try to eject a number of tapes using a standard NBU command, so for at least some of the tapes it would appear the issue is not vault itself.

Vault really only runs NBU commands (to do the dups, catalog backup and ejects, and so providing it gets as far as these commands, it pretty much clears vault as being the cause.

Martin

Katiebee
Level 4
12 years ago
Sorry, a bit more info: Last week I could manually eject the tapes, this week if I try the manual eject of one or two they eject but if i select more all say eject aborted after a couple of minutes on Netbackup but the tape library can see that one or two are in the map. I am inventorying a lot as if the manual eject fails, netbackup doesn't see that the tapes have ejected and the only way to resolve is inventory the robot.

I did see other threads on this but none with a solution
RamNagalla
Moderator
12 years ago
hi,

could you attach the detail.log and summary.log file for the failed vault session

you can find these files in /usr/openv/netbackup/vault/sessions/<profilename>/<sessionid>/
Katiebee
Level 4
12 years ago
This is the relevant bit from the detail.log, the vault is set to skip the duplication and catalog

16:22:08.478 [7668.6196] <4> vltrun@PickListReports::makeModel()^334: ***Completed Data Collection***
16:22:08.525 [7668.6196] <2> vltrun@PickListReports::makeView()^334: *** Started Data View ***
16:22:08.525 [7668.6196] <2> vltrun@VaultReport::initializeReportFiles^334: Temp RptFile=C:\Program Files\Veritas\NetBackup\Logs\user_ops\vault\vault-07668374851233425196000000000-a06196\picklist_robot.rpt RptID=0
16:22:08.525 [7668.6196] <2> vltrun@VaultReport::openReportFile^334: File=C:\Program Files\Veritas\NetBackup\Logs\user_ops\vault\vault-07668374851233425196000000000-a06196\picklist_robot.rpt for RPT_ID=0 output
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::makeView()^334: Opened report file for RPT_ID=0
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: rendering report RPR_ID=0
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Started Rendering in REGULAR format
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::createGPageHdrs()^334: RPT_ID=0
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Entering alignReportHeader for aligning REPORT_HEADER
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Breaking (if reqd)
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Broken into 0 parts
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::createCoverHdrs()^334: RPT_ID=0
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Entering alignReportHeader for aligning REPORT_TITLE
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Breaking Picking List for Robot (if reqd)
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Broken into 1 parts
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::writeGPageHdrs^334: Printed Report general page headers
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::writeCoverHdrs^334: Starting CoverPage for report
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::writeCoverHdrs^334: value of m_pageCnt, m_flatFormat, m_rptType are:1 0 1
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::writeCoverHdrs^334: Report Cover Page written out
16:22:08.541 [7668.6196] <2> vltrun@VR::writeColumnHdrs^334: Lines=3
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Completed Header Addition for Reports
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Completed Report Format Determination
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Completed Sorting the Data
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000051
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000051
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000073
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000073
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000092
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000092
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000106
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000106
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000113
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000113
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000184
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000184
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000192
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000192
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000213
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000213
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000215
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000215
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000217
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000217
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000220
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000220
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000221
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000221
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000222
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000222
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000245
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000245
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000256
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000256
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000273
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000273
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000276
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000276
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000281
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000281
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000301
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000301
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000304
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000304
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000320
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000320
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000324
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000324
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000327
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000327
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000355
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000355
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000364
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000364
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000369
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000369
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000370
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000370
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000422
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000422
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000441
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000441
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000454
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000454
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000465
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000465
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000476
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000476
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000509
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000509
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000529
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000529
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000535
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000535
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000539
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000539
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000636
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000636
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000650
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000650
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000655
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000655
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000661
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000661
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000670
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000670
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000672
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000672
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000681
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000681
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000693
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000693
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000696
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000696
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000698
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000698
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000700
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000700
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000701
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000701
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000702
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000702
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000703
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000703
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000704
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000704
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000705
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000705
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000708
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000708
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000710
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000710
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000726
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000726
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000737
16:22:08.541 [7668.6196] <2> vltrun@VaultReport::writeGPageHdrs^334: Printed Report general page headers
16:22:08.541 [7668.6196] <2> vltrun@VR::writeColumnHdrs^334: Lines=3
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000737
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000738
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000738
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000739
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000739
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printing Media details=000740
16:22:08.541 [7668.6196] <2> vltrun@PickListReports::renderReports()^334: Printed Media details=000740
16:22:08.556 [7668.6196] <2> vltrun@PickListReports::makeView()^334: Rendered report for RPT_ID=0
16:22:08.556 [7668.6196] <4> vltrun@PickListReports::makeView()^334: *** Completed Data View ***
16:22:08.556 [7668.6196] <2> vltrun@VaultReport::distribute^334: RptDistribution: RptType=1 Consol=0 Format=0
16:22:08.556 [7668.6196] <2> vltrun@VaultReport::distribute^334: Distributing reports: RPT_ID=0
16:22:08.572 [7668.6196] <2> vltrun@RU::consolidateDistributionValues^334: RPT_ID=0
16:22:08.572 [7668.6196] <2> vltrun@RU::consolidateDistributionValues^334: EM=kbroad@worcestershire.gov.uk;mparker@worcestershire.gov.uk; PR= DIR=D:\VaultReports
16:22:08.572 [7668.6196] <2> vltrun@RU::consolidateDistributionValues^334: EmailList has 3 addresses
16:22:08.572 [7668.6196] <2> vltrun@Distribute::sendToFile()^334: #Folders=1
16:22:08.572 [7668.6196] <2> vltrun@ReportUtil::createReportDirectory()^334: to create (if reqd) RptDir=D:\VaultReports
16:22:08.572 [7668.6196] <2> vltrun@ReportUtil::createReportDirectory()^334: RptDir=D:\VaultReports already exists
16:22:08.572 [7668.6196] <2> vltrun@Distribute::sendToFile()^334: RptSrc=C:\Program Files\Veritas\NetBackup\Logs\user_ops\vault\vault-07668374851233425196000000000-a06196\picklist_robot.rpt RptDest=D:\VaultReports\picklist_robot_sid334_1374851233.rpt
16:22:08.619 [7668.6196] <2> vltrun@Distribute::sendToEmail()^334: #emails=3
16:22:08.619 [7668.6196] <2> vltrun@Distribute::sendToEmail()^334: EmailAdd=,kbroad@worcestershire.gov.uk,mparker@worcestershire.gov.uk Sub=Picking List for Robot [WeeklyEject:Sid 334 ]
16:22:08.744 [7668.6196] <2> vltrun@VaultReport::distribute^334: Completed RPT Dist of RPT_ID=0 with STAT=0
16:22:08.744 [7668.6196] <4> vltrun@VaultReport::distribute^334: Completed Rpt distribution with STAT=0
16:22:08.759 [7668.6196] <2> vltrun@connectToVRTObject^334: Connecting to vccs server appnbu-v
16:22:08.759 [7668.6196] <2> vltrun@connectToVRTObject^334: VaultRuntimePortal init succeeded
16:22:08.759 [7668.6196] <8> vltrun@ReportUtil:isEjectDone()^334: Partial Eject timestamp is not found, so eject is not done
16:22:08.759 [7668.6196] <2> vltrun@ReportsFactory::createReport()^334: ReportCtgy=2
16:22:08.759 [7668.6196] <2> vltrun@RptsFactory::consolidateSubReports^334: RPT_TYPE=2
16:22:08.759 [7668.6196] <2> vltrun@ReportsFactory::getRequestedReports^334: For NORMAL REPORTS=2 #SubReports=2
16:22:08.759 [7668.6196] <2> vltrun@ReportsFactory::getRequestedReports^334: Checking if RPT=4 is enabled
16:22:08.759 [7668.6196] <2> vltrun@ReportsFactory::getRequestedReports^334: RPT=4 ENABLED
16:22:08.759 [7668.6196] <2> vltrun@ReportsFactory::getRequestedReports^334: Checking if RPT=5 is enabled
16:22:08.775 [7668.6196] <2> vltrun@VaultReport::VaultReport()^334: Vault Report with #RptSess=1
16:22:08.775 [7668.6196] <2> vltrun@VaultReport::VaultReport()^334: Rpt for session=WeeklyEject-334
16:22:08.775 [7668.6196] <2> vltrun@VaultReport::VaultReport()^334: Rpt for Containerized Vault?=>0
16:22:08.775 [7668.6196] <2> vltrun@VaultReport::VaultReport()^334: Creating RptDir=C:\Program Files\Veritas\NetBackup\Logs\user_ops\vault\vault-07668374852128775196000000001-a06196 for consol/session rpts
16:22:08.775 [7668.6196] <2> vltrun@VaultReport::initializeReportHeaderNames()^334: L10Ning Report Headers
16:22:08.791 [7668.6196] <2> vltrun@VaultReport::initializeReportHeaderNames()^334: Completed L10Ning Report Headers
16:22:08.791 [7668.6196] <4> vltrun@ReportsFactory::createReport()^334: Returing vreport by creating object of Vault Report Successfully
16:22:08.791 [7668.6196] <2> vltrun@DistListReports::makeModel^334: ***Make Model Starts***
16:22:08.791 [7668.6196] <2> vltrun@cVolInvMgr::LoadInvByPool^334: Host=appnbu-v Npools=1
16:22:08.822 [7668.6196] <4> vltrun@cVolInvMgr::LoadInvByPool^334: V_QUERY_BYPOOL H=appnbu-v Pool=DataStore
16:22:08.916 [7668.6196] <4> vltrun@cVolInvMgr::LoadInvByPool^334: Loaded 695 media records into volInvList
16:22:08.916 [7668.6196] <2> vltrun@cVolInvMgr::LoadInvScratchPools^334: H=appnbu-v
16:22:08.931 [7668.6196] <4> vltrun@cVolInvMgr::LoadInvScratchPools^334: Loaded 0 media from 0 scratch pools SC=0
16:22:08.963 [7668.6196] <4> vltrun@cVolInvMgr::LoadCatalogPools^334: Loaded 2 CtlgPools
16:22:08.963 [7668.6196] <2> vltrun@DistListReports::makeView^334: *** Started Data View ***
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::initializeReportFiles^334: Temp RptFile=C:\Program Files\Veritas\NetBackup\Logs\user_ops\vault\vault-07668374852128775196000000001-a06196\picklist_vault.rpt RptID=4
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::openReportFile^334: File=C:\Program Files\Veritas\NetBackup\Logs\user_ops\vault\vault-07668374852128775196000000001-a06196\picklist_vault.rpt for RPT_ID=4 output
16:22:08.963 [7668.6196] <4> vltrun@DistListReports::renderReports^334: Started Rendering in REGULAR format
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::createGPageHdrs()^334: RPT_ID=4
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Entering alignReportHeader for aligning REPORT_HEADER
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Breaking (if reqd)
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Broken into 0 parts
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::createCoverHdrs()^334: RPT_ID=4
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Entering alignReportHeader for aligning REPORT_TITLE
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Breaking Picking List for Vault (if reqd)
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::alignReportHeader()^334: Broken into 1 parts
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::writeGPageHdrs^334: Printed Report general page headers
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::writeCoverHdrs^334: Starting CoverPage for report
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::writeCoverHdrs^334: value of m_pageCnt, m_flatFormat, m_rptType are:1 0 2
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::writeCoverHdrs^334: Report Cover Page written out
16:22:08.963 [7668.6196] <2> vltrun@VR::writeColumnHdrs^334: Lines=4
16:22:08.963 [7668.6196] <2> vltrun@DistListReports::makeView^334: *** Completed Data View ***
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::distribute^334: RptDistribution: RptType=2 Consol=0 Format=0
16:22:08.963 [7668.6196] <2> vltrun@VaultReport::distribute^334: Distributing reports: RPT_ID=4
16:22:08.963 [7668.6196] <2> vltrun@RU::consolidateDistributionValues^334: RPT_ID=4
16:22:08.963 [7668.6196] <2> vltrun@RU::consolidateDistributionValues^334: EM=kbroad@worcestershire.gov.uk;mparker@worcestershire.gov.uk; PR= DIR=D:\VaultReports
16:22:08.963 [7668.6196] <2> vltrun@RU::consolidateDistributionValues^334: EmailList has 3 addresses
16:22:08.963 [7668.6196] <2> vltrun@Distribute::sendToFile()^334: #Folders=1
16:22:08.963 [7668.6196] <2> vltrun@ReportUtil::createReportDirectory()^334: to create (if reqd) RptDir=D:\VaultReports
16:22:08.963 [7668.6196] <2> vltrun@ReportUtil::createReportDirectory()^334: RptDir=D:\VaultReports already exists
16:22:08.963 [7668.6196] <2> vltrun@Distribute::sendToFile()^334: RptSrc=C:\Program Files\Veritas\NetBackup\Logs\user_ops\vault\vault-07668374852128775196000000001-a06196\picklist_vault.rpt RptDest=D:\VaultReports\picklist_vault_sid334_1374851233.rpt
16:22:08.978 [7668.6196] <2> vltrun@Distribute::sendToEmail()^334: #emails=3
16:22:08.978 [7668.6196] <2> vltrun@Distribute::sendToEmail()^334: EmailAdd=,kbroad@worcestershire.gov.uk,mparker@worcestershire.gov.uk Sub=Picking List for Vault [WeeklyEject:Sid 334 ]
16:22:09.056 [7668.6196] <2> vltrun@VaultReport::distribute^334: Completed RPT Dist of RPT_ID=4 with STAT=0
16:22:09.056 [7668.6196] <4> vltrun@VaultReport::distribute^334: Completed Rpt distribution with STAT=0
16:22:09.056 [7668.6196] <2> vltrun@connectToVRTObject^334: Connecting to vccs server appnbu-v
16:22:09.056 [7668.6196] <2> vltrun@connectToVRTObject^334: VaultRuntimePortal init succeeded
16:22:09.056 [7668.6196] <8> vltrun@ReportUtil:isEjectDone()^334: Partial Eject timestamp is not found, so eject is not done
16:22:09.056 [7668.6196] <2> vltrun@ReportsFactory::createReport()^334: ReportCtgy=3
16:22:09.056 [7668.6196] <2> vltrun@RptsFactory::consolidateSubReports^334: RPT_TYPE=3
16:22:09.072 [7668.6196] <2> vltrun@connectToVRTObject^334: Connecting to vccs server appnbu-v
16:22:09.072 [7668.6196] <2> vltrun@connectToVRTObject^334: VaultRuntimePortal init succeeded
16:22:09.072 [7668.6196] <8> vltrun@ReportUtil:isEjectDone()^334: Partial Eject timestamp is not found, so eject is not done
16:22:09.072 [7668.6196] <2> vltrun@ReportsFactory::createReport()^334: ReportCtgy=4
16:22:09.072 [7668.6196] <2> vltrun@RptsFactory::consolidateSubReports^334: RPT_TYPE=4
16:22:09.072 [7668.6196] <2> vltrun@connectToVRTObject^334: Connecting to vccs server appnbu-v
16:22:09.072 [7668.6196] <2> vltrun@connectToVRTObject^334: VaultRuntimePortal init succeeded
16:22:09.072 [7668.6196] <8> vltrun@ReportUtil:isEjectDone()^334: Partial Eject timestamp is not found, so eject is not done
16:22:09.072 [7668.6196] <2> vltrun@ReportsFactory::createReport()^334: ReportCtgy=5
16:22:09.072 [7668.6196] <2> vltrun@RptsFactory::consolidateSubReports^334: RPT_TYPE=5
16:22:09.072 [7668.6196] <2> vltrun@ReportsFactory::getRequestedReports^334: For NORMAL REPORTS=5 #SubReports=1
16:22:09.072 [7668.6196] <2> vltrun@ReportsFactory::getRequestedReports^334: Checking if RPT=10 is enabled
16:22:09.072 [7668.6196] <2> vltrun@RptsFactory::consolidateSubReports^334: No sub report enabled, removing session->334
16:22:09.072 [7668.6196] <2> vltrun@connectToVRTObject^334: Connecting to vccs server appnbu-v
16:22:09.072 [7668.6196] <2> vltrun@connectToVRTObject^334: VaultRuntimePortal init succeeded
16:22:09.072 [7668.6196] <8> vltrun@ReportUtil:isEjectDone()^334: Partial Eject timestamp is not found, so eject is not done
16:22:09.072 [7668.6196] <2> vltrun@ReportsFactory::createReport()^334: ReportCtgy=6
16:22:09.072 [7668.6196] <2> vltrun@RptsFactory::consolidateSubReports^334: RPT_TYPE=6
16:22:09.072 [7668.6196] <2> vltrun@vreport^334: Eject Pending. NOT Updating Reports TS V=OnsiteTapes SID=334
16:22:09.072 [7668.6196] <8> vltrun@VaultJobMonitor::IncrementJobProgress^334: BAD Job done PCT 104
16:22:09.072 [7668.6196] <8> vltrun@VltSession::sessionStep()^334: Session STEP COMPLETE
End Time  :2013.07.26 16:22:09 (1374852129)
Elapsed   :14:56
16:22:09.088 [7668.6196] <2> vltrun@VltSession::sessionStep()^334: entering function
16:22:09.088 [7668.6196] <8> vltrun@VltSession::sessionStep()^334: Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = vlt_end_notify
StartTime  = 2013.07.26 16:22:09 (1374852129)
16:22:09.088 [7668.6196] <2> vltrun@VltSession::lock_and_operate^334: OP: vlt_end_notify
16:22:09.088 [7668.6196] <4> vltrun@VltSession::analyzeSessionStatus^334: steps = 4, successful_steps = 3, final_result = 287
16:22:09.088 [7668.6196] <2> vltrun@VOpExecuteScript::doOperation^334: CALLING C:\Program Files\Veritas\NetBackup\bin\vlt_end_notify.cmd script; robot:0, vault:OnsiteTapes, profile:WeeklyEject, and sid:334
16:22:09.088 [7668.6196] <2> vltrun@VOpExecuteScript::doOperation^334: Vault Notify Script=C:\Program Files\Veritas\NetBackup\bin\vlt_end_notify.cmd RV=0
16:22:09.088 [7668.6196] <8> vltrun@VaultJobMonitor::IncrementJobProgress^334: BAD Job done PCT 101
16:22:09.088 [7668.6196] <8> vltrun@VltSession::sessionStep()^334: Session STEP COMPLETE
End Time  :2013.07.26 16:22:09 (1374852129)
Elapsed   :0:0
16:22:09.088 [7668.6196] <2> vltrun@main: Analyzing session status
16:22:09.088 [7668.6196] <4> vltrun@VltSession::analyzeSessionStatus^334: steps = 4, successful_steps = 3, final_result = 287
16:22:09.088 [7668.6196] <8> vltrun@main: vltrun Returning Status:287
16:22:09.088 [7668.6196] <2> vltrun@main^334: End Time:  2013.07.26 16:22:09 (1374852129) Elapsed: 34:05 (2045)

16:22:09.088 [7668.6196] <2> vltrun@main^334: >>********************************************************************<<
16:22:09.135 [7668.6196] <8> vltrun@VltLogger::mailSummaryLog^334: NotificationEmail ID NOT setup. Returning...
16:22:09.135 [7668.6196] <2> vltrun@main: cleanup vltrun
16:22:09.135 [7668.6196] <2> vltrun@VaultLockProxy::release_all_locks^334: UpdJobd=1
16:22:09.135 [7668.6196] <2> vltrun@VaultLockProxy::release_all_locks^334: Releasing lock Type=NBVAULT.MAXJOBS
16:22:09.135 [7668.6196] <2> vltrun@VaultLockProxy::release_lock^334: Type=NBVAULT.MAXJOBS
16:22:09.135 [7668.6196] <4> vltrun@VaultLockProxy::release_lock^334: released lock. Key=appnbu-v.NBVAULT.MAXJOBS
16:22:09.135 [7668.6196] <2> vltrun@VaultJobMonitor::_send_try_msg^334: At 1374852129 sent TRY_MSG: VAULT_GLOBAL_LOCK_RELEASED 1374852129

16:22:09.135 [7668.6196] <2> vltrun@cancel_keepalive_thread^334: Entered with JOBID=2519403 to cancel ThrGrpId=1
16:22:09.135 [7668.6196] <8> vltrun@cancel_keepalive_thread^334: Notified keepalive thread. Sleeping for a bit (4 secs)
16:22:10.963 [7668.560] <8> vltrun@jobd_pinger: Cancel requested. Leaving...
16:22:13.135 [7668.6196] <4> vltrun@main: Reporting Status=287 (vault eject failed)
16:22:13.135 [7668.6196] <16> vltrun@main Vault Session FAILED [PRFL=0/OnsiteTapes/WeeklyEject SID=334 JID=2519403 EC=287]
16:22:13.135 [7668.6196] <16> vltrun@main FAILed NB_EC=287 NB_MSG=vault eject failed
16:22:13.135 [7668.6196] <2> vltrun@VaultJobMonitor::_send_jobdata^334: SENT JobDataEx_t to JOBD at 1374852133

Summary.log is

Robot:                TLD(0)
Vault:                OnsiteTapes
Profile:              WeeklyEject
Session ID:           0
Job_Id:               2519403
====================================

Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = start_notify
StartTime  = 2013.07.26 15:48:04 (1374850084)
Session STEP COMPLETE
End Time  :2013.07.26 15:48:04 (1374850084)
Elapsed   :0:0
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = changegroup_torobot
StartTime  = 2013.07.26 15:48:04 (1374850084)
Session STEP COMPLETE
End Time  :2013.07.26 15:49:01 (1374850141)
Elapsed   :0:57
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = select
StartTime  = 2013.07.26 15:49:01 (1374850141)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:32 (1374850772)
Elapsed   :10:31
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = suspend_media
StartTime  = 2013.07.26 15:59:32 (1374850772)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:32 (1374850772)
Elapsed   :0:0
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = vlt_ejectlist_notify
StartTime  = 2013.07.26 15:59:32 (1374850772)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:32 (1374850772)
Elapsed   :0:0
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = collect_eject_media
StartTime  = 2013.07.26 15:59:32 (1374850772)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:32 (1374850772)
Elapsed   :0:0
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = assignslot_media
StartTime  = 2013.07.26 15:59:32 (1374850772)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:38 (1374850778)
Elapsed   :0:6
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = assignslot_media
StartTime  = 2013.07.26 15:59:38 (1374850778)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:49 (1374850789)
Elapsed   :0:11
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = genejectlist
StartTime  = 2013.07.26 15:59:49 (1374850789)
Generated eject list containing 59 media Id(s)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:49 (1374850789)
Elapsed   :0:0
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = recall_media
StartTime  = 2013.07.26 15:59:49 (1374850789)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:50 (1374850790)
Elapsed   :0:1
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = gen_session_debug_files
StartTime  = 2013.07.26 15:59:50 (1374850790)
Session STEP COMPLETE
End Time  :2013.07.26 15:59:50 (1374850790)
Elapsed   :0:0
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = eject_media
StartTime  = 2013.07.26 15:59:50 (1374850790)
NetBackup Media Manager Error: [2013:07:26::16:02:57] the media is allocated for use (199)
NetBackup Error: [2013:07:26::16:02:57] requested media id is in use, cannot process request (97)
NetBackup Error: [2013:07:26::16:02:57] failure occurred while suspending media for eject (335)
NetBackup Error: [2013:07:26::16:07:13] vault eject failed (287)
Session STEP COMPLETE
End Time  :2013.07.26 16:07:13 (1374851233)
Elapsed   :7:23
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = report
StartTime  = 2013.07.26 16:07:13 (1374851233)
Session STEP COMPLETE
End Time  :2013.07.26 16:22:09 (1374852129)
Elapsed   :14:56
Session STEP Information
RVP   = WeeklyEject
SID   = 334
STEP   = vlt_end_notify
StartTime  = 2013.07.26 16:22:09 (1374852129)
Session STEP COMPLETE
End Time  :2013.07.26 16:22:09 (1374852129)
Elapsed   :0:0

====================================

SUMMARY REPORT
================
Master Server:        appnbu-v
Started:              2013.07.26 15:48:04
Stopped:              2013.07.26 16:22:09
Exit Status:          vault eject failed (287)

For detailed information, please refer to:
    G:\NetBackup\vault\sessions\OnsiteTapes\sid334\logs\detail.log.

====================================

NetBackup Error: [2013:07:26::16:22:13] vault eject failed (287)
RamNagalla
Moderator
12 years ago
i would appreciate if you can provide the total log G:\NetBackup\vault\sessions\OnsiteTapes\sid334\logs\detail.log. as an attachment.
Katiebee
Level 4
12 years ago
Hi Nagalla,

This website is a public one so I am unable to upload the whole detail.log file unedited, and due to the issues that the failing vault process is causing I don't have time to abridge the whole file and replace all the server names etc. Can you be a bit more specific about what you expect or don't expect to see in the log so I can work on getting you that part?

Katie
mph999
Level 6
12 years ago
Katie,

If I PM you my address you can send it direct to me - I'll take a look when I can.

Martin
Katiebee
Level 4
12 years ago
Thanks Martin, I have sent that to you now

Katie
watsons
Level 6
12 years ago
You didn't mention how many MAPs on the library, but with your testing of ejecting 1 or 2 it will work, I'd assume there are 2 MAPs available.

26/07/2013 13:36:18 - suspend media for this session: failed to suspend 1 of 52 media at eject time
==> This will not be major issue as it can't suspend only 1 media

26/07/2013 13:36:18 - starting eject of 52 media
26/07/2013 13:40:34 - eject complete with status 287. 0 of 52 media ejected

NetBackup Media Manager Error: [2013:07:26::16:02:57] the media is allocated for use (199)
NetBackup Error: [2013:07:26::16:02:57] requested media id is in use, cannot process request (97)
NetBackup Error: [2013:07:26::16:02:57] failure occurred while suspending media for eject (335)

==> Just pick a few of those media chosen to be ejected, are they in use during the eject process? Make sure they're not. Suspended media will not be used for backup anymore, but restore job may still pick them up.

A look in the /usr/openv/netbackup/logs/vault/* will also help.
Katiebee
Level 4
12 years ago
Are you thinking that all 52 tapes are in use, or reserved for use? I have checked and there are no restores pending or tried today, and I have tried again to eject tapes using the vault. 2 have ended up in the map but Netbackup advised that the job failed with 0 of 44 ejected.

As far as I can tell they are not in use at the time of the eject. These are tapes which are full, but the primary copy of the data will still be on disk storage, so if someone were to request a restore it would come off a copy on disk.

There are 2 physical I/O drawers, one has 12 slots available and a library expansion added another 6 about 2 years ago.

I have logged a call with the tape library support although they are likely to point to the software as causing the issues (the tape library is not giving any alerts about load or eject failures), does everyone think this is some sort of hardware issue?

My Netbackup servers are windows boxes so I think the file path is the one earlier in the thread

I am also getting an error when trying to load tapes using Netbackup, which is why I am thinking it could be a hardware issue "Inventory failed: cannot move media from access port to slot (218)". I restarted all the boxes and the library last week when this all started happening, so the robot should have re-calibrated itself.

Katie
mph999
Level 6
12 years ago
One of the messages I saw in the full detail.log that you sent me suggested that the issue 'could' be with the robot inventory being out-of-date.

I say could, as with NBU a given error may have multiple causes, however it is sensible to try the 'most obvious' first.

From waat I saw, vault did try to eject a number of tapes using a standard NBU command, so for at least some of the tapes it would appear the issue is not vault itself.

Vault really only runs NBU commands (to do the dups, catalog backup and ejects, and so providing it gets as far as these commands, it pretty much clears vault as being the cause.

Martin

Forum Discussion

Vault failing Netbackup 7.1

Related Content

Integration of NITA (NetBackup IT Analytics) with Azure has failed.

NetBackup vault reports

Outlook searches fail - Enterprise vault

NetBackup BMR Restore failed communication master server

NetBackup for MySQL

Recent Discussions

Need an advise on Backup strategy for long term retention

Did a catalogue restore, but seem to have missing information.

ost datadomain download file

systemctl status netbackup show failed

Image Sharing Support for MSDP!