Vault policy ends with - invalid command parameter (20)

[MartinVi]

Hi all,

we're running NetBackup 7.0.1 on Solaris 10 x86 and we're facing issues with our Vault policy which should run once a month. The vault job should write all monthly backup to tapes.

The policy ends as follow:

 Sep 13, 2011 8:10:10 AM - requesting resource rozrhbckb01.NBVAULT.MAXJOBS
Sep 13, 2011 8:10:10 AM - requesting resource rozrhbckb01.NBU_POLICY.MAXJOBS.vault_monthly
Sep 13, 2011 8:10:10 AM - granted resource  rozrhbckb01.NBVAULT.MAXJOBS
Sep 13, 2011 8:10:10 AM - granted resource  rozrhbckb01.NBU_POLICY.MAXJOBS.vault_monthly
Sep 13, 2011 8:10:10 AM - estimated 0 kbytes needed
Sep 13, 2011 8:10:10 AM - begin Parent Job
Sep 13, 2011 8:10:10 AM - begin Vault: Start Notify Script
Sep 13, 2011 8:10:13 AM - started process RUNCMD (pid=25791)
Sep 13, 2011 8:10:13 AM - ended process 0 (pid=25791)
Operation Status: 0
Sep 13, 2011 8:10:13 AM - end Vault: Start Notify Script; elapsed time 0:00:03
Sep 13, 2011 8:10:13 AM - begin Vault: Execute Script
Operation Status: 20
Sep 13, 2011 8:10:16 AM - end Vault: Execute Script; elapsed time 0:00:03
Sep 13, 2011 8:10:16 AM - begin Vault: Stop On Error
Operation Status: 0
Sep 13, 2011 8:10:16 AM - end Vault: Stop On Error; elapsed time 0:00:00
Sep 13, 2011 8:10:16 AM - begin Vault: End Notify Script
Sep 13, 2011 8:10:19 AM - started process RUNCMD (pid=25816)
Sep 13, 2011 8:10:19 AM - ended process 0 (pid=25816)
Operation Status: 0
Sep 13, 2011 8:10:19 AM - end Vault: End Notify Script; elapsed time 0:00:03
Operation Status: 20
Sep 13, 2011 8:10:19 AM - end Parent Job; elapsed time 0:00:09
invalid command parameter  (20) 

What could be the problem?

Here is the output from the vault logfile:

 21:08:38.766 [2901] <2> emmlib_ListMediaPool: (0)
                poolnum = 0, version = 65, poolname = None, description = the None pool
                poolhost = ANYHOST, maxPartFull = 0, pooluid = -1, poolgid = -2

21:08:38.766 [2901] <2> emmlib_ListMediaPool: (0)
                poolnum = 1, version = 65, poolname = NetBackup, description = the NetBackup pool
                poolhost = ANYHOST, maxPartFull = 0, pooluid = 0, poolgid = -2

21:08:38.766 [2901] <2> emmlib_ListMediaPool: (0)
                poolnum = 2, version = 65, poolname = DataStore, description = the DataStore pool
                poolhost = ANYHOST, maxPartFull = 0, pooluid = 0, poolgid = -2

21:08:38.766 [2901] <2> emmlib_ListMediaPool: (0)
                poolnum = 3, version = 65, poolname = CatalogBackup, description = NetBackup Catalog Backup pool
                poolhost = ANYHOST, maxPartFull = 0, pooluid = 0, poolgid = -2

21:08:38.766 [2901] <4> vlteject@cVolInvMgr::LoadInvByPool: Loaded 0 media records into volInvList
21:08:38.766 [2901] <2> vlteject@cVolInvMgr::LoadInvScratchPools: H=rozrhbckb01
21:08:38.766 [2901] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host 10.235.155.105 SUCCESS(Endpoint_Selector.cpp:1712)
21:08:38.768 [2901] <2> emmlib_ListMediaPool: (0) LIST_SCRATCH_POOL successful, emmError = 0, nbError = 0
21:08:38.768 [2901] <4> vlteject@cVolInvMgr::LoadInvScratchPools: Loaded 0 media from 0 scratch pools SC=0
21:08:38.768 [2901] <2> vnet_connect_to_vnetd_extra: ../../libvlibs/vnet_vnetd.c.187: 0: msg: VNETD CONNECT FROM 10.235.155.105.42862 TO 10.235.155.105.13724 fd = 5
21:08:38.772 [2901] <2> vnet_vnetd_disconnect: ../../libvlibs/vnet_vnetd.c.288: 0: VN_REQUEST_DISCONNECT: 1 0x00000001
21:08:38.772 [2901] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host 10.235.155.105 SUCCESS(Endpoint_Selector.cpp:1712)
21:08:38.774 [2901] <2> emmlib_ListMediaPool: (0) LIST_CATALOG_POOL successful, emmError = 0, nbError = 0
21:08:38.774 [2901] <2> emmlib_ListMediaPool: (0)
                poolnum = 3, version = 65, poolname = CatalogBackup, description = NetBackup Catalog Backup pool
                poolhost = ANYHOST, maxPartFull = 0, pooluid = 0, poolgid = -2

21:08:38.774 [2901] <4> vmdb_get_catalog_list: get catalog list request status:  successful (0)
21:08:38.774 [2901] <4> vlteject@cVolInvMgr::LoadCatalogPools: Loaded 1 CtlgPools
21:08:38.774 [2901] <2> vlteject@DistListReports::makeView: *** Started Data View ***
21:08:38.774 [2901] <2> vlteject@VaultReport::initializeReportFiles: Temp RptFile=/usr/openv/netbackup/logs/user_ops/vault/vault-02901315422518752112000000001-W1aOQf/picklist_vau
lt_ff.rpt RptID=4
21:08:38.774 [2901] <2> vlteject@VaultReport::openReportFile: File=/usr/openv/netbackup/logs/user_ops/vault/vault-02901315422518752112000000001-W1aOQf/picklist_vault_ff.rpt for R
PT_ID=4 output
21:08:38.774 [2901] <4> vlteject@DistListReports::renderReports: Started Rendering in FLAT format
21:08:38.774 [2901] <2> vlteject@DistListReports::makeView: *** Completed Data View ***
21:08:38.774 [2901] <2> vlteject@VaultReport::distribute: RptDistribution: RptType=2 Consol=0 Format=1
21:08:38.774 [2901] <2> vlteject@VaultReport::distribute: Distributing reports: RPT_ID=4
21:08:38.774 [2901] <2> vlteject@Distribute::sendToBuffer: SRC=/usr/openv/netbackup/logs/user_ops/vault/vault-02901315422518752112000000001-W1aOQf/picklist_vault_ff.rpt
21:08:38.774 [2901] <2> vlteject@ReportUtil::readFileData: File=/usr/openv/netbackup/logs/user_ops/vault/vault-02901315422518752112000000001-W1aOQf/picklist_vault_ff.rpt
21:08:38.775 [2901] <2> vlteject@ReportUtil::readFileData: Read 3 lines from file:/usr/openv/netbackup/logs/user_ops/vault/vault-02901315422518752112000000001-W1aOQf/picklist_vau
lt_ff.rpt
21:08:38.775 [2901] <2> vlteject@Distribute::sendToBuffer: RPT contains 3 lines
21:08:38.775 [2901] <2> vlteject@VaultReport::distribute: Completed RPT Dist of RPT_ID=4 with STAT=0
21:08:38.775 [2901] <4> vlteject@VaultReport::distribute: Completed Rpt distribution with STAT=0
21:08:38.775 [2901] <2> Orb::destroyOrb: orb has reference count: 1(Orb.cpp:1591)
21:08:38.776 [2901] <2> vlteject@DoReport(): Printing the Report Data to stdout
21:08:38.777 [2901] <2> vlteject@DoReport(): Printing of Report Data to stdout is complete
21:08:38.777 [2901] <2> vlteject@DoReport(): Returning 0 status from DoReport
21:08:38.777 [2901] <2> vlteject@bv_vlteject_exit(): In
21:08:38.777 [2901] <16> vlteject@VaultJobMonitor::_check_job_id Job Id NOT set. Forgot to call Init/Connect?
21:08:38.823 [2901] <16> vlteject@VaultJobMonitor::_check_job_id FAILed NB_EC=20 NB_MSG=invalid command parameter
21:08:38.843 [2901] <16> vlteject@VaultJobMonitor::_check_job_id: Leaving with DMN=1 SC=20
21:08:38.852 [2901] <16> vlteject@VaultJobMonitor::_check_job_id Job Id NOT set. Forgot to call Init/Connect?
21:08:38.863 [2901] <16> vlteject@VaultJobMonitor::_check_job_id FAILed NB_EC=20 NB_MSG=invalid command parameter
21:08:38.873 [2901] <16> vlteject@VaultJobMonitor::_check_job_id: Leaving with DMN=1 SC=20
21:08:38.882 [2901] <4> vlteject@bv_vlteject_exit():  Job Complete
21:08:38.882 [2901] <2> vlteject@cancel_keepalive_process: Entering to cancel PID=0, JOB_ID=0 with FD=-1
21:08:38.882 [2901] <16> vlteject@cancel_keepalive_process: No keepalive process spawned, leaving...
21:08:38.892 [2901] <4> DeleteConnectionID: (-) Cleared Connection ID 0
21:08:38.892 [2901] <2> uninitialize: (0) Don't shutdown shared Orb
21:08:38.892 [2901] <4> emmlib_uninitialize: (0) Successfully released EMM session and database objects
21:08:38.893 [2901] <2> Orb::destroyOrb: orb has reference count: 1(Orb.cpp:1591) 

Thanks for your help ...

Regards,

Martin

[CRZ · Accepted solution]

Attempting to execute vlteject with no parameters will return a status 20.  I suspect that may be happening here.

It almost looks like your picklist is blank - or made up of three blank lines?

Have you investigated the report to see if it actually had valid data in it to feed to the eject process?

(Is anything getting backed up?  Your first logs run in about 10 seconds, so that's another "hmm..." to me :) )