Vault failing Netbackup 7.1

[Katiebee]

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

[Katiebee]

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]

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]

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]

i would appreciate if you can provide the total log G:\NetBackup\vault\sessions\OnsiteTapes\sid334\logs\detail.log. as an attachment.

[Katiebee]

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]

Katie,

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

Martin

[Katiebee]

Thanks Martin, I have sent that to you now

Katie

[watsons]

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]

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 · Accepted solution]

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]

I managed to eject a tape that had failed to vault manually from the library itself, so I tried a vault again (just the eject, skipped the dups and catalog) and this worked. Loading tapes then failed part way through, but looking at the robot logs which I am now collecting, it does seem to be a problem with the robot itself. Managed to load tapes for overnight duplications, came in this morning to find them all frozen...

To start the logs Martin (mph999) advised that I set the following:

On the robot control host.

Create dir.

<install path>\veritas\volmgr\debug\robots

Create empty file

<install path>\veritas\volmgr\ROBOT_DEBUG

Add VERBOSE to

<install path>\veritas\volmgr\vm.conf

(Restart services on robot control host)

I'm going to harass the library support a bit more as it really looks to me that the robot is not communicating correctly.

[Katiebee]

With a lot of help from mph999 and Marianne it has been decided that the fault or error is definitely coming from the library itself.

This is demonstrated in the robot log:

17:22:45.372 [2700.1124] <5> tldcd:move_medium: TLD(0) initiating MOVE_MEDIUM from addr 16 to addr 4139

17:22:48.043 [2700.1124] <3> tldcd:log_scsi_error: TLD(0) key = 0x5, asc = 0x53, ascq = 0x81, ATTEMPTED TO EXTEND EMPTY ENTRY/EXIT PORT

17:22:48.043 [2700.1124] <3> tldcd:move_medium: TLD(0) Move_medium error

17:22:48.043 [2700.1124] <5> tldcd:tld_main: TLD(0) closing/unlocking robotic path

17:22:48.043 [2700.1124] <3> tldcd:ChildExit: TLD Child process 2700 has terminated abnormally: Cannot move from media access port to slot

17:22:48.965 [2392.7552] <6> tldcd:check_unit_attention: command_init to check for UA on robot 0

17:36:19.492 [6580.3276] <5> tldcd:move_medium: TLD(0) initiating MOVE_MEDIUM from addr 19 to addr 4176

17:36:21.805 [6580.3276] <3> tldcd:log_scsi_error: TLD(0) key = 0x5, asc = 0x53, ascq = 0x81, ATTEMPTED TO EXTEND EMPTY ENTRY/EXIT PORT

17:36:21.805 [6580.3276] <3> tldcd:move_medium: TLD(0) Move_medium error

17:36:21.805 [6580.3276] <5> tldcd:tld_main: TLD(0) closing/unlocking robotic path

17:36:21.820 [6580.3276] <3> tldcd:ChildExit: TLD Child process 6580 has terminated abnormally: Cannot move from media access port to slot

17:38:34.953 [7356.3332] <5> tldcd:move_medium: TLD(0) initiating MOVE_MEDIUM from addr 20 to addr 4177

17:38:37.250 [7356.3332] <3> tldcd:log_scsi_error: TLD(0) key = 0x5, asc = 0x53, ascq = 0x81, ATTEMPTED TO EXTEND EMPTY ENTRY/EXIT PORT

17:38:37.250 [7356.3332] <3> tldcd:move_medium: TLD(0) Move_medium error

17:38:37.250 [7356.3332] <5> tldcd:tld_main: TLD(0) closing/unlocking robotic path

17:38:37.250 [7356.3332] <3> tldcd:ChildExit: TLD Child process 7356 has terminated abnormally: Cannot move from media access port to slot

With the library error message specifically being

key = 0x5, asc = 0x53, ascq = 0x81, ATTEMPTED TO EXTEND EMPTY ENTRY/EXIT PORT

Martin offered the following as well,

 To get the exact meaning, you will probably have to ask the library vendor, as it is their hardware that is producing the error.

I'll have another look, but I didn't find an exact match in out TNs.

However, I can confirm ASC/ ASCQ errors are sent from the hardware, impossible for NBU to generate this error.

....

Key Code Qualifier is an error-code returned by a SCSI device.

When a SCSI target device returns a check condition in response to a command, the initiator usually then issues a SCSI Request Sense command. This process is part of a SCSI protocol called Contingent Allegiance Condition. The target will respond to the Request Sense command with a set of SCSI sense data which includes three fields giving increasing levels of detail about the error

The vendor Quantum has not really offered an explanation yet but is sending me a bucket load of parts and an engineer to investigate further.

I'm marking this as solved as we have concluded that the fault is not with Netbackup

Thank you everyone for you help

Katie