diff --git a/sources/Service/Cron/CronLog.php b/sources/Service/Cron/CronLog.php new file mode 100644 index 000000000..857e0cc26 --- /dev/null +++ b/sources/Service/Cron/CronLog.php @@ -0,0 +1,30 @@ +Get('cron_max_execution_time'); @@ -193,17 +191,14 @@ function CronExec($oP, $bVerbose, $bDebug=false) $iCronSleep = MetaModel::GetConfig()->Get('cron_sleep'); $iMaxCronProcess = MetaModel::GetConfig()->Get('cron.max_processes'); - if ($bVerbose) - { - $oP->p("Planned duration = $iMaxDuration seconds"); - $oP->p("Loop pause = $iCronSleep seconds"); - } + CronLog::Debug("Planned duration = $iMaxDuration seconds"); + CronLog::Debug("Loop pause = $iCronSleep seconds"); - ReSyncProcesses($oP, $bVerbose, $bDebug); + ReSyncProcesses($bDebug); while (time() < $iTimeLimit) { - CheckMaintenanceMode($oP); + CheckMaintenanceMode(); $oNow = new DateTime(); $sNow = $oNow->format('Y-m-d H:i:s'); @@ -215,14 +210,8 @@ function CronExec($oP, $bVerbose, $bDebug=false) $aTasks = []; if ($oTasks->CountExceeds(0)) { - if ($bVerbose) - { - $sCount = $oTasks->Count(); - $oP->p("$sCount Tasks planned to run now ($sNow):"); - $oP->p('+---------------------------+---------+---------------------+---------------------+'); - $oP->p('| Task Class | Status | Last Run | Next Run |'); - $oP->p('+---------------------------+---------+---------------------+---------------------+'); - } + $sCount = $oTasks->Count(); + CronLog::Debug("$sCount Tasks planned to run now ($sNow):"); while ($oTask = $oTasks->Fetch()) { $sTaskName = $oTask->Get('class_name'); @@ -232,17 +221,10 @@ function CronExec($oP, $bVerbose, $bDebug=false) continue; } $aTasks[] = $oTask; - if ($bVerbose) - { - $sStatus = $oTask->Get('status'); - $sLastRunDate = $oTask->Get('latest_run_date'); - $sNextRunDate = $oTask->Get('next_run_date'); - $oP->p(sprintf('| %1$-25.25s | %2$-7s | %3$-19s | %4$-19s |', $sTaskName, $sStatus, $sLastRunDate, $sNextRunDate)); - } - } - if ($bVerbose) - { - $oP->p('+---------------------------+---------+---------------------+---------------------+'); + $sStatus = $oTask->Get('status'); + $sLastRunDate = $oTask->Get('latest_run_date'); + $sNextRunDate = $oTask->Get('next_run_date'); + CronLog::Debug(sprintf('Task Class: %1$-25.25s Status: %2$-7s Last Run: %3$-19s Next Run: %4$-19s', $sTaskName, $sStatus, $sLastRunDate, $sNextRunDate)); } $aRunTasks = []; while ($aTasks != []) { @@ -264,41 +246,34 @@ function CronExec($oP, $bVerbose, $bDebug=false) CMDBObject::SetCurrentChangeFromParams("Background task ($sTaskClass)"); // Run the task and record its next run time - if ($bVerbose) - { - $oNow = new DateTime(); - $oP->p(">> === ".$oNow->format('Y-m-d H:i:s').sprintf(" Starting:%-'=49s", ' '.$sTaskClass.' ')); - } + $oNow = new DateTime(); + CronLog::Debug(">> === ".$oNow->format('Y-m-d H:i:s').sprintf(" Start task:%-'=49s", ' '.$sTaskClass.' ')); try { $sMessage = RunTask($oTask, $iTimeLimit); } catch (MySQLHasGoneAwayException $e) { - $oP->p("ERROR : 'MySQL has gone away' thrown when processing $sTaskClass (error_code=".$e->getCode().")"); + CronLog::Error("ERROR : 'MySQL has gone away' thrown when processing $sTaskClass (error_code=".$e->getCode().")"); exit(EXIT_CODE_FATAL); } catch (ProcessFatalException $e) { - $oP->p("ERROR : an exception was thrown when processing '$sTaskClass' (".$e->getInfoLog().")"); - IssueLog::Error("Cron.php error : an exception was thrown when processing '$sTaskClass' (".$e->getInfoLog().')'); + CronLog::Error("ERROR : an exception was thrown when processing '$sTaskClass' (".$e->getInfoLog().")"); } finally { $oTaskMutex->Unlock(); } - if ($bVerbose) + if (!empty($sMessage)) { - if (!empty($sMessage)) - { - $oP->p("$sTaskClass: $sMessage"); - } - $oEnd = new DateTime(); - $sNextRunDate = $oTask->Get('next_run_date'); - $oP->p("<< === ".$oEnd->format('Y-m-d H:i:s').sprintf(" End of: %-'=42s", ' '.$sTaskClass.' ')." Next: $sNextRunDate"); + CronLog::Debug("$sTaskClass: $sMessage"); } + $oEnd = new DateTime(); + $sNextRunDate = $oTask->Get('next_run_date'); + CronLog::Debug("<< === ".$oEnd->format('Y-m-d H:i:s').sprintf(" End of: %-'=42s", ' '.$sTaskClass.' ')." Next: $sNextRunDate"); if (time() > $iTimeLimit) { break 2; } - CheckMaintenanceMode($oP); + CheckMaintenanceMode(); if ($iMaxCronProcess > 1) { // Reindex tasks every time break; @@ -306,9 +281,8 @@ function CronExec($oP, $bVerbose, $bDebug=false) } // Tasks to run later - if ($bVerbose && count($aTasks) == 0) + if (count($aTasks) == 0) { - $oP->p('--'); $oSearch = new DBObjectSearch('BackgroundTask'); $oSearch->AddCondition('next_run_date', $sNow, '>'); $oSearch->AddCondition('status', 'active'); @@ -317,33 +291,22 @@ function CronExec($oP, $bVerbose, $bDebug=false) { if (!in_array($oTask->Get('class_name'), $aRunTasks)) { - $oP->p(sprintf("-- Skipping task: %-'-40s", $oTask->Get('class_name').' ')." until: ".$oTask->Get('next_run_date')); + CronLog::Debug(sprintf("-- Skipping task: %-'-40s", $oTask->Get('class_name').' ')." until: ".$oTask->Get('next_run_date')); } } } } if (count($aTasks) == 0) { - if ($bVerbose) { - $oP->p("Sleeping...\n"); - } sleep($iCronSleep); } } - if ($bVerbose) - { - $oP->p(''); - DisplayStatus($oP, ['next_run_date' => true]); - $oP->p("Reached normal execution time limit (exceeded by ".(time() - $iTimeLimit)."s)"); - } + CronLog::Debug("Reached normal execution time limit (exceeded by ".(time() - $iTimeLimit)."s)"); } -/** - * @param WebPage $oP - */ -function CheckMaintenanceMode(Page $oP) { +function CheckMaintenanceMode() { // Verify files instead of reloading the full config each time if (file_exists(MAINTENANCE_MODE_FILE) || file_exists(READONLY_MODE_FILE)) { - $oP->p("Maintenance detected, exiting"); + CronLog::Info("Maintenance detected, exiting"); exit(EXIT_CODE_ERROR); } } @@ -358,7 +321,7 @@ function CheckMaintenanceMode(Page $oP) { * @throws \MySQLException * @throws \OQLException */ -function DisplayStatus($oP, $aTaskOrderBy = []) +function DisplayStatus($oP = null, $aTaskOrderBy = []) { $oSearch = new DBObjectSearch('BackgroundTask'); $oTasks = new DBObjectSet($oSearch, $aTaskOrderBy); @@ -380,8 +343,6 @@ function DisplayStatus($oP, $aTaskOrderBy = []) } /** - * @param $oP - * @param $bVerbose * @param $bDebug * * @throws \ArchivedObjectException @@ -393,28 +354,25 @@ function DisplayStatus($oP, $aTaskOrderBy = []) * @throws \OQLException * @throws \ReflectionException */ -function ReSyncProcesses($oP, $bVerbose, $bDebug) +function ReSyncProcesses($bDebug) { // Enumerate classes implementing BackgroundProcess // $oSearch = new DBObjectSearch('BackgroundTask'); $oTasks = new DBObjectSet($oSearch); $aTasks = array(); - while ($oTask = $oTasks->Fetch()) - { + while ($oTask = $oTasks->Fetch()) { $aTasks[$oTask->Get('class_name')] = $oTask; } $oNow = new DateTime(); $aProcesses = array(); - foreach (InterfaceDiscovery::GetInstance()->FindItopClasses(iProcess::class) as $sTaskClass) - { + foreach (InterfaceDiscovery::GetInstance()->FindItopClasses(iProcess::class) as $sTaskClass) { $oProcess = new $sTaskClass; $aProcesses[$sTaskClass] = $oProcess; // Create missing entry if needed - if (!array_key_exists($sTaskClass, $aTasks)) - { + if (!array_key_exists($sTaskClass, $aTasks)) { // New entry, let's create a new BackgroundTask record, and plan the first execution $oTask = new BackgroundTask(); $oTask->SetDebug($bDebug); @@ -424,41 +382,30 @@ function ReSyncProcesses($oP, $bVerbose, $bDebug) $oTask->Set('max_run_duration', 0); $oTask->Set('average_run_duration', 0); $oRefClass = new ReflectionClass($sTaskClass); - if ($oRefClass->implementsInterface('iScheduledProcess')) - { + if ($oRefClass->implementsInterface('iScheduledProcess')) { $oNextOcc = $oProcess->GetNextOccurrence(); $oTask->Set('next_run_date', $oNextOcc->format('Y-m-d H:i:s')); - } - else - { + } else { // Background processes do start asap, i.e. "now" $oTask->Set('next_run_date', $oNow->format('Y-m-d H:i:s')); } - if ($bVerbose) - { - $oP->p('Creating record for: '.$sTaskClass); - $oP->p('First execution planned at: '.$oTask->Get('next_run_date')); - } + CronLog::Debug('Creating record for: '.$sTaskClass); + CronLog::Debug('First execution planned at: '.$oTask->Get('next_run_date')); $oTask->DBInsert(); - } - else - { + } else { /** @var \BackgroundTask $oTask */ $oTask = $aTasks[$sTaskClass]; - if ($oTask->Get('next_run_date') == '3000-01-01 00:00:00') - { + if ($oTask->Get('next_run_date') == '3000-01-01 00:00:00') { // check for rescheduled tasks $oRefClass = new ReflectionClass($sTaskClass); - if ($oRefClass->implementsInterface('iScheduledProcess')) - { + if ($oRefClass->implementsInterface('iScheduledProcess')) { $oNextOcc = $oProcess->GetNextOccurrence(); $oTask->Set('next_run_date', $oNextOcc->format('Y-m-d H:i:s')); $oTask->DBUpdate(); } } // Reactivate task if necessary - if ($oTask->Get('status') == 'removed') - { + if ($oTask->Get('status') == 'removed') { $oTask->Set('status', 'active'); $oTask->DBUpdate(); } @@ -468,26 +415,20 @@ function ReSyncProcesses($oP, $bVerbose, $bDebug) } // Remove all the tasks not having a valid class - foreach ($aTasks as $oTask) - { + foreach ($aTasks as $oTask) { $sTaskClass = $oTask->Get('class_name'); - if (!class_exists($sTaskClass)) - { + if (!class_exists($sTaskClass)) { $oTask->Set('status', 'removed'); $oTask->DBUpdate(); } } - if ($bVerbose) - { - $aDisplayProcesses = array(); - foreach ($aProcesses as $oExecInstance) - { - $aDisplayProcesses[] = get_class($oExecInstance); - } - $sDisplayProcesses = implode(', ', $aDisplayProcesses); - $oP->p("Background processes: ".$sDisplayProcesses); + $aDisplayProcesses = array(); + foreach ($aProcesses as $oExecInstance) { + $aDisplayProcesses[] = get_class($oExecInstance); } + $sDisplayProcesses = implode(', ', $aDisplayProcesses); + CronLog::Debug("Background processes: ".$sDisplayProcesses); } //////////////////////////////////////////////////////////////////////////////// @@ -513,7 +454,6 @@ try { utils::UseParamFile(); - $bVerbose = utils::ReadParam('verbose', false, true /* Allow CLI */); $bDebug = utils::ReadParam('debug', false, true /* Allow CLI */); if ($bIsModeCLI) @@ -556,7 +496,6 @@ try } require_once(APPROOT.'core/mutex.class.inc.php'); - $oP->p("Starting: ".time().' ('.date('Y-m-d H:i:s').')'); } catch (Exception $e) { @@ -565,40 +504,42 @@ catch (Exception $e) exit(EXIT_CODE_FATAL); } +CronLog::Enable(APPROOT.'/log/cron.log'); try { if (!MetaModel::DBHasAccess(ACCESS_ADMIN_WRITE)) { - $oP->p("A maintenance is ongoing"); + CronLog::Info("A maintenance is ongoing"); } else { // Limit the number of cron process to run in parallel - $iMaxCronProcess = MetaModel::GetConfig()->Get('cron.max_process'); + $iMaxCronProcess = MetaModel::GetConfig()->Get('cron.max_processes'); $bCanRun = false; + $iProcessNumber = 0; for ($i = 0; $i < $iMaxCronProcess; $i++) { $oMutex = new iTopMutex("cron#$i"); if ($oMutex->TryLock()) { + $iProcessNumber = $i + 1; $bCanRun = true; break; } } if ($bCanRun) { - CronExec($oP, $bVerbose, $bDebug); + CronLog::$iProcessNumber = $iProcessNumber; + CronLog::Info('Starting: '.time().' ('.date('Y-m-d H:i:s').')'); + CronExec($bDebug); } else { - $oP->p("Already $iMaxCronProcess are running..."); + CronLog::Debug("Already $iMaxCronProcess are running..."); } } } catch (Exception $e) { - $oP->p("ERROR: '".$e->getMessage()."'"); - if ($bDebug) - { - // Might contain verb parameters such a password... - $oP->p($e->getTraceAsString()); - } + CronLog::Error("ERROR: '".$e->getMessage()."'"); + // Might contain verb parameters such a password... + CronLog::Debug($e->getTraceAsString()); } -$oP->p("Exiting: ".time().' ('.date('Y-m-d H:i:s').')'); +CronLog::Info("Exiting: ".time().' ('.date('Y-m-d H:i:s').')'); $oP->Output();