Fix task manager messages log levels

This commit is contained in:
Romain Neutron
2014-01-23 11:31:21 +01:00
parent 67b0f4120e
commit d622eb0ab4
5 changed files with 30 additions and 29 deletions

View File

@@ -42,7 +42,7 @@ class module_console_schedulerStart extends Command
$logger->pushHandler($streamHandler); $logger->pushHandler($streamHandler);
$logfile = __DIR__ . '/../../../../logs/scheduler.log'; $logfile = __DIR__ . '/../../../../logs/scheduler.log';
$rotateHandler = new Handler\RotatingFileHandler($logfile, 10); $rotateHandler = new Handler\RotatingFileHandler($logfile, 10, Logger::INFO);
$logger->pushHandler($rotateHandler); $logger->pushHandler($rotateHandler);
try { try {

View File

@@ -18,6 +18,7 @@ use Symfony\Component\Console\Output\OutputInterface;
use Monolog\Handler; use Monolog\Handler;
use Monolog\Handler\StreamHandler; use Monolog\Handler\StreamHandler;
use Monolog\Handler\RotatingFileHandler; use Monolog\Handler\RotatingFileHandler;
use Monolog\Logger;
/** /**
* @todo write tests * @todo write tests
@@ -96,7 +97,7 @@ class module_console_taskrun extends Command
} }
$logfile = __DIR__ . '/../../../../logs/task_' . $task_id . '.log'; $logfile = __DIR__ . '/../../../../logs/task_' . $task_id . '.log';
$this->container['task-manager.logger']->pushHandler(new RotatingFileHandler($logfile, 10)); $this->container['task-manager.logger']->pushHandler(new RotatingFileHandler($logfile, 10, Logger::INFO));
$this->task = $task_manager->getTask($task_id, $this->container['task-manager.logger']); $this->task = $task_manager->getTask($task_id, $this->container['task-manager.logger']);
$lib2v = array( $lib2v = array(

View File

@@ -45,9 +45,9 @@ class task_Scheduler
$this->schedstatus = ''; $this->schedstatus = '';
} }
protected function log($message) protected function log($message, $level = Logger::DEBUG)
{ {
$this->logger->addInfo($message); $this->logger->addRecord($level, $message);
return $this; return $this;
} }
@@ -114,7 +114,7 @@ class task_Scheduler
$lockfile = ($lockdir . 'scheduler.lock'); $lockfile = ($lockdir . 'scheduler.lock');
if (($schedlock = fopen($lockfile, 'a+')) != FALSE) { if (($schedlock = fopen($lockfile, 'a+')) != FALSE) {
if (flock($schedlock, LOCK_EX | LOCK_NB) === FALSE) { if (flock($schedlock, LOCK_EX | LOCK_NB) === FALSE) {
$this->log(sprintf("failed to lock '%s' (try=%s/4)", $lockfile, $try)); $this->log(sprintf("failed to lock '%s' (try=%s/4)", $lockfile, $try), Logger::INFO);
if ($try == 4) { if ($try == 4) {
$this->log("scheduler already running."); $this->log("scheduler already running.");
fclose($schedlock); fclose($schedlock);
@@ -140,7 +140,7 @@ class task_Scheduler
} }
} }
$this->log(sprintf("running scheduler with method %s", $this->method)); $this->log(sprintf("running scheduler with method %s", $this->method), Logger::INFO);
$conn = $this->dependencyContainer['phraseanet.appbox']->get_connection(); $conn = $this->dependencyContainer['phraseanet.appbox']->get_connection();
@@ -182,7 +182,7 @@ class task_Scheduler
unset($conn); unset($conn);
if (! $connwaslost) { if (! $connwaslost) {
$this->log(sprintf("Warning : abox connection lost, restarting in 10 min.")); $this->log(sprintf("Warning : abox connection lost, restarting in 10 min."), Logger::INFO);
} }
for ($i = 0; $i < 60 * 10; $i ++) { for ($i = 0; $i < 60 * 10; $i ++) {
sleep(1); sleep(1);
@@ -196,7 +196,7 @@ class task_Scheduler
$connwaslost = true; $connwaslost = true;
} }
if ($connwaslost) { if ($connwaslost) {
$this->log("abox connection restored"); $this->log("abox connection restored", Logger::INFO);
$sql = 'UPDATE task SET crashed=0'; $sql = 'UPDATE task SET crashed=0';
$stmt = $conn->prepare($sql); $stmt = $conn->prepare($sql);
@@ -235,7 +235,7 @@ class task_Scheduler
$stmt = $conn->prepare($sql); $stmt = $conn->prepare($sql);
$stmt->execute(); $stmt->execute();
$stmt->closeCursor(); $stmt->closeCursor();
$this->log("schedstatus == 'stopping', waiting tasks to end"); $this->log("schedstatus == 'stopping', waiting tasks to end", Logger::INFO);
} }
// initialy, all tasks are supposed to be removed from the poll // initialy, all tasks are supposed to be removed from the poll
@@ -490,7 +490,7 @@ class task_Scheduler
"Task %s crashed %d times" "Task %s crashed %d times"
, $taskPoll[$tkey]["task"]->getID() , $taskPoll[$tkey]["task"]->getID()
, $taskPoll[$tkey]["task"]->getCrashCounter() , $taskPoll[$tkey]["task"]->getCrashCounter()
) ), Logger::INFO
); );
if ($taskPoll[$tkey]["task"]->getCrashCounter() > 5) { if ($taskPoll[$tkey]["task"]->getCrashCounter() > 5) {
@@ -519,7 +519,7 @@ class task_Scheduler
"SIGTERM sent to task %s (pid=%s)" "SIGTERM sent to task %s (pid=%s)"
, $taskPoll[$tkey]["task"]->getID() , $taskPoll[$tkey]["task"]->getID()
, $pid , $pid
) ), Logger::INFO
); );
} }
} }
@@ -536,7 +536,7 @@ class task_Scheduler
"proc_terminate(...) done on task %s (pid=%s)" "proc_terminate(...) done on task %s (pid=%s)"
, $taskPoll[$tkey]["task"]->getID() , $taskPoll[$tkey]["task"]->getID()
, $pid , $pid
) ), Logger::INFO
); );
} else { // METHOD_FORK, I guess we have posix } else { // METHOD_FORK, I guess we have posix
posix_kill($pid, 9); posix_kill($pid, 9);
@@ -545,7 +545,7 @@ class task_Scheduler
"SIGKILL sent to task %s (pid=%s)" "SIGKILL sent to task %s (pid=%s)"
, $taskPoll[$tkey]["task"]->getID() , $taskPoll[$tkey]["task"]->getID()
, $pid , $pid
) ), Logger::INFO
); );
} }
} else { } else {
@@ -554,7 +554,7 @@ class task_Scheduler
"waiting task %s to quit (kill in %d seconds)" "waiting task %s to quit (kill in %d seconds)"
, $taskPoll[$tkey]["task"]->getID() , $taskPoll[$tkey]["task"]->getID()
, $dt , $dt
) ), Logger::INFO
); );
$runningtask ++; $runningtask ++;
} }
@@ -563,7 +563,7 @@ class task_Scheduler
sprintf( sprintf(
"task %s has quit" "task %s has quit"
, $taskPoll[$tkey]["task"]->getID() , $taskPoll[$tkey]["task"]->getID()
) ), Logger::INFO
); );
$taskPoll[$tkey]["task"]->setState(task_abstract::STATE_STOPPED); $taskPoll[$tkey]["task"]->setState(task_abstract::STATE_STOPPED);
} }
@@ -610,11 +610,11 @@ class task_Scheduler
$stmt->execute(); $stmt->execute();
$stmt->closeCursor(); $stmt->closeCursor();
$this->log("Scheduler2 is quitting."); $this->log("Scheduler2 is quitting.", Logger::INFO);
ftruncate($schedlock, 0); ftruncate($schedlock, 0);
fclose($schedlock); fclose($schedlock);
$this->log("Scheduler2 has quit.\n"); $this->log("Scheduler2 has quit.\n", Logger::INFO);
} }
} }

View File

@@ -136,8 +136,7 @@ abstract class task_abstract
try { try {
$conn = connection::getPDOConnection($this->dependencyContainer); $conn = connection::getPDOConnection($this->dependencyContainer);
} catch (Exception $e) { } catch (Exception $e) {
$this->log($e->getMessage()); $this->log(("Warning : abox connection lost : ".$e->getMessage().", restarting in 10 min."), self::LOG_DEBUG);
$this->log(("Warning : abox connection lost, restarting in 10 min."));
$this->sleep(60 * 10); $this->sleep(60 * 10);
@@ -252,7 +251,7 @@ abstract class task_abstract
$stmt = $conn->prepare($sql); $stmt = $conn->prepare($sql);
$stmt->execute(array(':status' => $status, ':taskid' => $this->getID())); $stmt->execute(array(':status' => $status, ':taskid' => $this->getID()));
$stmt->closeCursor(); $stmt->closeCursor();
$this->log(sprintf("task %d <- %s", $this->getID(), $status)); $this->log(sprintf("task %d <- %s", $this->getID(), $status), self::LOG_INFO);
} }
/** /**
@@ -542,7 +541,9 @@ abstract class task_abstract
protected function pause($when_started = 0) protected function pause($when_started = 0)
{ {
$this->log($this->records_done . ' records done'); if ($this->records_done > 0) {
$this->log($this->records_done . ' records done');
}
if ($this->running) { // && $this->records_done == 0) if ($this->running) { // && $this->records_done == 0)
$when_started = time() - $when_started; $when_started = time() - $when_started;
if ($when_started < $this->period) { if ($when_started < $this->period) {
@@ -602,7 +603,7 @@ abstract class task_abstract
$locker = true; $locker = true;
if (flock($lockFD, LOCK_EX | LOCK_NB, $locker) === FALSE) { if (flock($lockFD, LOCK_EX | LOCK_NB, $locker) === FALSE) {
$this->log("runtask::ERROR : task already running."); $this->log("runtask::ERROR : task already running.", self::LOG_ERROR);
fclose($lockFD); fclose($lockFD);
throw new Exception('task already running.', self::ERR_ALREADY_RUNNING); throw new Exception('task already running.', self::ERR_ALREADY_RUNNING);
@@ -691,7 +692,7 @@ abstract class task_abstract
// process one record // process one record
$this->processOneContent($box, $row); $this->processOneContent($box, $row);
} catch (Exception $e) { } catch (Exception $e) {
$this->log("Exception : " . $e->getMessage() . " " . basename($e->getFile()) . " " . $e->getLine()); $this->log("Exception : " . $e->getMessage() . " " . basename($e->getFile()) . " " . $e->getLine(), self::LOG_ERROR);
} }
$this->records_done ++; $this->records_done ++;
@@ -704,13 +705,13 @@ abstract class task_abstract
$current_memory = memory_get_usage(); $current_memory = memory_get_usage();
if ($current_memory >> 20 >= $this->maxmegs) { if ($current_memory >> 20 >= $this->maxmegs) {
$this->log(sprintf("Max memory (%s M) reached (actual is %.02f M)", $this->maxmegs, ($current_memory >> 10) / 1024), self::LOG_ERROR); $this->log(sprintf("Max memory (%s M) reached (actual is %.02f M)", $this->maxmegs, ($current_memory >> 10) / 1024), self::LOG_DEBUG);
$this->running = FALSE; $this->running = FALSE;
$ret = self::STATE_MAXMEGSREACHED; $ret = self::STATE_MAXMEGSREACHED;
} }
if ($this->records_done >= (integer) ($this->maxrecs)) { if ($this->records_done >= (integer) ($this->maxrecs)) {
$this->log(sprintf("Max records done (%s) reached (actual is %s)", $this->maxrecs, $this->records_done)); $this->log(sprintf("Max records done (%s) reached (actual is %s)", $this->maxrecs, $this->records_done), self::LOG_DEBUG);
$this->running = FALSE; $this->running = FALSE;
$ret = self::STATE_MAXRECSDONE; $ret = self::STATE_MAXRECSDONE;
} }
@@ -789,7 +790,7 @@ abstract class task_abstract
protected function incrementLoops() protected function incrementLoops()
{ {
if ($this->getRunner() == self::RUNNER_SCHEDULER && ++ $this->loop >= $this->maxloops) { if ($this->getRunner() == self::RUNNER_SCHEDULER && ++ $this->loop >= $this->maxloops) {
$this->log(sprintf(('%d loops done, restarting'), $this->loop)); $this->log(sprintf(('%d loops done, restarting'), $this->loop), self::LOG_DEBUG);
$this->setState(self::STATE_TORESTART); $this->setState(self::STATE_TORESTART);
$this->running = false; $this->running = false;
@@ -812,9 +813,8 @@ abstract class task_abstract
$this->logger->addDebug(memory_get_usage() . " -- " . memory_get_usage(true)); $this->logger->addDebug(memory_get_usage() . " -- " . memory_get_usage(true));
} }
public function log($message, $level=self::LOG_INFO) public function log($message, $level = Logger::LOG_DEBUG)
{ {
// nb : self::log_levels ARE standard log levels, ok with monolog
$this->logger->addRecord($level, $message); $this->logger->addRecord($level, $message);
return $this; return $this;

View File

@@ -82,7 +82,7 @@ abstract class task_databoxAbstract extends task_abstract
} }
$this->sbas_id = (int) $row['sbas_id']; $this->sbas_id = (int) $row['sbas_id'];
$this->log(sprintf('This task works now on sbasid=%s ', $this->sbas_id), self::LOG_INFO); $this->log(sprintf('This task works now on sbasid=%s ', $this->sbas_id), self::LOG_DEBUG);
try { try {
// get the records to process // get the records to process