mirror of
https://github.com/Combodo/iTop.git
synced 2026-04-19 08:38:45 +02:00
Cron parallelization
* refactor logs
This commit is contained in:
Eric Espie
30
sources/Service/Cron/CronLog.php
Normal file
30
sources/Service/Cron/CronLog.php
Normal file
@@ -0,0 +1,30 @@
|
||||
<?php
|
||||
/*
|
||||
* @copyright Copyright (C) 2010-2022 Combodo SARL
|
||||
* @license http://opensource.org/licenses/AGPL-3.0
|
||||
*/
|
||||
|
||||
namespace Combodo\iTop\Service\Cron;
|
||||
|
||||
use LogAPI;
|
||||
|
||||
class CronLog extends LogAPI
|
||||
{
|
||||
public static $iProcessNumber = 0;
|
||||
|
||||
const CHANNEL_DEFAULT = 'Cron';
|
||||
/**
|
||||
* @inheritDoc
|
||||
*
|
||||
* As this object is used during setup, without any conf file available, customizing the level can be done by changing this constant !
|
||||
*/
|
||||
const LEVEL_DEFAULT = self::LEVEL_INFO;
|
||||
|
||||
protected static $m_oFileLog = null;
|
||||
|
||||
public static function Log($sLevel, $sMessage, $sChannel = null, $aContext = array())
|
||||
{
|
||||
$sMessage = 'cron'.str_pad(static::$iProcessNumber, 3).$sMessage;
|
||||
parent::Log($sLevel, $sMessage, $sChannel, $aContext);
|
||||
}
|
||||
}
|
||||
@@ -18,10 +18,12 @@
|
||||
*/
|
||||
|
||||
use Combodo\iTop\Application\WebPage\CLIPage;
|
||||
use Combodo\iTop\Application\WebPage\Page;
|
||||
use Combodo\iTop\Application\WebPage\WebPage;
|
||||
use Combodo\iTop\Service\Cron\CronLog;
|
||||
use Combodo\iTop\Service\InterfaceDiscovery\InterfaceDiscovery;
|
||||
|
||||
if (!defined('__DIR__')) define('__DIR__', dirname(__FILE__));
|
||||
|
||||
require_once(__DIR__.'/../approot.inc.php');
|
||||
|
||||
const EXIT_CODE_ERROR = -1;
|
||||
@@ -169,10 +171,6 @@ function RunTask(BackgroundTask $oTask, $iTimeLimit)
|
||||
}
|
||||
|
||||
/**
|
||||
* @param CLIPage|WebPage $oP
|
||||
* @param boolean $bVerbose
|
||||
*
|
||||
* @param bool $bDebug
|
||||
*
|
||||
* @throws \ArchivedObjectException
|
||||
* @throws \CoreCannotSaveObjectException
|
||||
@@ -185,7 +183,7 @@ function RunTask(BackgroundTask $oTask, $iTimeLimit)
|
||||
* @throws \OQLException
|
||||
* @throws \ReflectionException
|
||||
*/
|
||||
function CronExec($oP, $bVerbose, $bDebug=false)
|
||||
function CronExec($bDebug)
|
||||
{
|
||||
$iStarted = time();
|
||||
$iMaxDuration = MetaModel::GetConfig()->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();
|
||||
|
||||
Reference in New Issue
Block a user