From 726e58a297a22aeb30607f97b01343993696a134 Mon Sep 17 00:00:00 2001 From: Rockstar04 Date: Tue, 25 Jun 2013 10:06:37 -0700 Subject: [PATCH] Added basic logging class for a fallback Corrected unit tests for new code Add partial unit coverage for logging class Add newline to logTest file --- bin/resque | 21 ++++---- lib/Resque/Log.php | 62 ++++++++++++++++++++++ lib/Resque/Worker.php | 80 ++++++++++++----------------- test/Resque/Tests/EventTest.php | 1 + test/Resque/Tests/JobStatusTest.php | 1 + test/Resque/Tests/JobTest.php | 1 + test/Resque/Tests/LogTest.php | 31 +++++++++++ test/Resque/Tests/WorkerTest.php | 20 ++++++++ 8 files changed, 161 insertions(+), 56 deletions(-) create mode 100644 lib/Resque/Log.php create mode 100644 test/Resque/Tests/LogTest.php diff --git a/bin/resque b/bin/resque index f0f1429..890c529 100755 --- a/bin/resque +++ b/bin/resque @@ -39,17 +39,19 @@ if(!empty($REDIS_BACKEND)) { Resque::setBackend($REDIS_BACKEND, $REDIS_BACKEND_DB); } -$logLevel = 0; +$logLevel = false; $LOGGING = getenv('LOGGING'); $VERBOSE = getenv('VERBOSE'); $VVERBOSE = getenv('VVERBOSE'); if(!empty($LOGGING) || !empty($VERBOSE)) { - $logLevel = Resque_Worker::LOG_NORMAL; + $logLevel = true; } else if(!empty($VVERBOSE)) { - $logLevel = Resque_Worker::LOG_VERBOSE; + $logLevel = true; } +$logger = new Resque_Log($logLevel); + $APP_INCLUDE = getenv('APP_INCLUDE'); if($APP_INCLUDE) { if(!file_exists($APP_INCLUDE)) { @@ -75,7 +77,7 @@ if(!empty($COUNT) && $COUNT > 1) { $PREFIX = getenv('PREFIX'); if(!empty($PREFIX)) { - fwrite(STDOUT, '*** Prefix set to '.$PREFIX."\n"); + $logger->log(Psr\Log\LogLevel::INFO, 'Prefix set to {prefix}', array('prefix' => $PREFIX)); Resque_Redis::prefix($PREFIX); } @@ -83,14 +85,15 @@ if($count > 1) { for($i = 0; $i < $count; ++$i) { $pid = Resque::fork(); if($pid == -1) { - die("Could not fork worker ".$i."\n"); + $logger->log(Psr\Log\LogLevel::EMERGENCY, 'Could not fork worker {count}', array('count' => $i)); + die(); } // Child, start the worker else if(!$pid) { $queues = explode(',', $QUEUE); $worker = new Resque_Worker($queues); - $worker->logLevel = $logLevel; - fwrite(STDOUT, '*** Starting worker '.$worker."\n"); + $worker->setLogger(new Resque_Log($logLevel)); + $logger->log(Psr\Log\LogLevel::NOTICE, 'Starting worker {worker}', array('worker' => $worker)); $worker->work($interval, $BLOCKING); break; } @@ -100,7 +103,7 @@ if($count > 1) { else { $queues = explode(',', $QUEUE); $worker = new Resque_Worker($queues); - $worker->logLevel = $logLevel; + $worker->setLogger(new Resque_Log($logLevel)); $PIDFILE = getenv('PIDFILE'); if ($PIDFILE) { @@ -108,7 +111,7 @@ else { die('Could not write PID information to ' . $PIDFILE); } - fwrite(STDOUT, '*** Starting worker '.$worker."\n"); + $logger->log(Psr\Log\LogLevel::NOTICE, 'Starting worker {worker}', array('worker' => $worker)); $worker->work($interval, $BLOCKING); } ?> \ No newline at end of file diff --git a/lib/Resque/Log.php b/lib/Resque/Log.php new file mode 100644 index 0000000..ce279cc --- /dev/null +++ b/lib/Resque/Log.php @@ -0,0 +1,62 @@ + + * @license http://www.opensource.org/licenses/mit-license.php + */ +class Resque_Log extends Psr\Log\AbstractLogger +{ + public $verbose; + + public function __construct($verbose = false) { + $this->verbose = $verbose; + } + + /** + * Logs with an arbitrary level. + * + * @param mixed $level PSR-3 log level constant, or equivalent string + * @param string $message Message to log, may contain a { placeholder } + * @param array $context Variables to replace { placeholder } + * @return null + */ + public function log($level, $message, array $context = array()) + { + if ($this->verbose) { + fwrite( + STDOUT, + '[' . $level . '] [' . strftime('%T %Y-%m-%d') . '] ' . $this->interpolate($message, $context) . PHP_EOL + ); + return; + } + + if (!($level === Psr\Log\LogLevel::INFO || $level === Psr\Log\LogLevel::DEBUG)) { + fwrite( + STDOUT, + '[' . $level . '] ' . $this->interpolate($message, $context) . PHP_EOL + ); + } + } + + /** + * Fill placeholders with the provided context + * @author Jordi Boggiano j.boggiano@seld.be + * + * @param string $message Message to be logged + * @param array $context Array of variables to use in message + * @return string + */ + public function interpolate($message, array $context = array()) + { + // build a replacement array with braces around the context keys + $replace = array(); + foreach ($context as $key => $val) { + $replace['{' . $key . '}'] = $val; + } + + // interpolate replacement values into the message and return + return strtr($message, $replace); + } +} diff --git a/lib/Resque/Worker.php b/lib/Resque/Worker.php index 870d4c8..28161c9 100644 --- a/lib/Resque/Worker.php +++ b/lib/Resque/Worker.php @@ -9,14 +9,10 @@ */ class Resque_Worker { - const LOG_NONE = 0; - const LOG_NORMAL = 1; - const LOG_VERBOSE = 2; - /** - * @var int Current log level of this worker. - */ - public $logLevel = 0; + * @var LoggerInterface Logging object that impliments the PSR-3 LoggerInterface + */ + public $logger; /** * @var array Array of all associated queues for this worker. @@ -161,7 +157,7 @@ class Resque_Worker $job = false; if(!$this->paused) { if($blocking === true) { - $this->log('Starting blocking with timeout of ' . $interval, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, 'Starting blocking with timeout of {interval}', array('interval' => $interval)); $this->updateProcLine('Waiting for ' . implode(',', $this->queues) . ' with blocking timeout ' . $interval); } else { $this->updateProcLine('Waiting for ' . implode(',', $this->queues) . ' with interval ' . $interval); @@ -179,7 +175,7 @@ class Resque_Worker if($blocking === false) { // If no job was found, we sleep for $interval before continuing and checking again - $this->log('Sleeping for ' . $interval, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, 'Sleeping for {interval}', array('interval' => $interval)); if($this->paused) { $this->updateProcLine('Paused'); } @@ -193,7 +189,7 @@ class Resque_Worker continue; } - $this->log('got ' . $job); + $this->logger->log(Psr\Log\LogLevel::NOTICE, 'Starting work on {job}', array('job' => $job)); Resque_Event::trigger('beforeFork', $job); $this->workingOn($job); @@ -203,7 +199,7 @@ class Resque_Worker if ($this->child === 0 || $this->child === false) { $status = 'Processing ' . $job->queue . ' since ' . strftime('%F %T'); $this->updateProcLine($status); - $this->log($status, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, $status); $this->perform($job); if ($this->child === 0) { exit(0); @@ -214,7 +210,7 @@ class Resque_Worker // Parent process, sit and wait $status = 'Forked ' . $this->child . ' at ' . strftime('%F %T'); $this->updateProcLine($status); - $this->log($status, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, $status); // Wait until the child process finishes before continuing pcntl_wait($status); @@ -245,13 +241,13 @@ class Resque_Worker $job->perform(); } catch(Exception $e) { - $this->log($job . ' failed: ' . $e->getMessage()); + $this->logger->log(Psr\Log\LogLevel::CRITICAL, '{job} has failed {stack}', array('job' => $job, 'stack' => $e->getMessage())); $job->fail($e); return; } $job->updateStatus(Resque_Job_Status::STATUS_COMPLETE); - $this->log('done ' . $job); + $this->logger->log(Psr\Log\LogLevel::NOTICE, '{job} has finished', array('job' => $job)); } /** @@ -269,15 +265,15 @@ class Resque_Worker if($blocking === true) { $job = Resque_Job::reserveBlocking($queues, $timeout); if($job) { - $this->log('Found job on ' . $job->queue, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, 'Found job on {queue}', array('queue' => $job->queue)); return $job; } } else { foreach($queues as $queue) { - $this->log('Checking ' . $queue, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, 'Checking {queue} for jobs', array('queue' => $queue)); $job = Resque_Job::reserve($queue); if($job) { - $this->log('Found job on ' . $queue, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, 'Found job on {queue}', array('queue' => $job->queue)); return $job; } } @@ -355,7 +351,7 @@ class Resque_Worker pcntl_signal(SIGUSR2, array($this, 'pauseProcessing')); pcntl_signal(SIGCONT, array($this, 'unPauseProcessing')); pcntl_signal(SIGPIPE, array($this, 'reestablishRedisConnection')); - $this->log('Registered signals', self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::DEBUG, 'Registered signals'); } /** @@ -363,7 +359,7 @@ class Resque_Worker */ public function pauseProcessing() { - $this->log('USR2 received; pausing job processing'); + $this->logger->log(Psr\Log\LogLevel::NOTICE, 'USR2 received; pausing job processing'); $this->paused = true; } @@ -373,7 +369,7 @@ class Resque_Worker */ public function unPauseProcessing() { - $this->log('CONT received; resuming job processing'); + $this->logger->log(Psr\Log\LogLevel::NOTICE, 'CONT received; resuming job processing'); $this->paused = false; } @@ -383,7 +379,7 @@ class Resque_Worker */ public function reestablishRedisConnection() { - $this->log('SIGPIPE received; attempting to reconnect'); + $this->logger->log(Psr\Log\LogLevel::NOTICE, 'SIGPIPE received; attempting to reconnect'); Resque::redis()->establishConnection(); } @@ -394,7 +390,7 @@ class Resque_Worker public function shutdown() { $this->shutdown = true; - $this->log('Exiting...'); + $this->logger->log(Psr\Log\LogLevel::NOTICE, 'Shutting down'); } /** @@ -414,18 +410,18 @@ class Resque_Worker public function killChild() { if(!$this->child) { - $this->log('No child to kill.', self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::DEBUG, 'No child to kill.'); return; } - $this->log('Killing child at ' . $this->child, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, 'Killing child at {child}', array('child' => $this->child)); if(exec('ps -o pid,state -p ' . $this->child, $output, $returnCode) && $returnCode != 1) { - $this->log('Killing child at ' . $this->child, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::DEBUG, 'Child {child} found, killing.', array('child' => $this->child)); posix_kill($this->child, SIGKILL); $this->child = null; } else { - $this->log('Child ' . $this->child . ' not found, restarting.', self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, 'Child {child} not found, restarting.', array('child' => $this->child)); $this->shutdown(); } } @@ -448,7 +444,7 @@ class Resque_Worker if($host != $this->hostname || in_array($pid, $workerPids) || $pid == getmypid()) { continue; } - $this->log('Pruning dead worker: ' . (string)$worker, self::LOG_VERBOSE); + $this->logger->log(Psr\Log\LogLevel::INFO, 'Pruning dead worker: {worker}', array('worker' => (string)$worker)); $worker->unregisterWorker(); } } @@ -536,26 +532,6 @@ class Resque_Worker return $this->id; } - /** - * Output a given log message to STDOUT. - * - * @param string $message Message to output. - * @param int $logLevel The logging level to capture - */ - public function log($message, $logLevel = self::LOG_NORMAL) - { - if ($logLevel > $this->logLevel) { - return; - } - - if ($this->logLevel == self::LOG_NORMAL) { - fwrite(STDOUT, "*** " . $message . "\n"); - return; - } - - fwrite(STDOUT, "** [" . strftime('%T %Y-%m-%d') . "] " . $message . "\n"); - } - /** * Return an object describing the job this worker is currently working on. * @@ -582,5 +558,15 @@ class Resque_Worker { return Resque_Stat::get($stat . ':' . $this); } + + /** + * Inject the logging object into the worker + * + * @param Psr\Log\LoggerInterface $logger + */ + public function setLogger(Psr\Log\LoggerInterface $logger) + { + $this->logger = $logger; + } } ?> diff --git a/test/Resque/Tests/EventTest.php b/test/Resque/Tests/EventTest.php index 880a323..894fd7a 100644 --- a/test/Resque/Tests/EventTest.php +++ b/test/Resque/Tests/EventTest.php @@ -16,6 +16,7 @@ class Resque_Tests_EventTest extends Resque_Tests_TestCase // Register a worker to test with $this->worker = new Resque_Worker('jobs'); + $this->worker->setLogger(new Resque_Log()); $this->worker->registerWorker(); } diff --git a/test/Resque/Tests/JobStatusTest.php b/test/Resque/Tests/JobStatusTest.php index 68a25ff..d751c37 100644 --- a/test/Resque/Tests/JobStatusTest.php +++ b/test/Resque/Tests/JobStatusTest.php @@ -19,6 +19,7 @@ class Resque_Tests_JobStatusTest extends Resque_Tests_TestCase // Register a worker to test with $this->worker = new Resque_Worker('jobs'); + $this->worker->setLogger(new Resque_Log()); } public function testJobStatusCanBeTracked() diff --git a/test/Resque/Tests/JobTest.php b/test/Resque/Tests/JobTest.php index 688c265..0c09696 100644 --- a/test/Resque/Tests/JobTest.php +++ b/test/Resque/Tests/JobTest.php @@ -17,6 +17,7 @@ class Resque_Tests_JobTest extends Resque_Tests_TestCase // Register a worker to test with $this->worker = new Resque_Worker('jobs'); + $this->worker->setLogger(new Resque_Log()); $this->worker->registerWorker(); } diff --git a/test/Resque/Tests/LogTest.php b/test/Resque/Tests/LogTest.php new file mode 100644 index 0000000..db97b16 --- /dev/null +++ b/test/Resque/Tests/LogTest.php @@ -0,0 +1,31 @@ + + * @license http://www.opensource.org/licenses/mit-license.php + */ +class Resque_Tests_LogTest extends Resque_Tests_TestCase +{ + public function testLogInterpolate() + { + $logger = new Resque_Log(); + $actual = $logger->interpolate('string {replace}', array('replace' => 'value')); + $expected = 'string value'; + + $this->assertEquals($expected, $actual); + } + + public function testLogInterpolateMutiple() + { + $logger = new Resque_Log(); + $actual = $logger->interpolate( + 'string {replace1} {replace2}', + array('replace1' => 'value1', 'replace2' => 'value2') + ); + $expected = 'string value1 value2'; + + $this->assertEquals($expected, $actual); + } +} diff --git a/test/Resque/Tests/WorkerTest.php b/test/Resque/Tests/WorkerTest.php index 1ab7dd2..93c0621 100644 --- a/test/Resque/Tests/WorkerTest.php +++ b/test/Resque/Tests/WorkerTest.php @@ -11,6 +11,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testWorkerRegistersInList() { $worker = new Resque_Worker('*'); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); // Make sure the worker is in the list @@ -23,6 +24,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase // Register a few workers for($i = 0; $i < $num; ++$i) { $worker = new Resque_Worker('queue_' . $i); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); } @@ -33,6 +35,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testGetWorkerById() { $worker = new Resque_Worker('*'); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); $newWorker = Resque_Worker::find((string)$worker); @@ -47,6 +50,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testWorkerCanUnregister() { $worker = new Resque_Worker('*'); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); $worker->unregisterWorker(); @@ -58,6 +62,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testPausedWorkerDoesNotPickUpJobs() { $worker = new Resque_Worker('*'); + $worker->setLogger(new Resque_Log()); $worker->pauseProcessing(); Resque::enqueue('jobs', 'Test_Job'); $worker->work(0); @@ -68,6 +73,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testResumedWorkerPicksUpJobs() { $worker = new Resque_Worker('*'); + $worker->setLogger(new Resque_Log()); $worker->pauseProcessing(); Resque::enqueue('jobs', 'Test_Job'); $worker->work(0); @@ -83,6 +89,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase 'queue1', 'queue2' )); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); Resque::enqueue('queue1', 'Test_Job_1'); Resque::enqueue('queue2', 'Test_Job_2'); @@ -101,6 +108,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase 'medium', 'low' )); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); // Queue the jobs in a different order @@ -122,6 +130,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testWildcardQueueWorkerWorksAllQueues() { $worker = new Resque_Worker('*'); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); Resque::enqueue('queue1', 'Test_Job_1'); @@ -137,6 +146,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testWorkerDoesNotWorkOnUnknownQueues() { $worker = new Resque_Worker('queue1'); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); Resque::enqueue('queue2', 'Test_Job'); @@ -147,6 +157,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase { Resque::enqueue('jobs', 'Test_Job'); $worker = new Resque_Worker('jobs'); + $worker->setLogger(new Resque_Log()); $job = $worker->reserve(); $worker->workingOn($job); $worker->doneWorking(); @@ -156,6 +167,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testWorkerRecordsWhatItIsWorkingOn() { $worker = new Resque_Worker('jobs'); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); $payload = array( @@ -178,6 +190,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase Resque::enqueue('jobs', 'Invalid_Job'); $worker = new Resque_Worker('jobs'); + $worker->setLogger(new Resque_Log()); $worker->work(0); $worker->work(0); @@ -189,15 +202,18 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase { // Register a good worker $goodWorker = new Resque_Worker('jobs'); + $goodWorker->setLogger(new Resque_Log()); $goodWorker->registerWorker(); $workerId = explode(':', $goodWorker); // Register some bad workers $worker = new Resque_Worker('jobs'); + $worker->setLogger(new Resque_Log()); $worker->setId($workerId[0].':1:jobs'); $worker->registerWorker(); $worker = new Resque_Worker(array('high', 'low')); + $worker->setLogger(new Resque_Log()); $worker->setId($workerId[0].':2:high,low'); $worker->registerWorker(); @@ -213,12 +229,14 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase { // Register a bad worker on this machine $worker = new Resque_Worker('jobs'); + $worker->setLogger(new Resque_Log()); $workerId = explode(':', $worker); $worker->setId($workerId[0].':1:jobs'); $worker->registerWorker(); // Register some other false workers $worker = new Resque_Worker('jobs'); + $worker->setLogger(new Resque_Log()); $worker->setId('my.other.host:1:jobs'); $worker->registerWorker(); @@ -235,6 +253,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testWorkerFailsUncompletedJobsOnExit() { $worker = new Resque_Worker('jobs'); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); $payload = array( @@ -251,6 +270,7 @@ class Resque_Tests_WorkerTest extends Resque_Tests_TestCase public function testBlockingListPop() { $worker = new Resque_Worker('jobs'); + $worker->setLogger(new Resque_Log()); $worker->registerWorker(); Resque::enqueue('jobs', 'Test_Job_1');