diff --git a/src/Monolog/Handler/DeduplicationHandler.php b/src/Monolog/Handler/DeduplicationHandler.php new file mode 100644 index 00000000..7778c22a --- /dev/null +++ b/src/Monolog/Handler/DeduplicationHandler.php @@ -0,0 +1,169 @@ + + * + * For the full copyright and license information, please view the LICENSE + * file that was distributed with this source code. + */ + +namespace Monolog\Handler; + +use Monolog\Logger; + +/** + * Simple handler wrapper that deduplicates log records across multiple requests + * + * It also includes the BufferHandler functionality and will buffer + * all messages until the end of the request or flush() is called. + * + * This works by storing all log records' messages above $deduplicationLevel + * to the file specified by $deduplicationStore. When further logs come in at the end of the + * request (or when flush() is called), all those above $deduplicationLevel are checked + * against the existing stored logs. If they match and the timestamps in the stored log is + * not older than $time seconds, the new log record is discarded. If no log record is new, the + * whole data set is discarded. + * + * This is mainly useful in combination with Mail handlers or things like Slack or HipChat handlers + * that send messages to people, to avoid spamming with the same message over and over in case of + * a major component failure like a database server being down which makes all requests fail in the + * same way. + * + * @author Jordi Boggiano + */ +class DeduplicationHandler extends BufferHandler +{ + /** + * @var string + */ + protected $deduplicationStore; + + /** + * @var int + */ + protected $deduplicationLevel; + + /** + * @var int + */ + protected $time; + + /** + * @var bool + */ + private $gc = false; + + /** + * @param HandlerInterface $handler Handler. + * @param string $deduplicationStore The file/path where the deduplication log should be kept + * @param int $deduplicationLevel The minimum logging level for log records to be looked at for deduplication purposes + * @param int $time The period (in seconds) during which duplicate entries should be suppressed after a given log is sent through + * @param Boolean $bubble Whether the messages that are handled can bubble up the stack or not + */ + public function __construct(HandlerInterface $handler, $deduplicationStore = null, $deduplicationLevel = Logger::ERROR, $time = 60, $bubble = true) + { + parent::__construct($handler, 0, Logger::DEBUG, $bubble, false); + + $this->deduplicationStore = $deduplicationStore === null ? sys_get_temp_dir() . '/monolog-dedup-' . substr(md5(__FILE__), 0, 20) .'.log' : $deduplicationStore; + $this->deduplicationLevel = Logger::toMonologLevel($deduplicationLevel); + $this->time = $time; + } + + public function flush() + { + if ($this->bufferSize === 0) { + return; + } + + $passthru = null; + + foreach ($this->buffer as $record) { + if ($record['level'] >= $this->deduplicationLevel) { + + $passthru = $passthru || !$this->isDuplicate($record); + if ($passthru) { + $this->appendRecord($record); + } + } + } + + // default of null is valid as well as if no record matches duplicationLevel we just pass through + if ($passthru === true || $passthru === null) { + $this->handler->handleBatch($this->buffer); + } + + $this->clear(); + + if ($this->gc) { + $this->collectLogs(); + } + } + + private function isDuplicate(array $record) + { + if (!file_exists($this->deduplicationStore)) { + return false; + } + + $store = file($this->deduplicationStore, FILE_IGNORE_NEW_LINES | FILE_SKIP_EMPTY_LINES); + if (!is_array($store)) { + return false; + } + + $yesterday = time() - 86400; + $timestampValidity = $record['datetime']->getTimestamp() - $this->time; + $expectedMessage = preg_replace('{[\r\n].*}', '', $record['message']); + + for ($i = count($store) - 1; $i >= 0; $i--) { + list($timestamp, $level, $message) = explode(':', $store[$i], 3); + + if ($level === $record['level_name'] && $message === $expectedMessage && $timestamp > $timestampValidity) { + return true; + } + + if ($timestamp < $yesterday) { + $this->gc = true; + } + } + + return false; + } + + private function collectLogs() + { + if (!file_exists($this->deduplicationStore)) { + return false; + } + + $handle = fopen($this->deduplicationStore, 'rw+'); + flock($handle, LOCK_EX); + $validLogs = array(); + + $timestampValidity = time() - $this->time; + + while (!feof($handle)) { + $log = fgets($handle); + if (substr($log, 0, 10) >= $timestampValidity) { + $validLogs[] = $log; + } + } + + ftruncate($handle, 0); + rewind($handle); + foreach ($validLogs as $log) { + fwrite($handle, $log); + } + + flock($handle, LOCK_UN); + fclose($handle); + + $this->gc = false; + } + + private function appendRecord(array $record) + { + file_put_contents($this->deduplicationStore, $record['datetime']->getTimestamp() . ':' . $record['level_name'] . ':' . preg_replace('{[\r\n].*}', '', $record['message']) . "\n", FILE_APPEND); + } +} diff --git a/src/Monolog/Handler/MailHandler.php b/src/Monolog/Handler/MailHandler.php index 50ed6380..9e232838 100644 --- a/src/Monolog/Handler/MailHandler.php +++ b/src/Monolog/Handler/MailHandler.php @@ -52,4 +52,16 @@ abstract class MailHandler extends AbstractProcessingHandler { $this->send((string) $record['formatted'], array($record)); } + + protected function getHighestRecord(array $records) + { + $highestRecord = null; + foreach ($records as $record) { + if ($highestRecord === null || $highestRecord['level'] < $record['level']) { + $highestRecord = $record; + } + } + + return $highestRecord; + } } diff --git a/src/Monolog/Handler/NativeMailerHandler.php b/src/Monolog/Handler/NativeMailerHandler.php index 6ff92a96..d7807fd1 100644 --- a/src/Monolog/Handler/NativeMailerHandler.php +++ b/src/Monolog/Handler/NativeMailerHandler.php @@ -12,6 +12,7 @@ namespace Monolog\Handler; use Monolog\Logger; +use Monolog\Formatter\LineFormatter; /** * NativeMailerHandler uses the mail() function to send the emails @@ -122,9 +123,16 @@ class NativeMailerHandler extends MailHandler if ($this->getContentType() == 'text/html' && false === strpos($headers, 'MIME-Version:')) { $headers .= 'MIME-Version: 1.0' . "\r\n"; } + + $subject = $this->subject; + if ($records) { + $subjectFormatter = new LineFormatter($this->subject); + $subject = $subjectFormatter->format($this->getHighestRecord($records)); + } + $parameters = implode(' ', $this->parameters); foreach ($this->to as $to) { - mail($to, $this->subject, $content, $headers, $parameters); + mail($to, $subject, $content, $headers, $parameters); } } diff --git a/src/Monolog/Handler/SwiftMailerHandler.php b/src/Monolog/Handler/SwiftMailerHandler.php index 3e5166d5..92e3e939 100644 --- a/src/Monolog/Handler/SwiftMailerHandler.php +++ b/src/Monolog/Handler/SwiftMailerHandler.php @@ -12,6 +12,7 @@ namespace Monolog\Handler; use Monolog\Logger; +use Monolog\Formatter\LineFormatter; /** * SwiftMailerHandler uses Swift_Mailer to send the emails @@ -66,6 +67,11 @@ class SwiftMailerHandler extends MailHandler throw new \InvalidArgumentException('Could not resolve message as instance of Swift_Message or a callable returning it'); } + if ($records) { + $subjectFormatter = new LineFormatter($message->getSubject()); + $message->setSubject($subjectFormatter->format($this->getHighestRecord($records))); + } + $message->setBody($content); $message->setDate(time()); diff --git a/src/Monolog/Handler/TestHandler.php b/src/Monolog/Handler/TestHandler.php index 2e0e8c4b..458020b6 100644 --- a/src/Monolog/Handler/TestHandler.php +++ b/src/Monolog/Handler/TestHandler.php @@ -73,6 +73,12 @@ class TestHandler extends AbstractProcessingHandler return $this->records; } + public function clear() + { + $this->records = array(); + $this->recordsByLevel = array(); + } + protected function hasRecordRecords($level) { return isset($this->recordsByLevel[$level]); diff --git a/tests/Monolog/Handler/DeduplicationHandlerTest.php b/tests/Monolog/Handler/DeduplicationHandlerTest.php new file mode 100644 index 00000000..e2aff868 --- /dev/null +++ b/tests/Monolog/Handler/DeduplicationHandlerTest.php @@ -0,0 +1,165 @@ + + * + * For the full copyright and license information, please view the LICENSE + * file that was distributed with this source code. + */ + +namespace Monolog\Handler; + +use Monolog\TestCase; +use Monolog\Logger; + +class DeduplicationHandlerTest extends TestCase +{ + /** + * @covers Monolog\Handler\DeduplicationHandler::flush + */ + public function testFlushPassthruIfAllRecordsUnderTrigger() + { + $test = new TestHandler(); + @unlink(sys_get_temp_dir().'/monolog_dedup.log'); + $handler = new DeduplicationHandler($test, sys_get_temp_dir().'/monolog_dedup.log', 0); + + $handler->handle($this->getRecord(Logger::DEBUG)); + $handler->handle($this->getRecord(Logger::INFO)); + + $handler->flush(); + + $this->assertTrue($test->hasInfoRecords()); + $this->assertTrue($test->hasDebugRecords()); + $this->assertFalse($test->hasWarningRecords()); + } + + /** + * @covers Monolog\Handler\DeduplicationHandler::flush + * @covers Monolog\Handler\DeduplicationHandler::appendRecord + */ + public function testFlushPassthruIfEmptyLog() + { + $test = new TestHandler(); + @unlink(sys_get_temp_dir().'/monolog_dedup.log'); + $handler = new DeduplicationHandler($test, sys_get_temp_dir().'/monolog_dedup.log', 0); + + $handler->handle($this->getRecord(Logger::ERROR, 'Foo:bar')); + $handler->handle($this->getRecord(Logger::CRITICAL, "Foo\nbar")); + + $handler->flush(); + + $this->assertTrue($test->hasErrorRecords()); + $this->assertTrue($test->hasCriticalRecords()); + $this->assertFalse($test->hasWarningRecords()); + } + + /** + * @covers Monolog\Handler\DeduplicationHandler::flush + * @covers Monolog\Handler\DeduplicationHandler::appendRecord + * @covers Monolog\Handler\DeduplicationHandler::isDuplicate + * @depends testFlushPassthruIfEmptyLog + */ + public function testFlushSkipsIfLogExists() + { + $test = new TestHandler(); + $handler = new DeduplicationHandler($test, sys_get_temp_dir().'/monolog_dedup.log', 0); + + $handler->handle($this->getRecord(Logger::ERROR, 'Foo:bar')); + $handler->handle($this->getRecord(Logger::CRITICAL, "Foo\nbar")); + + $handler->flush(); + + $this->assertFalse($test->hasErrorRecords()); + $this->assertFalse($test->hasCriticalRecords()); + $this->assertFalse($test->hasWarningRecords()); + } + + /** + * @covers Monolog\Handler\DeduplicationHandler::flush + * @covers Monolog\Handler\DeduplicationHandler::appendRecord + * @covers Monolog\Handler\DeduplicationHandler::isDuplicate + * @depends testFlushPassthruIfEmptyLog + */ + public function testFlushPassthruIfLogTooOld() + { + $test = new TestHandler(); + $handler = new DeduplicationHandler($test, sys_get_temp_dir().'/monolog_dedup.log', 0); + + $record = $this->getRecord(Logger::ERROR); + $record['datetime']->modify('+62seconds'); + $handler->handle($record); + $record = $this->getRecord(Logger::CRITICAL); + $record['datetime']->modify('+62seconds'); + $handler->handle($record); + + $handler->flush(); + + $this->assertTrue($test->hasErrorRecords()); + $this->assertTrue($test->hasCriticalRecords()); + $this->assertFalse($test->hasWarningRecords()); + } + + /** + * @covers Monolog\Handler\DeduplicationHandler::flush + * @covers Monolog\Handler\DeduplicationHandler::appendRecord + * @covers Monolog\Handler\DeduplicationHandler::isDuplicate + * @covers Monolog\Handler\DeduplicationHandler::collectLogs + */ + public function testGcOldLogs() + { + $test = new TestHandler(); + @unlink(sys_get_temp_dir().'/monolog_dedup.log'); + $handler = new DeduplicationHandler($test, sys_get_temp_dir().'/monolog_dedup.log', 0); + + // handle two records from yesterday, and one recent + $record = $this->getRecord(Logger::ERROR); + $record['datetime']->modify('-1day -10seconds'); + $handler->handle($record); + $record2 = $this->getRecord(Logger::CRITICAL); + $record2['datetime']->modify('-1day -10seconds'); + $handler->handle($record2); + $record3 = $this->getRecord(Logger::CRITICAL); + $record3['datetime']->modify('-30seconds'); + $handler->handle($record3); + + // log is written as none of them are duplicate + $handler->flush(); + $this->assertSame( + $record['datetime']->getTimestamp() . ":ERROR:test\n" . + $record2['datetime']->getTimestamp() . ":CRITICAL:test\n" . + $record3['datetime']->getTimestamp() . ":CRITICAL:test\n", + file_get_contents(sys_get_temp_dir() . '/monolog_dedup.log') + ); + $this->assertTrue($test->hasErrorRecords()); + $this->assertTrue($test->hasCriticalRecords()); + $this->assertFalse($test->hasWarningRecords()); + + // clear test handler + $test->clear(); + $this->assertFalse($test->hasErrorRecords()); + $this->assertFalse($test->hasCriticalRecords()); + + // log new records, duplicate log gets GC'd at the end of this flush call + $handler->handle($record = $this->getRecord(Logger::ERROR)); + $handler->handle($record2 = $this->getRecord(Logger::CRITICAL)); + $handler->flush(); + + // log should now contain the new errors and the previous one that was recent enough + $this->assertSame( + $record3['datetime']->getTimestamp() . ":CRITICAL:test\n" . + $record['datetime']->getTimestamp() . ":ERROR:test\n" . + $record2['datetime']->getTimestamp() . ":CRITICAL:test\n", + file_get_contents(sys_get_temp_dir() . '/monolog_dedup.log') + ); + $this->assertTrue($test->hasErrorRecords()); + $this->assertTrue($test->hasCriticalRecords()); + $this->assertFalse($test->hasWarningRecords()); + } + + public static function tearDownAfterClass() + { + @unlink(sys_get_temp_dir().'/monolog_dedup.log'); + } +} diff --git a/tests/Monolog/Handler/NativeMailerHandlerTest.php b/tests/Monolog/Handler/NativeMailerHandlerTest.php index b597f698..ddf545db 100644 --- a/tests/Monolog/Handler/NativeMailerHandlerTest.php +++ b/tests/Monolog/Handler/NativeMailerHandlerTest.php @@ -96,4 +96,16 @@ class NativeMailerHandlerTest extends TestCase $this->assertSame("From: $from\r\nContent-type: text/plain; charset=utf-8\r\n", $params[3]); $this->assertSame('', $params[4]); } + + public function testMessageSubjectFormatting() + { + $mailer = new NativeMailerHandler('to@example.org', 'Alert: %level_name% %message%', 'from@example.org'); + $mailer->handle($this->getRecord(Logger::ERROR, "Foo\nBar\r\n\r\nBaz")); + $this->assertNotEmpty($GLOBALS['mail']); + $this->assertInternalType('array', $GLOBALS['mail']); + $this->assertArrayHasKey('0', $GLOBALS['mail']); + $params = $GLOBALS['mail'][0]; + $this->assertCount(5, $params); + $this->assertSame('Alert: ERROR Foo Bar Baz', $params[1]); + } } diff --git a/tests/Monolog/Handler/SwiftMailerHandlerTest.php b/tests/Monolog/Handler/SwiftMailerHandlerTest.php index b98b498d..85886910 100644 --- a/tests/Monolog/Handler/SwiftMailerHandlerTest.php +++ b/tests/Monolog/Handler/SwiftMailerHandlerTest.php @@ -72,6 +72,30 @@ class SwiftMailerHandlerTest extends TestCase $handler->handleBatch($records); } + public function testMessageSubjectFormatting() + { + // Wire Mailer to expect a specific Swift_Message with a customized Subject + $messageTemplate = new \Swift_Message(); + $messageTemplate->setSubject('Alert: %level_name% %message%'); + $receivedMessage = null; + + $this->mailer->expects($this->once()) + ->method('send') + ->with($this->callback(function ($value) use (&$receivedMessage) { + $receivedMessage = $value; + return true; + })); + + $handler = new SwiftMailerHandler($this->mailer, $messageTemplate); + + $records = array( + $this->getRecord(Logger::EMERGENCY), + ); + $handler->handleBatch($records); + + $this->assertEquals('Alert: EMERGENCY test', $receivedMessage->getSubject()); + } + public function testMessageHaveUniqueId() { $messageTemplate = \Swift_Message::newInstance();