Skip to content

Commit 726e58a

Browse files
Rockstar04Rockstar04
committed
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
1 parent 7aa9abd commit 726e58a

File tree

8 files changed

+161
-56
lines changed

8 files changed

+161
-56
lines changed

‎bin/resque

Lines changed: 12 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -39,17 +39,19 @@ if(!empty($REDIS_BACKEND)) {
3939
Resque::setBackend($REDIS_BACKEND, $REDIS_BACKEND_DB);
4040
}
4141

42-
$logLevel = 0;
42+
$logLevel = false;
4343
$LOGGING = getenv('LOGGING');
4444
$VERBOSE = getenv('VERBOSE');
4545
$VVERBOSE = getenv('VVERBOSE');
4646
if(!empty($LOGGING) || !empty($VERBOSE)) {
47-
$logLevel = Resque_Worker::LOG_NORMAL;
47+
$logLevel = true;
4848
}
4949
else if(!empty($VVERBOSE)) {
50-
$logLevel = Resque_Worker::LOG_VERBOSE;
50+
$logLevel = true;
5151
}
5252

53+
$logger = new Resque_Log($logLevel);
54+
5355
$APP_INCLUDE = getenv('APP_INCLUDE');
5456
if($APP_INCLUDE) {
5557
if(!file_exists($APP_INCLUDE)) {
@@ -75,22 +77,23 @@ if(!empty($COUNT) && $COUNT > 1) {
7577

7678
$PREFIX = getenv('PREFIX');
7779
if(!empty($PREFIX)) {
78-
fwrite(STDOUT, '*** Prefix set to '.$PREFIX."\n");
80+
$logger->log(Psr\Log\LogLevel::INFO, 'Prefix set to {prefix}', array('prefix' => $PREFIX));
7981
Resque_Redis::prefix($PREFIX);
8082
}
8183

8284
if($count > 1) {
8385
for($i = 0; $i < $count; ++$i) {
8486
$pid = Resque::fork();
8587
if($pid == -1) {
86-
die("Could not fork worker ".$i."\n");
88+
$logger->log(Psr\Log\LogLevel::EMERGENCY, 'Could not fork worker {count}', array('count' => $i));
89+
die();
8790
}
8891
// Child, start the worker
8992
else if(!$pid) {
9093
$queues = explode(',', $QUEUE);
9194
$worker = new Resque_Worker($queues);
92-
$worker->logLevel = $logLevel;
93-
fwrite(STDOUT, '*** Starting worker '.$worker."\n");
95+
$worker->setLogger(new Resque_Log($logLevel));
96+
$logger->log(Psr\Log\LogLevel::NOTICE, 'Starting worker {worker}', array('worker' => $worker));
9497
$worker->work($interval, $BLOCKING);
9598
break;
9699
}
@@ -100,15 +103,15 @@ if($count > 1) {
100103
else {
101104
$queues = explode(',', $QUEUE);
102105
$worker = new Resque_Worker($queues);
103-
$worker->logLevel = $logLevel;
106+
$worker->setLogger(new Resque_Log($logLevel));
104107

105108
$PIDFILE = getenv('PIDFILE');
106109
if ($PIDFILE) {
107110
file_put_contents($PIDFILE, getmypid()) or
108111
die('Could not write PID information to ' . $PIDFILE);
109112
}
110113

111-
fwrite(STDOUT, '*** Starting worker '.$worker."\n");
114+
$logger->log(Psr\Log\LogLevel::NOTICE, 'Starting worker {worker}', array('worker' => $worker));
112115
$worker->work($interval, $BLOCKING);
113116
}
114117
?>

‎lib/Resque/Log.php

Lines changed: 62 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,62 @@
1+
<?php
2+
/**
3+
* Resque default logger PSR-3 compliant
4+
*
5+
* @package Resque/Stat
6+
* @author Chris Boulton <[email protected]>
7+
* @license http://www.opensource.org/licenses/mit-license.php
8+
*/
9+
class Resque_Log extends Psr\Log\AbstractLogger
10+
{
11+
public $verbose;
12+
13+
public function __construct($verbose = false) {
14+
$this->verbose = $verbose;
15+
}
16+
17+
/**
18+
* Logs with an arbitrary level.
19+
*
20+
* @param mixed $level PSR-3 log level constant, or equivalent string
21+
* @param string $message Message to log, may contain a { placeholder }
22+
* @param array $context Variables to replace { placeholder }
23+
* @return null
24+
*/
25+
public function log($level, $message, array $context = array())
26+
{
27+
if ($this->verbose) {
28+
fwrite(
29+
STDOUT,
30+
'[' . $level . '] [' . strftime('%T %Y-%m-%d') . '] ' . $this->interpolate($message, $context) . PHP_EOL
31+
);
32+
return;
33+
}
34+
35+
if (!($level === Psr\Log\LogLevel::INFO || $level === Psr\Log\LogLevel::DEBUG)) {
36+
fwrite(
37+
STDOUT,
38+
'[' . $level . '] ' . $this->interpolate($message, $context) . PHP_EOL
39+
);
40+
}
41+
}
42+
43+
/**
44+
* Fill placeholders with the provided context
45+
* @author Jordi Boggiano [email protected]
46+
*
47+
* @param string $message Message to be logged
48+
* @param array $context Array of variables to use in message
49+
* @return string
50+
*/
51+
public function interpolate($message, array $context = array())
52+
{
53+
// build a replacement array with braces around the context keys
54+
$replace = array();
55+
foreach ($context as $key => $val) {
56+
$replace['{' . $key . '}'] = $val;
57+
}
58+
59+
// interpolate replacement values into the message and return
60+
return strtr($message, $replace);
61+
}
62+
}

‎lib/Resque/Worker.php

Lines changed: 33 additions & 47 deletions
Original file line numberDiff line numberDiff line change
@@ -9,14 +9,10 @@
99
*/
1010
class Resque_Worker
1111
{
12-
const LOG_NONE = 0;
13-
const LOG_NORMAL = 1;
14-
const LOG_VERBOSE = 2;
15-
1612
/**
17-
* @var int Current log level of this worker.
18-
*/
19-
public $logLevel = 0;
13+
* @var LoggerInterface Logging object that impliments the PSR-3 LoggerInterface
14+
*/
15+
public $logger;
2016

2117
/**
2218
* @var array Array of all associated queues for this worker.
@@ -161,7 +157,7 @@ public function work($interval = Resque::DEFAULT_INTERVAL, $blocking = false)
161157
$job = false;
162158
if(!$this->paused) {
163159
if($blocking === true) {
164-
$this->log('Starting blocking with timeout of ' . $interval, self::LOG_VERBOSE);
160+
$this->logger->log(Psr\Log\LogLevel::INFO, 'Starting blocking with timeout of {interval}', array('interval' => $interval));
165161
$this->updateProcLine('Waiting for ' . implode(',', $this->queues) . ' with blocking timeout ' . $interval);
166162
} else {
167163
$this->updateProcLine('Waiting for ' . implode(',', $this->queues) . ' with interval ' . $interval);
@@ -179,7 +175,7 @@ public function work($interval = Resque::DEFAULT_INTERVAL, $blocking = false)
179175
if($blocking === false)
180176
{
181177
// If no job was found, we sleep for $interval before continuing and checking again
182-
$this->log('Sleeping for ' . $interval, self::LOG_VERBOSE);
178+
$this->logger->log(Psr\Log\LogLevel::INFO, 'Sleeping for {interval}', array('interval' => $interval));
183179
if($this->paused) {
184180
$this->updateProcLine('Paused');
185181
}
@@ -193,7 +189,7 @@ public function work($interval = Resque::DEFAULT_INTERVAL, $blocking = false)
193189
continue;
194190
}
195191

196-
$this->log('got ' . $job);
192+
$this->logger->log(Psr\Log\LogLevel::NOTICE, 'Starting work on {job}', array('job' => $job));
197193
Resque_Event::trigger('beforeFork', $job);
198194
$this->workingOn($job);
199195

@@ -203,7 +199,7 @@ public function work($interval = Resque::DEFAULT_INTERVAL, $blocking = false)
203199
if ($this->child === 0 || $this->child === false) {
204200
$status = 'Processing ' . $job->queue . ' since ' . strftime('%F %T');
205201
$this->updateProcLine($status);
206-
$this->log($status, self::LOG_VERBOSE);
202+
$this->logger->log(Psr\Log\LogLevel::INFO, $status);
207203
$this->perform($job);
208204
if ($this->child === 0) {
209205
exit(0);
@@ -214,7 +210,7 @@ public function work($interval = Resque::DEFAULT_INTERVAL, $blocking = false)
214210
// Parent process, sit and wait
215211
$status = 'Forked ' . $this->child . ' at ' . strftime('%F %T');
216212
$this->updateProcLine($status);
217-
$this->log($status, self::LOG_VERBOSE);
213+
$this->logger->log(Psr\Log\LogLevel::INFO, $status);
218214

219215
// Wait until the child process finishes before continuing
220216
pcntl_wait($status);
@@ -245,13 +241,13 @@ public function perform(Resque_Job $job)
245241
$job->perform();
246242
}
247243
catch(Exception $e) {
248-
$this->log($job . ' failed: ' . $e->getMessage());
244+
$this->logger->log(Psr\Log\LogLevel::CRITICAL, '{job} has failed {stack}', array('job' => $job, 'stack' => $e->getMessage()));
249245
$job->fail($e);
250246
return;
251247
}
252248

253249
$job->updateStatus(Resque_Job_Status::STATUS_COMPLETE);
254-
$this->log('done ' . $job);
250+
$this->logger->log(Psr\Log\LogLevel::NOTICE, '{job} has finished', array('job' => $job));
255251
}
256252

257253
/**
@@ -269,15 +265,15 @@ public function reserve($blocking = false, $timeout = null)
269265
if($blocking === true) {
270266
$job = Resque_Job::reserveBlocking($queues, $timeout);
271267
if($job) {
272-
$this->log('Found job on ' . $job->queue, self::LOG_VERBOSE);
268+
$this->logger->log(Psr\Log\LogLevel::INFO, 'Found job on {queue}', array('queue' => $job->queue));
273269
return $job;
274270
}
275271
} else {
276272
foreach($queues as $queue) {
277-
$this->log('Checking ' . $queue, self::LOG_VERBOSE);
273+
$this->logger->log(Psr\Log\LogLevel::INFO, 'Checking {queue} for jobs', array('queue' => $queue));
278274
$job = Resque_Job::reserve($queue);
279275
if($job) {
280-
$this->log('Found job on ' . $queue, self::LOG_VERBOSE);
276+
$this->logger->log(Psr\Log\LogLevel::INFO, 'Found job on {queue}', array('queue' => $job->queue));
281277
return $job;
282278
}
283279
}
@@ -355,15 +351,15 @@ private function registerSigHandlers()
355351
pcntl_signal(SIGUSR2, array($this, 'pauseProcessing'));
356352
pcntl_signal(SIGCONT, array($this, 'unPauseProcessing'));
357353
pcntl_signal(SIGPIPE, array($this, 'reestablishRedisConnection'));
358-
$this->log('Registered signals', self::LOG_VERBOSE);
354+
$this->logger->log(Psr\Log\LogLevel::DEBUG, 'Registered signals');
359355
}
360356

361357
/**
362358
* Signal handler callback for USR2, pauses processing of new jobs.
363359
*/
364360
public function pauseProcessing()
365361
{
366-
$this->log('USR2 received; pausing job processing');
362+
$this->logger->log(Psr\Log\LogLevel::NOTICE, 'USR2 received; pausing job processing');
367363
$this->paused = true;
368364
}
369365

@@ -373,7 +369,7 @@ public function pauseProcessing()
373369
*/
374370
public function unPauseProcessing()
375371
{
376-
$this->log('CONT received; resuming job processing');
372+
$this->logger->log(Psr\Log\LogLevel::NOTICE, 'CONT received; resuming job processing');
377373
$this->paused = false;
378374
}
379375

@@ -383,7 +379,7 @@ public function unPauseProcessing()
383379
*/
384380
public function reestablishRedisConnection()
385381
{
386-
$this->log('SIGPIPE received; attempting to reconnect');
382+
$this->logger->log(Psr\Log\LogLevel::NOTICE, 'SIGPIPE received; attempting to reconnect');
387383
Resque::redis()->establishConnection();
388384
}
389385

@@ -394,7 +390,7 @@ public function reestablishRedisConnection()
394390
public function shutdown()
395391
{
396392
$this->shutdown = true;
397-
$this->log('Exiting...');
393+
$this->logger->log(Psr\Log\LogLevel::NOTICE, 'Shutting down');
398394
}
399395

400396
/**
@@ -414,18 +410,18 @@ public function shutdownNow()
414410
public function killChild()
415411
{
416412
if(!$this->child) {
417-
$this->log('No child to kill.', self::LOG_VERBOSE);
413+
$this->logger->log(Psr\Log\LogLevel::DEBUG, 'No child to kill.');
418414
return;
419415
}
420416

421-
$this->log('Killing child at ' . $this->child, self::LOG_VERBOSE);
417+
$this->logger->log(Psr\Log\LogLevel::INFO, 'Killing child at {child}', array('child' => $this->child));
422418
if(exec('ps -o pid,state -p ' . $this->child, $output, $returnCode) && $returnCode != 1) {
423-
$this->log('Killing child at ' . $this->child, self::LOG_VERBOSE);
419+
$this->logger->log(Psr\Log\LogLevel::DEBUG, 'Child {child} found, killing.', array('child' => $this->child));
424420
posix_kill($this->child, SIGKILL);
425421
$this->child = null;
426422
}
427423
else {
428-
$this->log('Child ' . $this->child . ' not found, restarting.', self::LOG_VERBOSE);
424+
$this->logger->log(Psr\Log\LogLevel::INFO, 'Child {child} not found, restarting.', array('child' => $this->child));
429425
$this->shutdown();
430426
}
431427
}
@@ -448,7 +444,7 @@ public function pruneDeadWorkers()
448444
if($host != $this->hostname || in_array($pid, $workerPids) || $pid == getmypid()) {
449445
continue;
450446
}
451-
$this->log('Pruning dead worker: ' . (string)$worker, self::LOG_VERBOSE);
447+
$this->logger->log(Psr\Log\LogLevel::INFO, 'Pruning dead worker: {worker}', array('worker' => (string)$worker));
452448
$worker->unregisterWorker();
453449
}
454450
}
@@ -536,26 +532,6 @@ public function __toString()
536532
return $this->id;
537533
}
538534

539-
/**
540-
* Output a given log message to STDOUT.
541-
*
542-
* @param string $message Message to output.
543-
* @param int $logLevel The logging level to capture
544-
*/
545-
public function log($message, $logLevel = self::LOG_NORMAL)
546-
{
547-
if ($logLevel > $this->logLevel) {
548-
return;
549-
}
550-
551-
if ($this->logLevel == self::LOG_NORMAL) {
552-
fwrite(STDOUT, "*** " . $message . "\n");
553-
return;
554-
}
555-
556-
fwrite(STDOUT, "** [" . strftime('%T %Y-%m-%d') . "] " . $message . "\n");
557-
}
558-
559535
/**
560536
* Return an object describing the job this worker is currently working on.
561537
*
@@ -582,5 +558,15 @@ public function getStat($stat)
582558
{
583559
return Resque_Stat::get($stat . ':' . $this);
584560
}
561+
562+
/**
563+
* Inject the logging object into the worker
564+
*
565+
* @param Psr\Log\LoggerInterface $logger
566+
*/
567+
public function setLogger(Psr\Log\LoggerInterface $logger)
568+
{
569+
$this->logger = $logger;
570+
}
585571
}
586572
?>

‎test/Resque/Tests/EventTest.php

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@ public function setUp()
1616

1717
// Register a worker to test with
1818
$this->worker = new Resque_Worker('jobs');
19+
$this->worker->setLogger(new Resque_Log());
1920
$this->worker->registerWorker();
2021
}
2122

‎test/Resque/Tests/JobStatusTest.php

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@ public function setUp()
1919

2020
// Register a worker to test with
2121
$this->worker = new Resque_Worker('jobs');
22+
$this->worker->setLogger(new Resque_Log());
2223
}
2324

2425
public function testJobStatusCanBeTracked()

‎test/Resque/Tests/JobTest.php

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ public function setUp()
1717

1818
// Register a worker to test with
1919
$this->worker = new Resque_Worker('jobs');
20+
$this->worker->setLogger(new Resque_Log());
2021
$this->worker->registerWorker();
2122
}
2223

0 commit comments

Comments
 (0)