21/04/2022 06:00:00.007 V-116-215 [BaseJob::run] jobid=48218 submitted to nbjm for processing
21/04/2022 06:00:00.023 [JobInstance::state] (00000000044ADE90) state=0(JobInstance.cpp:365)
21/04/2022 06:00:00.023 V-117-56 [BackupJob::sendRequestToRB] requesting resources from RB for backup job (jobid=48218)
21/04/2022 06:00:00.039 V-118-227 [ResBroker_i::requestResources] received resource request ID {696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}, priority 999, secondary priority 26384, description THE_BACKUP_JOB-48218-{696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}
21/04/2022 06:00:00.039 [ResBroker_i::requestResources] RequestSeq:
Request=0 provider=NamedResourceProvider resourcename=bkp01.NBU_CATALOG.MAXJOBS CountedResourceRequest { max=1 }
21/04/2022 06:00:00.054 [ResBroker_i::evaluateOne] Evaluating request ID {696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}
21/04/2022 06:00:00.054 [ProviderManager::allocate] NamedResourceProvider returned Allocation Granted for request ID {696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}
21/04/2022 06:00:00.070 [JobInstance::state] (00000000044ADE90) state=1(JobInstance.cpp:365)
21/04/2022 06:00:00.070 V-117-296 [BackupJob::extractResourceAttributes] unable to get storage unit resource attribute
21/04/2022 06:00:00.070 V-117-296 [BackupJob::extractResourceAttributes] unable to get media server resource attribute
21/04/2022 06:00:00.070 [BackupJob::extractResourceAttributes] (00000000044ADE90) media server=(BackupJob.cpp:1439)
21/04/2022 06:00:00.070 V-117-296 [BackupJob::extractResourceAttributes] unable to get stu name resource attribute
21/04/2022 06:00:00.070 V-117-296 [BackupJob::extractResourceAttributes] unable to get mpxid resource attribute
21/04/2022 06:00:00.070 [BackupJob::processProxyResponse] (00000000044ADE90) Done: flush proxy response, next:start job, jobid=48218(BackupJob.cpp:4081)
21/04/2022 06:00:00.070 [JobInstance::state] (00000000044ADE90) state=1(JobInstance.cpp:365)
21/04/2022 06:00:00.070 [JobInstance::state] (00000000044ADE90) state=1(JobInstance.cpp:365)
21/04/2022 06:00:00.070 [ResBroker_i::evaluateOne] resources found for request, requestId={696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}, userId=jobid=48218, birthTime=1650517200, timeToFirstEval=0 sec, timeToSuccessOrFailure=0 sec, numberOfTimesEvaluated=1
21/04/2022 06:00:00.070 V-118-109 [ResBroker_i::passOne] resources found for request ID {696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}, following allocations are granted:
21/04/2022 06:00:00.070 V-118-228 [ResBroker_i::passOne] allocation ID {A89A2704-9FBB-4722-BF5F-9F0D37D588A4}, group ID {00000000-0000-0000-0000-000000000000}, provider NamedResourceProvider, resource bkp01.NBU_CATALOG.MAXJOBS
21/04/2022 06:00:00.070 [ResBroker_i::passOne] allocation: (Allocation: id={A89A2704-9FBB-4722-BF5F-9F0D37D588A4} provider=NamedResourceProvider resourcename=bkp01.NBU_CATALOG.MAXJOBS masterserver=bkp01 groupid={00000000-0000-0000-0000-000000000000} userSequence=-1 userid="jobid=48218"  firstuserid="jobid=48218" named resource allocation)
21/04/2022 06:00:00.070 V-118-249 [CallbackQueue::resourcesAvailable] added allocations to the callback queue for request ID {696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}
21/04/2022 06:00:00.070 V-118-250 [CallbackQueue::notifyClientAvailable] queueing notification of availability of resources for request ID {696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}
21/04/2022 06:00:00.070 V-118-256 [CorbaCall_notifyClientAvailable::execute] sending availability of resources to nbjm for request ID {696EF702-2FFA-4C1A-B2B5-8141E6E58FF1}
21/04/2022 06:00:00.242 [GenBackupJob::processProxyResponse] (00000000044ADE90) Done: create image, Next: start genjob, proxy status=0(GenBackupJob.cpp:899)
21/04/2022 06:00:00.242 [JobInstance::state] (00000000044ADE90) state=1(JobInstance.cpp:365)
21/04/2022 06:00:00.257 [GenBackupJob::spawnGenericJob] (00000000044ADE90) start CommandActions(GenBackupJob.cpp:680)
21/04/2022 06:00:00.257 [GenBackupJob::spawnGenericJob] GenBackupJob Commandline Options=
**************************
* GenBackupJob           *
**************************
Jobid            = 48218
GroupId          = 48218
SubType          = 35
MediaServer      = 
MasterServer     = bkp01
PolicyName       = Catalogue
SchedName        = incr_daily
SchedType        = 1
ClientName       = bkp01
ClientType       = 35
Stream Num       = -1
Birthtime        = 1650517200
BackupCopy       = 0
BackupId         = bkp01_1650517200
SnapshotId       = 
User             = root
BMRSave          = no
StreamDiscovery  = no
Resume           = no
Checkpoint       = no
UseInternalJobid = no
OpaqueString     =  -cbustart 0 -cbuend 0 -cbustart 0 -cbuend 0

**************************
*BackupJob               *
(jobid=48218 jobtype=6)
**************************
isStdBackup       = false
backupType        = 6
subtype           = 35
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 1650517200
backupid          = bkp01_1650517200
Active pid        = 0
Job Count         = 1
IPaddr            = 
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 0
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = Catalogue
Num copies        = 1
Include_file#     = 1
resourceCount     = 1
Stu               = MSDP_DP-MSDP1
Pool              = NetBackup
Retention         = 0
UseLocal          = false
(GenBackupJob.cpp:748)
21/04/2022 06:00:00.257 [Info] V-117-32 Map jobtype to column=7, column name=CATALOG_BACKUP:
21/04/2022 06:00:00.257 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:StartNotifyScript] m_JobStep=1, Jobid=48218
21/04/2022 06:00:00.257 [Info] V-117-122 started backup job for client bkp01, policy Catalogue, schedule incr_daily on storage unit <?>
21/04/2022 06:00:01.007 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:StartNotifyScript] m_JobStep=1, Jobid=48218, returns=0
21/04/2022 06:00:01.007 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:DbmQuery] m_JobStep=2, Jobid=48218
21/04/2022 06:01:48.024 [JobInstance::state] (00000000044ADE90) state=5(JobInstance.cpp:365)
21/04/2022 06:01:48.024 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:DbmQuery] m_JobStep=2, Jobid=48218, returns=2
21/04/2022 06:01:48.024 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:StopOnError] m_JobStep=-5, Jobid=48218
21/04/2022 06:01:48.024 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:StopOnError] m_JobStep=3, Jobid=48218, returns=0
21/04/2022 06:01:48.024 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:EndNotifyScript] m_JobStep=4, Jobid=48218
21/04/2022 06:01:48.774 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:EndNotifyScript] m_JobStep=4, Jobid=48218, returns=0
21/04/2022 06:01:48.774 [Info] V-117-107 *********** Jobid 48218 status summary for CATALOG_BACKUP: *********
21/04/2022 06:01:48.774 [Info] V-117-114 Step 1 StartNotifyScript status 0 jobstatus -
21/04/2022 06:01:48.774 [Info] V-117-114 Step 2 DbmQuery status 2 jobstatus 2
21/04/2022 06:01:48.774 [Info] V-117-114 Step 3 ValidateImage status - jobstatus 2
21/04/2022 06:01:48.790 [Info] V-117-114 Step 4 EndNotifyScript status 0 jobstatus 2
21/04/2022 06:01:48.790 [Info] V-117-111 ********** job status is 2 **********
21/04/2022 06:01:48.790 [Info] V-117-52 GenBackupJob Terminating status=2
21/04/2022 06:01:48.790 [JobInstance::state] (00000000044ADE90) state=5(JobInstance.cpp:365)
21/04/2022 06:01:48.790 [JobInstance::state] (00000000044ADE90) state=5(JobInstance.cpp:365)
21/04/2022 06:01:48.790 [JobInstance::state] (00000000044ADE90) state=11(JobInstance.cpp:365)
21/04/2022 06:01:48.790 [BackupJob::sendNotifications] (00000000044ADE90) disable resume=false, brm started=false(BackupJob.cpp:2717)
21/04/2022 06:01:48.790 V-117-239 [BackupJob::terminateThisJob] terminated job, jobid=48218, status=2 (null)
21/04/2022 06:01:48.790 [BackupJob::~BackupJob] (dump Backup Job): 
**************************
*BackupJob               *
(jobid=48218 jobtype=6)
**************************
isStdBackup       = false
backupType        = 6
subtype           = 35
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 1650517200
backupid          = bkp01_1650517200
Active pid        = 0
Job Count         = 1
IPaddr            = 
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 0
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = Catalogue
Num copies        = 1
Include_file#     = 1
resourceCount     = 1
Stu               = MSDP_DP-MSDP1
Pool              = NetBackup
Retention         = 0
UseLocal          = false
(BackupJob.cpp:437)
21/04/2022 06:01:48.790 V-116-216 [RecoverableJob::doJobCompletion] jobid=48218 completed with status 2
21/04/2022 06:01:48.790 V-118-102 [ResBroker_i::releaseOne] releasing allocation ID {A89A2704-9FBB-4722-BF5F-9F0D37D588A4}
21/04/2022 06:01:48.806 [Scheduler::forwardRun] (ID:00000000048C77A8) DEBUG stream=-1 m_lastBackup=138694685330000000(Scheduler.cpp:499)
21/04/2022 06:01:48.821 [Scheduler::forwardRun] (ID:00000000048C77A8) DEBUG stream=-1 m_lastBackup=138697236000000000(Scheduler.cpp:499)
21/04/2022 06:01:48.821 [Scheduler::forwardRun] (ID:00000000048C77A8) DEBUG stream=-1 m_lastBackup=138697236000000000(Scheduler.cpp:499)
21/04/2022 06:01:48.821 V-116-222 [RecoverableJob::registerForRetryTime] retry of jobid=48218 schedule for 21/04/2022 07:11:48
21/04/2022 06:01:48.821 [Info] V-116-14 CLIENT bkp01  POLICY Catalogue  SCHED incr_daily  EXIT STATUS 2 (none of the requested files were backed up) VBRF 1 2
21/04/2022 06:01:48.837 [Error] V-116-305 catalog backup exited with status 2 (none of the requested files were backed up)
21/04/2022 06:11:48.000 V-116-215 [RecoverableJob::run_SUBMIT_RETRY] jobid=48218 submitted to nbjm for processing
21/04/2022 06:11:48.016 [JobInstance::state] (00000000044BF4E0) state=0(JobInstance.cpp:365)
21/04/2022 06:11:48.016 V-117-56 [BackupJob::sendRequestToRB] requesting resources from RB for backup job (jobid=48218)
21/04/2022 06:11:48.016 V-118-227 [ResBroker_i::requestResources] received resource request ID {E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}, priority 999, secondary priority 26384, description THE_BACKUP_JOB-48218-{E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}
21/04/2022 06:11:48.016 [ResBroker_i::requestResources] RequestSeq:
Request=0 provider=NamedResourceProvider resourcename=bkp01.NBU_CATALOG.MAXJOBS CountedResourceRequest { max=1 }
21/04/2022 06:11:48.047 [JobInstance::state] (00000000044BF4E0) state=1(JobInstance.cpp:365)
21/04/2022 06:11:48.047 V-117-296 [BackupJob::extractResourceAttributes] unable to get storage unit resource attribute
21/04/2022 06:11:48.047 V-117-296 [BackupJob::extractResourceAttributes] unable to get media server resource attribute
21/04/2022 06:11:48.047 [BackupJob::extractResourceAttributes] (00000000044BF4E0) media server=(BackupJob.cpp:1439)
21/04/2022 06:11:48.047 V-117-296 [BackupJob::extractResourceAttributes] unable to get stu name resource attribute
21/04/2022 06:11:48.047 V-117-296 [BackupJob::extractResourceAttributes] unable to get mpxid resource attribute
21/04/2022 06:11:48.047 [BackupJob::processProxyResponse] (00000000044BF4E0) Done: flush proxy response, next:start job, jobid=48218(BackupJob.cpp:4081)
21/04/2022 06:11:48.047 [JobInstance::state] (00000000044BF4E0) state=1(JobInstance.cpp:365)
21/04/2022 06:11:48.047 [JobInstance::state] (00000000044BF4E0) state=1(JobInstance.cpp:365)
21/04/2022 06:11:48.047 [ResBroker_i::evaluateOne] Evaluating request ID {E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}
21/04/2022 06:11:48.047 [ProviderManager::allocate] NamedResourceProvider returned Allocation Granted for request ID {E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}
21/04/2022 06:11:48.047 [ResBroker_i::evaluateOne] resources found for request, requestId={E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}, userId=jobid=48218, birthTime=1650517908, timeToFirstEval=0 sec, timeToSuccessOrFailure=0 sec, numberOfTimesEvaluated=1
21/04/2022 06:11:48.047 V-118-109 [ResBroker_i::passOne] resources found for request ID {E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}, following allocations are granted:
21/04/2022 06:11:48.047 V-118-228 [ResBroker_i::passOne] allocation ID {33B19C95-2F66-4348-97E0-ABAE945E0C37}, group ID {00000000-0000-0000-0000-000000000000}, provider NamedResourceProvider, resource bkp01.NBU_CATALOG.MAXJOBS
21/04/2022 06:11:48.047 [ResBroker_i::passOne] allocation: (Allocation: id={33B19C95-2F66-4348-97E0-ABAE945E0C37} provider=NamedResourceProvider resourcename=bkp01.NBU_CATALOG.MAXJOBS masterserver=bkp01 groupid={00000000-0000-0000-0000-000000000000} userSequence=-1 userid="jobid=48218"  firstuserid="jobid=48218" named resource allocation)
21/04/2022 06:11:48.047 V-118-249 [CallbackQueue::resourcesAvailable] added allocations to the callback queue for request ID {E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}
21/04/2022 06:11:48.047 V-118-250 [CallbackQueue::notifyClientAvailable] queueing notification of availability of resources for request ID {E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}
21/04/2022 06:11:48.047 V-118-256 [CorbaCall_notifyClientAvailable::execute] sending availability of resources to nbjm for request ID {E130FC77-0EAD-4A3E-8D5B-F5164A53AB09}
21/04/2022 06:11:48.141 [GenBackupJob::processProxyResponse] (00000000044BF4E0) Done: create image, Next: start genjob, proxy status=0(GenBackupJob.cpp:899)
21/04/2022 06:11:48.141 [JobInstance::state] (00000000044BF4E0) state=1(JobInstance.cpp:365)
21/04/2022 06:11:48.156 [GenBackupJob::spawnGenericJob] (00000000044BF4E0) start CommandActions(GenBackupJob.cpp:680)
21/04/2022 06:11:48.156 [GenBackupJob::spawnGenericJob] GenBackupJob Commandline Options=
**************************
* GenBackupJob           *
**************************
Jobid            = 48218
GroupId          = 48218
SubType          = 35
MediaServer      = 
MasterServer     = bkp01
PolicyName       = Catalogue
SchedName        = incr_daily
SchedType        = 1
ClientName       = bkp01
ClientType       = 35
Stream Num       = -1
Birthtime        = 1650517908
BackupCopy       = 0
BackupId         = bkp01_1650517908
SnapshotId       = 
User             = root
BMRSave          = no
StreamDiscovery  = no
Resume           = no
Checkpoint       = no
UseInternalJobid = no
OpaqueString     =  -cbustart 0 -cbuend 0 -cbustart 0 -cbuend 0

**************************
*BackupJob               *
(jobid=48218 jobtype=6)
**************************
isStdBackup       = false
backupType        = 6
subtype           = 35
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 1650517908
backupid          = bkp01_1650517908
Active pid        = 0
Job Count         = 1
IPaddr            = 
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 0
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = Catalogue
Num copies        = 1
Include_file#     = 1
resourceCount     = 1
Stu               = MSDP_DP-MSDP1
Pool              = NetBackup
Retention         = 0
UseLocal          = false
(GenBackupJob.cpp:748)
21/04/2022 06:11:48.156 [Info] V-117-32 Map jobtype to column=7, column name=CATALOG_BACKUP:
21/04/2022 06:11:48.156 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:StartNotifyScript] m_JobStep=1, Jobid=48218
21/04/2022 06:11:48.172 [Info] V-117-122 started backup job for client bkp01, policy Catalogue, schedule incr_daily on storage unit <?>
21/04/2022 06:11:48.922 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:StartNotifyScript] m_JobStep=1, Jobid=48218, returns=0
21/04/2022 06:11:48.922 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:DbmQuery] m_JobStep=2, Jobid=48218
21/04/2022 06:13:40.488 [JobInstance::state] (00000000044BF4E0) state=5(JobInstance.cpp:365)
21/04/2022 06:13:40.488 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:DbmQuery] m_JobStep=2, Jobid=48218, returns=2
21/04/2022 06:13:40.488 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:StopOnError] m_JobStep=-5, Jobid=48218
21/04/2022 06:13:40.488 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:StopOnError] m_JobStep=3, Jobid=48218, returns=0
21/04/2022 06:13:40.488 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:EndNotifyScript] m_JobStep=4, Jobid=48218
21/04/2022 06:13:41.238 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:EndNotifyScript] m_JobStep=4, Jobid=48218, returns=0
21/04/2022 06:13:41.238 [Info] V-117-107 *********** Jobid 48218 status summary for CATALOG_BACKUP: *********
21/04/2022 06:13:41.238 [Info] V-117-114 Step 1 StartNotifyScript status 0 jobstatus -
21/04/2022 06:13:41.238 [Info] V-117-114 Step 2 DbmQuery status 2 jobstatus 2
21/04/2022 06:13:41.238 [Info] V-117-114 Step 3 ValidateImage status - jobstatus 2
21/04/2022 06:13:41.238 [Info] V-117-114 Step 4 EndNotifyScript status 0 jobstatus 2
21/04/2022 06:13:41.238 [Info] V-117-111 ********** job status is 2 **********
21/04/2022 06:13:41.238 [Info] V-117-52 GenBackupJob Terminating status=2
21/04/2022 06:13:41.238 [JobInstance::state] (00000000044BF4E0) state=5(JobInstance.cpp:365)
21/04/2022 06:13:41.238 [JobInstance::state] (00000000044BF4E0) state=5(JobInstance.cpp:365)
21/04/2022 06:13:41.238 [JobInstance::state] (00000000044BF4E0) state=11(JobInstance.cpp:365)
21/04/2022 06:13:41.238 [BackupJob::sendNotifications] (00000000044BF4E0) disable resume=false, brm started=false(BackupJob.cpp:2717)
21/04/2022 06:13:41.238 V-117-239 [BackupJob::terminateThisJob] terminated job, jobid=48218, status=2 (null)
21/04/2022 06:13:41.238 [BackupJob::~BackupJob] (dump Backup Job): 
**************************
*BackupJob               *
(jobid=48218 jobtype=6)
**************************
isStdBackup       = false
backupType        = 6
subtype           = 35
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 1650517908
backupid          = bkp01_1650517908
Active pid        = 0
Job Count         = 1
IPaddr            = 
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 0
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = Catalogue
Num copies        = 1
Include_file#     = 1
resourceCount     = 1
Stu               = MSDP_DP-MSDP1
Pool              = NetBackup
Retention         = 0
UseLocal          = false
(BackupJob.cpp:437)
21/04/2022 06:13:41.238 V-116-216 [RecoverableJob::doJobCompletion] jobid=48218 completed with status 2
21/04/2022 06:13:41.254 [Scheduler::forwardRun] (ID:00000000048C7BE8) DEBUG stream=-1 m_lastBackup=138694685330000000(Scheduler.cpp:499)
21/04/2022 06:13:41.254 V-118-102 [ResBroker_i::releaseOne] releasing allocation ID {33B19C95-2F66-4348-97E0-ABAE945E0C37}
21/04/2022 06:13:41.269 [Scheduler::forwardRun] (ID:00000000048C7BE8) DEBUG stream=-1 m_lastBackup=138697236000000000(Scheduler.cpp:499)
21/04/2022 06:13:41.269 [Scheduler::forwardRun] (ID:00000000048C7BE8) DEBUG stream=-1 m_lastBackup=138697236000000000(Scheduler.cpp:499)
21/04/2022 06:13:41.269 V-116-222 [RecoverableJob::registerForRetryTime] retry of jobid=48218 schedule for 21/04/2022 07:23:41
21/04/2022 06:13:41.269 [Info] V-116-14 CLIENT bkp01  POLICY Catalogue  SCHED incr_daily  EXIT STATUS 2 (none of the requested files were backed up) VBRF 1 2
21/04/2022 06:13:41.285 [Error] V-116-305 catalog backup exited with status 2 (none of the requested files were backed up)
21/04/2022 06:23:41.004 V-116-215 [RecoverableJob::run_SUBMIT_RETRY] jobid=48218 submitted to nbjm for processing
21/04/2022 06:23:41.020 [JobInstance::state] (00000000043F9FB0) state=0(JobInstance.cpp:365)
21/04/2022 06:23:41.020 V-117-56 [BackupJob::sendRequestToRB] requesting resources from RB for backup job (jobid=48218)
21/04/2022 06:23:41.020 V-118-227 [ResBroker_i::requestResources] received resource request ID {DB3719A8-7031-4944-BBAD-FEF6813D2F6B}, priority 999, secondary priority 26384, description THE_BACKUP_JOB-48218-{DB3719A8-7031-4944-BBAD-FEF6813D2F6B}
21/04/2022 06:23:41.020 [ResBroker_i::requestResources] RequestSeq:
Request=0 provider=NamedResourceProvider resourcename=bkp01.NBU_CATALOG.MAXJOBS CountedResourceRequest { max=1 }
21/04/2022 06:23:41.035 [ResBroker_i::evaluateOne] Evaluating request ID {DB3719A8-7031-4944-BBAD-FEF6813D2F6B}
21/04/2022 06:23:41.035 [ProviderManager::allocate] NamedResourceProvider returned Allocation Granted for request ID {DB3719A8-7031-4944-BBAD-FEF6813D2F6B}
21/04/2022 06:23:41.035 [ResBroker_i::evaluateOne] resources found for request, requestId={DB3719A8-7031-4944-BBAD-FEF6813D2F6B}, userId=jobid=48218, birthTime=1650518621, timeToFirstEval=0 sec, timeToSuccessOrFailure=0 sec, numberOfTimesEvaluated=1
21/04/2022 06:23:41.051 [JobInstance::state] (00000000043F9FB0) state=1(JobInstance.cpp:365)
21/04/2022 06:23:41.051 V-117-296 [BackupJob::extractResourceAttributes] unable to get storage unit resource attribute
21/04/2022 06:23:41.051 V-117-296 [BackupJob::extractResourceAttributes] unable to get media server resource attribute
21/04/2022 06:23:41.051 [BackupJob::extractResourceAttributes] (00000000043F9FB0) media server=(BackupJob.cpp:1439)
21/04/2022 06:23:41.051 V-117-296 [BackupJob::extractResourceAttributes] unable to get stu name resource attribute
21/04/2022 06:23:41.051 V-117-296 [BackupJob::extractResourceAttributes] unable to get mpxid resource attribute
21/04/2022 06:23:41.051 [BackupJob::processProxyResponse] (00000000043F9FB0) Done: flush proxy response, next:start job, jobid=48218(BackupJob.cpp:4081)
21/04/2022 06:23:41.051 [JobInstance::state] (00000000043F9FB0) state=1(JobInstance.cpp:365)
21/04/2022 06:23:41.051 [JobInstance::state] (00000000043F9FB0) state=1(JobInstance.cpp:365)
21/04/2022 06:23:41.051 V-118-109 [ResBroker_i::passOne] resources found for request ID {DB3719A8-7031-4944-BBAD-FEF6813D2F6B}, following allocations are granted:
21/04/2022 06:23:41.051 V-118-228 [ResBroker_i::passOne] allocation ID {BA2A8410-5DDD-4FCB-82C7-68190D7C17CC}, group ID {00000000-0000-0000-0000-000000000000}, provider NamedResourceProvider, resource bkp01.NBU_CATALOG.MAXJOBS
21/04/2022 06:23:41.051 [ResBroker_i::passOne] allocation: (Allocation: id={BA2A8410-5DDD-4FCB-82C7-68190D7C17CC} provider=NamedResourceProvider resourcename=bkp01.NBU_CATALOG.MAXJOBS masterserver=bkp01 groupid={00000000-0000-0000-0000-000000000000} userSequence=-1 userid="jobid=48218"  firstuserid="jobid=48218" named resource allocation)
21/04/2022 06:23:41.051 V-118-249 [CallbackQueue::resourcesAvailable] added allocations to the callback queue for request ID {DB3719A8-7031-4944-BBAD-FEF6813D2F6B}
21/04/2022 06:23:41.051 V-118-250 [CallbackQueue::notifyClientAvailable] queueing notification of availability of resources for request ID {DB3719A8-7031-4944-BBAD-FEF6813D2F6B}
21/04/2022 06:23:41.051 V-118-256 [CorbaCall_notifyClientAvailable::execute] sending availability of resources to nbjm for request ID {DB3719A8-7031-4944-BBAD-FEF6813D2F6B}
21/04/2022 06:23:41.098 [GenBackupJob::processProxyResponse] (00000000043F9FB0) Done: create image, Next: start genjob, proxy status=0(GenBackupJob.cpp:899)
21/04/2022 06:23:41.098 [JobInstance::state] (00000000043F9FB0) state=1(JobInstance.cpp:365)
21/04/2022 06:23:41.113 [GenBackupJob::spawnGenericJob] (00000000043F9FB0) start CommandActions(GenBackupJob.cpp:680)
21/04/2022 06:23:41.113 [GenBackupJob::spawnGenericJob] GenBackupJob Commandline Options=
**************************
* GenBackupJob           *
**************************
Jobid            = 48218
GroupId          = 48218
SubType          = 35
MediaServer      = 
MasterServer     = bkp01
PolicyName       = Catalogue
SchedName        = incr_daily
SchedType        = 1
ClientName       = bkp01
ClientType       = 35
Stream Num       = -1
Birthtime        = 1650518621
BackupCopy       = 0
BackupId         = bkp01_1650518621
SnapshotId       = 
User             = root
BMRSave          = no
StreamDiscovery  = no
Resume           = no
Checkpoint       = no
UseInternalJobid = no
OpaqueString     =  -cbustart 0 -cbuend 0 -cbustart 0 -cbuend 0

**************************
*BackupJob               *
(jobid=48218 jobtype=6)
**************************
isStdBackup       = false
backupType        = 6
subtype           = 35
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 1650518621
backupid          = bkp01_1650518621
Active pid        = 0
Job Count         = 1
IPaddr            = 
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 0
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = Catalogue
Num copies        = 1
Include_file#     = 1
resourceCount     = 1
Stu               = MSDP_DP-MSDP1
Pool              = NetBackup
Retention         = 0
UseLocal          = false
(GenBackupJob.cpp:748)
21/04/2022 06:23:41.113 [Info] V-117-32 Map jobtype to column=7, column name=CATALOG_BACKUP:
21/04/2022 06:23:41.113 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:StartNotifyScript] m_JobStep=1, Jobid=48218
21/04/2022 06:23:41.113 [Info] V-117-122 started backup job for client bkp01, policy Catalogue, schedule incr_daily on storage unit <?>
21/04/2022 06:23:41.863 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:StartNotifyScript] m_JobStep=1, Jobid=48218, returns=0
21/04/2022 06:23:41.863 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:DbmQuery] m_JobStep=2, Jobid=48218
21/04/2022 06:25:50.481 [JobInstance::state] (00000000043F9FB0) state=5(JobInstance.cpp:365)
21/04/2022 06:25:50.481 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:DbmQuery] m_JobStep=2, Jobid=48218, returns=2
21/04/2022 06:25:50.481 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:StopOnError] m_JobStep=-5, Jobid=48218
21/04/2022 06:25:50.481 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:StopOnError] m_JobStep=3, Jobid=48218, returns=0
21/04/2022 06:25:50.481 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:EndNotifyScript] m_JobStep=4, Jobid=48218
21/04/2022 06:25:51.200 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:EndNotifyScript] m_JobStep=4, Jobid=48218, returns=0
21/04/2022 06:25:51.200 [Info] V-117-107 *********** Jobid 48218 status summary for CATALOG_BACKUP: *********
21/04/2022 06:25:51.200 [Info] V-117-114 Step 1 StartNotifyScript status 0 jobstatus -
21/04/2022 06:25:51.200 [Info] V-117-114 Step 2 DbmQuery status 2 jobstatus 2
21/04/2022 06:25:51.200 [Info] V-117-114 Step 3 ValidateImage status - jobstatus 2
21/04/2022 06:25:51.200 [Info] V-117-114 Step 4 EndNotifyScript status 0 jobstatus 2
21/04/2022 06:25:51.200 [Info] V-117-111 ********** job status is 2 **********
21/04/2022 06:25:51.200 [Info] V-117-52 GenBackupJob Terminating status=2
21/04/2022 06:25:51.200 [JobInstance::state] (00000000043F9FB0) state=5(JobInstance.cpp:365)
21/04/2022 06:25:51.200 [JobInstance::state] (00000000043F9FB0) state=5(JobInstance.cpp:365)
21/04/2022 06:25:51.200 [JobInstance::state] (00000000043F9FB0) state=11(JobInstance.cpp:365)
21/04/2022 06:25:51.200 [BackupJob::sendNotifications] (00000000043F9FB0) disable resume=false, brm started=false(BackupJob.cpp:2717)
21/04/2022 06:25:51.200 V-117-239 [BackupJob::terminateThisJob] terminated job, jobid=48218, status=2 (null)
21/04/2022 06:25:51.200 [BackupJob::~BackupJob] (dump Backup Job): 
**************************
*BackupJob               *
(jobid=48218 jobtype=6)
**************************
isStdBackup       = false
backupType        = 6
subtype           = 35
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 1650518621
backupid          = bkp01_1650518621
Active pid        = 0
Job Count         = 1
IPaddr            = 
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 0
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = Catalogue
Num copies        = 1
Include_file#     = 1
resourceCount     = 1
Stu               = MSDP_DP-MSDP1
Pool              = NetBackup
Retention         = 0
UseLocal          = false
(BackupJob.cpp:437)
21/04/2022 06:25:51.200 V-116-216 [RecoverableJob::doJobCompletion] jobid=48218 completed with status 2
21/04/2022 06:25:51.216 V-118-102 [ResBroker_i::releaseOne] releasing allocation ID {BA2A8410-5DDD-4FCB-82C7-68190D7C17CC}
21/04/2022 06:25:51.232 [Scheduler::forwardRun] (ID:00000000048C7E08) DEBUG stream=-1 m_lastBackup=138694685330000000(Scheduler.cpp:499)
21/04/2022 06:25:51.247 [Scheduler::forwardRun] (ID:00000000048C7E08) DEBUG stream=-1 m_lastBackup=138697236000000000(Scheduler.cpp:499)
21/04/2022 06:25:51.247 [Scheduler::forwardRun] (ID:00000000048C7E08) DEBUG stream=-1 m_lastBackup=138697236000000000(Scheduler.cpp:499)
21/04/2022 06:25:51.247 V-116-222 [RecoverableJob::registerForRetryTime] retry of jobid=48218 schedule for 21/04/2022 07:35:51
21/04/2022 06:25:51.247 [Info] V-116-14 CLIENT bkp01  POLICY Catalogue  SCHED incr_daily  EXIT STATUS 2 (none of the requested files were backed up) VBRF 1 2
21/04/2022 06:25:51.247 [Error] V-116-305 catalog backup exited with status 2 (none of the requested files were backed up)
21/04/2022 06:35:51.010 V-116-215 [RecoverableJob::run_SUBMIT_RETRY] jobid=48218 submitted to nbjm for processing
21/04/2022 06:35:51.025 [JobInstance::state] (00000000044957F0) state=0(JobInstance.cpp:365)
21/04/2022 06:35:51.025 V-117-56 [BackupJob::sendRequestToRB] requesting resources from RB for backup job (jobid=48218)
21/04/2022 06:35:51.025 V-118-227 [ResBroker_i::requestResources] received resource request ID {7ABC456C-F4A2-4E77-9154-307B71607844}, priority 999, secondary priority 26384, description THE_BACKUP_JOB-48218-{7ABC456C-F4A2-4E77-9154-307B71607844}
21/04/2022 06:35:51.025 [ResBroker_i::requestResources] RequestSeq:
Request=0 provider=NamedResourceProvider resourcename=bkp01.NBU_CATALOG.MAXJOBS CountedResourceRequest { max=1 }
21/04/2022 06:35:51.072 [ResBroker_i::evaluateOne] Evaluating request ID {7ABC456C-F4A2-4E77-9154-307B71607844}
21/04/2022 06:35:51.072 [ProviderManager::allocate] NamedResourceProvider returned Allocation Granted for request ID {7ABC456C-F4A2-4E77-9154-307B71607844}
21/04/2022 06:35:51.072 [ResBroker_i::evaluateOne] resources found for request, requestId={7ABC456C-F4A2-4E77-9154-307B71607844}, userId=jobid=48218, birthTime=1650519351, timeToFirstEval=0 sec, timeToSuccessOrFailure=0 sec, numberOfTimesEvaluated=1
21/04/2022 06:35:51.072 V-118-109 [ResBroker_i::passOne] resources found for request ID {7ABC456C-F4A2-4E77-9154-307B71607844}, following allocations are granted:
21/04/2022 06:35:51.072 V-118-228 [ResBroker_i::passOne] allocation ID {F13DB90F-8014-439B-B4A8-2473C809772F}, group ID {00000000-0000-0000-0000-000000000000}, provider NamedResourceProvider, resource bkp01.NBU_CATALOG.MAXJOBS
21/04/2022 06:35:51.072 [ResBroker_i::passOne] allocation: (Allocation: id={F13DB90F-8014-439B-B4A8-2473C809772F} provider=NamedResourceProvider resourcename=bkp01.NBU_CATALOG.MAXJOBS masterserver=bkp01 groupid={00000000-0000-0000-0000-000000000000} userSequence=-1 userid="jobid=48218"  firstuserid="jobid=48218" named resource allocation)
21/04/2022 06:35:51.088 [JobInstance::state] (00000000044957F0) state=1(JobInstance.cpp:365)
21/04/2022 06:35:51.088 V-117-296 [BackupJob::extractResourceAttributes] unable to get storage unit resource attribute
21/04/2022 06:35:51.088 V-117-296 [BackupJob::extractResourceAttributes] unable to get media server resource attribute
21/04/2022 06:35:51.088 [BackupJob::extractResourceAttributes] (00000000044957F0) media server=(BackupJob.cpp:1439)
21/04/2022 06:35:51.088 V-117-296 [BackupJob::extractResourceAttributes] unable to get stu name resource attribute
21/04/2022 06:35:51.088 V-117-296 [BackupJob::extractResourceAttributes] unable to get mpxid resource attribute
21/04/2022 06:35:51.088 [BackupJob::processProxyResponse] (00000000044957F0) Done: flush proxy response, next:start job, jobid=48218(BackupJob.cpp:4081)
21/04/2022 06:35:51.088 [JobInstance::state] (00000000044957F0) state=1(JobInstance.cpp:365)
21/04/2022 06:35:51.088 [JobInstance::state] (00000000044957F0) state=1(JobInstance.cpp:365)
21/04/2022 06:35:51.088 V-118-249 [CallbackQueue::resourcesAvailable] added allocations to the callback queue for request ID {7ABC456C-F4A2-4E77-9154-307B71607844}
21/04/2022 06:35:51.088 V-118-250 [CallbackQueue::notifyClientAvailable] queueing notification of availability of resources for request ID {7ABC456C-F4A2-4E77-9154-307B71607844}
21/04/2022 06:35:51.088 V-118-256 [CorbaCall_notifyClientAvailable::execute] sending availability of resources to nbjm for request ID {7ABC456C-F4A2-4E77-9154-307B71607844}
21/04/2022 06:35:51.182 [GenBackupJob::processProxyResponse] (00000000044957F0) Done: create image, Next: start genjob, proxy status=0(GenBackupJob.cpp:899)
21/04/2022 06:35:51.182 [JobInstance::state] (00000000044957F0) state=1(JobInstance.cpp:365)
21/04/2022 06:35:51.197 [GenBackupJob::spawnGenericJob] (00000000044957F0) start CommandActions(GenBackupJob.cpp:680)
21/04/2022 06:35:51.197 [GenBackupJob::spawnGenericJob] GenBackupJob Commandline Options=
**************************
* GenBackupJob           *
**************************
Jobid            = 48218
GroupId          = 48218
SubType          = 35
MediaServer      = 
MasterServer     = bkp01
PolicyName       = Catalogue
SchedName        = incr_daily
SchedType        = 1
ClientName       = bkp01
ClientType       = 35
Stream Num       = -1
Birthtime        = 1650519351
BackupCopy       = 0
BackupId         = bkp01_1650519351
SnapshotId       = 
User             = root
BMRSave          = no
StreamDiscovery  = no
Resume           = no
Checkpoint       = no
UseInternalJobid = no
OpaqueString     =  -cbustart 0 -cbuend 0 -cbustart 0 -cbuend 0

**************************
*BackupJob               *
(jobid=48218 jobtype=6)
**************************
isStdBackup       = false
backupType        = 6
subtype           = 35
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 1650519351
backupid          = bkp01_1650519351
Active pid        = 0
Job Count         = 1
IPaddr            = 
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 0
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = Catalogue
Num copies        = 1
Include_file#     = 1
resourceCount     = 1
Stu               = MSDP_DP-MSDP1
Pool              = NetBackup
Retention         = 0
UseLocal          = false
(GenBackupJob.cpp:748)
21/04/2022 06:35:51.197 [Info] V-117-32 Map jobtype to column=7, column name=CATALOG_BACKUP:
21/04/2022 06:35:51.197 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:StartNotifyScript] m_JobStep=1, Jobid=48218
21/04/2022 06:35:51.197 [Info] V-117-122 started backup job for client bkp01, policy Catalogue, schedule incr_daily on storage unit <?>
21/04/2022 06:35:51.916 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:StartNotifyScript] m_JobStep=1, Jobid=48218, returns=0
21/04/2022 06:35:51.916 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:DbmQuery] m_JobStep=2, Jobid=48218
21/04/2022 06:58:10.438 [JobInstance::state] (00000000044957F0) state=5(JobInstance.cpp:365)
21/04/2022 06:58:10.438 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:DbmQuery] m_JobStep=2, Jobid=48218, returns=150
21/04/2022 06:58:10.438 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:StopOnError] m_JobStep=-5, Jobid=48218
21/04/2022 06:58:10.438 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:StopOnError] m_JobStep=3, Jobid=48218, returns=0
21/04/2022 06:58:10.438 [Info] V-117-88 FSM JobTable[CATALOG_BACKUP:EndNotifyScript] m_JobStep=4, Jobid=48218
21/04/2022 06:58:11.219 [Info] V-117-94 FSM JobTable[CATALOG_BACKUP:EndNotifyScript] m_JobStep=4, Jobid=48218, returns=0
21/04/2022 06:58:11.219 [Info] V-117-107 *********** Jobid 48218 status summary for CATALOG_BACKUP: *********
21/04/2022 06:58:11.219 [Info] V-117-114 Step 1 StartNotifyScript status 0 jobstatus -
21/04/2022 06:58:11.219 [Info] V-117-114 Step 2 DbmQuery status 150 jobstatus 150
21/04/2022 06:58:11.219 [Info] V-117-114 Step 3 ValidateImage status - jobstatus 150
21/04/2022 06:58:11.219 [Info] V-117-114 Step 4 EndNotifyScript status 0 jobstatus 150
21/04/2022 06:58:11.219 [Info] V-117-111 ********** job status is 150 **********
21/04/2022 06:58:11.219 [Info] V-117-52 GenBackupJob Terminating status=150
21/04/2022 06:58:11.219 [JobInstance::state] (00000000044957F0) state=5(JobInstance.cpp:365)
21/04/2022 06:58:11.219 [JobInstance::state] (00000000044957F0) state=5(JobInstance.cpp:365)
21/04/2022 06:58:11.219 [JobInstance::state] (00000000044957F0) state=10(JobInstance.cpp:365)
21/04/2022 06:58:11.219 [BackupJob::sendNotifications] (00000000044957F0) disable resume=false, brm started=false(BackupJob.cpp:2717)
21/04/2022 06:58:11.219 V-117-239 [BackupJob::terminateThisJob] terminated job, jobid=48218, status=150 (null)
21/04/2022 06:58:11.219 [BackupJob::~BackupJob] (dump Backup Job): 
**************************
*BackupJob               *
(jobid=48218 jobtype=6)
**************************
isStdBackup       = false
backupType        = 6
subtype           = 35
mpxid             = {00000000-0000-0000-0000-000000000000}
maxmpx            = 1
Birthtime         = 1650519351
backupid          = bkp01_1650519351
Active pid        = 0
Job Count         = 1
IPaddr            = 
currentThrottle   = -1
estimatedSize     = 0
estimatedFileCount= 0
suspendable       = 0
progressLogTimerID= -1
localBackup       = 0
policy            = Catalogue
Num copies        = 1
Include_file#     = 1
resourceCount     = 1
Stu               = MSDP_DP-MSDP1
Pool              = NetBackup
Retention         = 0
UseLocal          = false
(BackupJob.cpp:437)
21/04/2022 06:58:11.235 V-116-216 [RecoverableJob::doJobCompletion] jobid=48218 completed with status 150
21/04/2022 06:58:11.235 [PemTask::taskComplete] (ID:000000000491CB58 CTX:00000000048C50E8) Active subtask count=0(PemTask.cpp:530)
21/04/2022 06:58:11.235 [Info] V-116-14 CLIENT bkp01  POLICY Catalogue  SCHED incr_daily  EXIT STATUS 150 (termination requested by administrator) VBRF 1 150
21/04/2022 06:58:11.235 V-118-102 [ResBroker_i::releaseOne] releasing allocation ID {F13DB90F-8014-439B-B4A8-2473C809772F}
21/04/2022 06:58:11.250 [Error] V-116-305 catalog backup exited with status 150 (termination requested by administrator)
21/04/2022 06:58:11.250 [RecoverableJob::unregisterForEmail] (ID:000000000491CB58 CTX:00000000048C50E8) Unregistered for email(RecoverableJob.cpp:3068)