Vault Eject failed, file open failed (12)

[MickBoosh]

Hi,

Since we upgraded to NBU 7 from 6.5.5 our Vault_Eject job is failing with a  file open failed (12) status almost instantly.

Sounds like a permissions problem. Any ideas?


31/08/2010 16:18:43 - requesting resource xxxxx.NBVAULT.MAXJOBS
31/08/2010 16:18:43 - requesting resource xxxxx.NBU_POLICY.MAXJOBS.Vault_eject
31/08/2010 16:18:43 - granted resource xxxxxx.NBVAULT.MAXJOBS
31/08/2010 16:18:43 - granted resource xxxxx.NBU_POLICY.MAXJOBS.Vault_eject
31/08/2010 16:18:44 - estimated 0 Kbytes needed
31/08/2010 16:18:44 - begin Parent Job
31/08/2010 16:18:44 - begin Vault, Start Notify Script
31/08/2010 16:18:44 - started process RUNCMD (3764)
31/08/2010 16:18:44 - ended process 0 (3764)
Status 0
31/08/2010 16:18:44 - end Vault, Start Notify Script; elapsed time: 00:00:00
31/08/2010 16:18:44 - begin Vault, Execute Script
31/08/2010 16:18:44 - started process bpbrm (7428)
31/08/2010 16:18:45 - begin Eject/Report
31/08/2010 16:18:45 - connecting
31/08/2010 16:18:45 - connected; connect time: 00:00:00
31/08/2010 16:18:45 - end Eject/Report; elapsed time: 00:00:00
31/08/2010 16:18:45 - end writing
Status 12
31/08/2010 16:18:45 - end Vault, Execute Script; elapsed time: 00:00:01
31/08/2010 16:18:45 - begin Vault, Stop On Error
Status 0
31/08/2010 16:18:45 - end Vault, Stop On Error; elapsed time: 00:00:00
31/08/2010 16:18:45 - begin Vault, End Notify Script
31/08/2010 16:18:45 - started process RUNCMD (5160)
31/08/2010 16:18:45 - ended process 0 (5160)
Status 0
31/08/2010 16:18:45 - end Vault, End Notify Script; elapsed time: 00:00:00
Status 12
31/08/2010 16:18:45 - end Parent Job; elapsed time: 00:00:01
file open failed(12)

[Will_Restore]

check the log file netbackup/logs/vault/log.<date>

[MickBoosh]

Ok I've created the vault folder and it appers it can't open a file. I've looked at permissions and it does have rights over the file/folder and it is present.


09:45:54.815 [6780.7972] <2> vlteject@VaultJobMonitor::_send_jobdata: SENT JobDataEx_t to JOBD at 1283330754
09:45:54.831 [6780.7292] <2> vlteject@filterSessions(): Entering filterSessions Function [IN Size: 12]
09:45:54.831 [6780.7292] <2> vlteject@filterSessions(): Retruning... [OUT Size: 12]
09:45:54.831 [6780.7292] <2> vlteject@Consolidate::getSessionsForEject(): Returning 12 number of records
09:45:54.831 [6780.7292] <2> vlteject@RobotsFactory::RobotsFactory(): Robots factory received 12 number of session records
09:45:54.831 [6780.7292] <2> vlteject@RobotsFactory::prepareRobotAndVaultObjects(): Creating Robot object for Robot 0
09:45:54.831 [6780.7292] <2> vlteject@VaultRobot::VaultRobot(): >>********** Vault Robot Starts *************<<
09:45:54.831 [6780.7292] <2> vlteject@VaultRobot::VaultRobot(): rob Type = TLD
09:45:54.831 [6780.7292] <2> vlteject@VaultRobot::VaultRobot(): Lower rob Type = tld
09:45:54.831 [6780.7292] <2> vlteject@VaultScsiRobot::VaultScsiRobot(): >>********** Vault SCSI Robot Starts *************<<
09:45:54.831 [6780.7292] <2> vlteject@RobotsFactory::prepareRobotAndVaultObjects(): Creating Vault Session object for Profile:Daily and Sessionid:1239
09:45:54.831 [6780.7292] <2> vlteject@VaultSession::VaultSession: Creating a vault session with 0 SouthTees Daily 1239
09:45:54.831 [6780.7292] <2> vlteject@ReportUtil::checkForValidityOfSession(): For SDIR=D:\Program Files\VERITAS\NetBackup\vault\sessions\xxxxxx\sid1239\logs
09:45:54.831 [6780.7292] <16> vlteject@VaultSession::VaultSession: cannot open detail.log file in directory D:\Program Files\VERITAS\NetBackup\vault\sessions\xxxxx\sid1239\logs
09:45:54.831 [6780.7292] <8> vlteject@VaultSession::VaultSession Destructor called during stack unwinding
09:45:54.831 [6780.7292] <8> vlteject@RobotsFactory::prepareRobotAndVaultObjects() Destructor called during stack unwinding
09:45:54.831 [6780.7292] <8> vlteject@RobotsFactory::RobotsFactory() Destructor called during stack unwinding
09:45:54.831 [6780.7292] <8> vlteject@veject() Destructor called during stack unwinding
09:45:54.831 [6780.7292] <2> vlteject@VaultLockProxy::release_all_locks: UpdJobd=0
09:45:54.831 [6780.7292] <8> vlteject@VaultLockProxy::release_all_locks Destructor called during stack unwinding
09:45:54.831 [6780.7292] <8> vlteject@VaultLockProxy DES Destructor called during stack unwinding
09:45:54.831 [6780.7292] <16> vlteject@main: file open failed
09:45:54.847 [6780.7292] <2> vlteject@bv_vlteject_exit(): In
09:45:54.847 [6780.7292] <2> vlteject@VaultJobMonitor::_send_try_msg: At 1283330754 sent TRY_MSG: END_OPERATION 1283330754

09:45:54.847 [6780.7292] <4> vlteject@bv_vlteject_exit():  Job Complete
09:45:54.847 [6780.7292] <2> vlteject@cancel_keepalive_thread: Entered with JOBID=534087 to cancel ThrGrpId=1
09:45:54.847 [6780.7292] <8> vlteject@cancel_keepalive_thread: Notified keepalive thread. Sleeping for a bit (4 secs)
09:45:57.815 [6780.7972] <8> vlteject@jobd_pinger: Cancel requested. Leaving...

[Will_Restore]

which describes similar failure after upgrade from 5.x to 6.0
perhaps history is repeating itself
http://seer.entsupport.symantec.com/docs/295311.htm

[MickBoosh]

Hi,

Thanks for that, I did have a look but the folder is there, where as the document states that it isn't there. I did remove the line anyway but that brought back a 282 exit code and down the vault service!

Mike

[Will_Restore]

The NetBackup Vault Manager service is down, possibly because of the following: the Vault is not licensed, the vault.xml configuration file is corrupt, or the vault.xml configuration file upgrade failed during an upgrade installation.

[MickBoosh]

It only dropped when I edited the vlteject.mstr file, I restored a copy of it and it went back to the old problem.

It maybe the vault.xml file, how could I deal with that?

[Andy_Welburn]

Looking closely at the T/N that Bill quoted & also another similar one ( http://seer.entsupport.symantec.com/docs/283390.htm :(

"...
For each of the Vault sessions that exist in the vlteject.mstr file there must be a corresponding SID folder in the /usr/openv/netbackup/vault/sessions directory.  If the directory does not exist then a Status 12 or garbage text will appear.  

In order to stop these errors from occurring it will be necessary to manually edit the vlteject.mstr file ...  Any line for a session ID that does not have a matching session directory will need to be removed.
..."

Notice "...for each..." and "...Any line..." - so should not just be looking at the sid that is being reported on but ALL sids?

[MickBoosh]

Well yeah I was only looking for 1239. In the sessions folder there are only folders 1214 to 1252 and in the vlteject.mstr file it literally starts from 1:

0/xxxxxx/Daily|1|1186669253|1186669254|1185894003|1497|0
0/xxxxxx/Daily|2|1187877641|1187877646|1185894976|1497|0
0/xxxxxx/Daily|3|1187877641|1187877646|1185980403|1805|0
0/xxxxxx/Daily|4|1187877641|1187877646|1186066803|2187|0
0/xxxxxx/Daily|5|1187877641|1187877646|1186153205|2187|0
0/xxxxxx/Daily|6|1187877641|1187877646|1186412403|4088|0

All the way to 1252

Maybe that's the problem, however I'm reluclant to start editing that file again as it caused a 282 error last time.

Having said that, we have another tape library and that is ejecting fine, it has entries in that mstr file for sids which don't exist too.

But to make it worse, when it hits about 800 or so, the entries do not start on a new line, they just follow on so it's very difficult to read.

We have logged it with symantec anyway so I'll let you know how we got on

Mike

[Andy_Welburn]

Probably the way to go. Not many other ideas forthcoming! Let us know the resolution ... (note my confidence!)

[MickBoosh · Accepted solution]

They asked us to make new vault polices and a new profile and it worked!

Problem solved

[Andy_Welburn]