diff --git a/.github/workflows/continuous-integration.yml b/.github/workflows/continuous-integration.yml index 0654540f..bab50dba 100644 --- a/.github/workflows/continuous-integration.yml +++ b/.github/workflows/continuous-integration.yml @@ -186,7 +186,7 @@ jobs: sudo sysctl -w vm.max_map_count=262144 - name: Run Elasticsearch - timeout-minutes: 1 + timeout-minutes: 3 uses: elastic/elastic-github-actions/elasticsearch@master with: stack-version: "${{ matrix.es-version }}" diff --git a/CHANGELOG.md b/CHANGELOG.md index f7917046..58bd5e44 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -41,6 +41,15 @@ New deprecations: value equal to what `Logger::WARNING` was giving you. - `Logger::getLevelName()` is now deprecated. +### 2.6.0 (2022-05-10) + + * Deprecated `SwiftMailerHandler`, use `SymfonyMailerHandler` instead + * Added `SymfonyMailerHandler` (#1663) + * Added ElasticSearch 8.x support to the ElasticsearchHandler (#1662) + * Added a way to filter/modify stack traces in LineFormatter (#1665) + * Fixed UdpSocket not being able to reopen/reconnect after close() + * Fixed infinite loops if a Handler is triggering logging while handling log records + ### 2.5.0 (2022-04-08) * Added `callType` to IntrospectionProcessor (#1612) diff --git a/src/Monolog/Formatter/LineFormatter.php b/src/Monolog/Formatter/LineFormatter.php index 554515c5..cdfcca61 100644 --- a/src/Monolog/Formatter/LineFormatter.php +++ b/src/Monolog/Formatter/LineFormatter.php @@ -11,6 +11,7 @@ namespace Monolog\Formatter; +use Closure; use Monolog\Utils; use Monolog\LogRecord; @@ -30,6 +31,7 @@ class LineFormatter extends NormalizerFormatter protected bool $allowInlineLineBreaks; protected bool $ignoreEmptyContextAndExtra; protected bool $includeStacktraces; + protected Closure|null $stacktracesParser = null; /** * @param string|null $format The format of the message @@ -45,11 +47,12 @@ class LineFormatter extends NormalizerFormatter parent::__construct($dateFormat); } - public function includeStacktraces(bool $include = true): self + public function includeStacktraces(bool $include = true, ?Closure $parser = null): self { $this->includeStacktraces = $include; if ($this->includeStacktraces) { $this->allowInlineLineBreaks = true; + $this->stacktracesParser = $parser; } return $this; @@ -205,9 +208,25 @@ class LineFormatter extends NormalizerFormatter $str .= '): ' . $e->getMessage() . ' at ' . $e->getFile() . ':' . $e->getLine() . ')'; if ($this->includeStacktraces) { - $str .= "\n[stacktrace]\n" . $e->getTraceAsString() . "\n"; + $str .= $this->stacktracesParser($e); } return $str; } + + private function stacktracesParser(\Throwable $e): string + { + $trace = $e->getTraceAsString(); + + if ($this->stacktracesParser !== null) { + $trace = $this->stacktracesParserCustom($trace); + } + + return "\n[stacktrace]\n" . $trace . "\n"; + } + + private function stacktracesParserCustom(string $trace): string + { + return implode("\n", array_filter(array_map($this->stacktracesParser, explode("\n", $trace)))); + } } diff --git a/src/Monolog/Handler/SyslogUdp/UdpSocket.php b/src/Monolog/Handler/SyslogUdp/UdpSocket.php index 19db8950..6a483345 100644 --- a/src/Monolog/Handler/SyslogUdp/UdpSocket.php +++ b/src/Monolog/Handler/SyslogUdp/UdpSocket.php @@ -26,18 +26,6 @@ class UdpSocket { $this->ip = $ip; $this->port = $port; - $domain = AF_INET; - $protocol = SOL_UDP; - // Check if we are using unix sockets. - if ($port === 0) { - $domain = AF_UNIX; - $protocol = IPPROTO_IP; - } - - $socket = socket_create($domain, SOCK_DGRAM, $protocol); - if ($socket instanceof Socket) { - $this->socket = $socket; - } } public function write(string $line, string $header = ""): void @@ -53,12 +41,31 @@ class UdpSocket } } + protected function getSocket(): Socket + { + if (null !== $this->socket) { + return $this->socket; + } + + $domain = AF_INET; + $protocol = SOL_UDP; + // Check if we are using unix sockets. + if ($this->port === 0) { + $domain = AF_UNIX; + $protocol = IPPROTO_IP; + } + + $socket = socket_create($domain, SOCK_DGRAM, $protocol); + if ($socket instanceof Socket) { + return $this->socket = $socket; + } + + throw new \RuntimeException('The UdpSocket to '.$this->ip.':'.$this->port.' could not be opened via socket_create'); + } + protected function send(string $chunk): void { - if (!$this->socket instanceof Socket) { - throw new \RuntimeException('The UdpSocket to '.$this->ip.':'.$this->port.' has been closed and can not be written to anymore'); - } - socket_sendto($this->socket, $chunk, strlen($chunk), $flags = 0, $this->ip, $this->port); + socket_sendto($this->getSocket(), $chunk, strlen($chunk), $flags = 0, $this->ip, $this->port); } protected function assembleMessage(string $line, string $header): string diff --git a/src/Monolog/Logger.php b/src/Monolog/Logger.php index 01532519..e5a32445 100644 --- a/src/Monolog/Logger.php +++ b/src/Monolog/Logger.php @@ -129,6 +129,11 @@ class Logger implements LoggerInterface, ResettableInterface protected Closure|null $exceptionHandler = null; + /** + * Keeps track of depth to prevent infinite logging loops + */ + private int $logDepth = 0; + /** * @param string $name The logging channel, a simple descriptive name that is attached to all log records * @param HandlerInterface[] $handlers Optional stack of handlers, the first one in the array is called first, etc. @@ -276,30 +281,52 @@ class Logger implements LoggerInterface, ResettableInterface */ public function addRecord(int|Level $level, string $message, array $context = []): bool { - $recordInitialized = count($this->processors) === 0; + $this->logDepth += 1; + if ($this->logDepth === 3) { + $this->warning('A possible infinite logging loop was detected and aborted. It appears some of your handler code is triggering logging, see the previous log record for a hint as to what may be the cause.'); + return false; + } elseif ($this->logDepth >= 5) { // log depth 4 is let through so we can log the warning above + return false; + } - $record = new LogRecord( - message: $message, - context: $context, - level: self::toMonologLevel($level), - channel: $this->name, - datetime: new DateTimeImmutable($this->microsecondTimestamps, $this->timezone), - extra: [], - ); - $handled = false; + try { + $recordInitialized = count($this->processors) === 0; - foreach ($this->handlers as $handler) { - if (false === $recordInitialized) { - // skip initializing the record as long as no handler is going to handle it - if (!$handler->isHandling($record)) { - continue; + $record = new LogRecord( + message: $message, + context: $context, + level: self::toMonologLevel($level), + channel: $this->name, + datetime: new DateTimeImmutable($this->microsecondTimestamps, $this->timezone), + extra: [], + ); + $handled = false; + + foreach ($this->handlers as $handler) { + if (false === $recordInitialized) { + // skip initializing the record as long as no handler is going to handle it + if (!$handler->isHandling($record)) { + continue; + } + + try { + foreach ($this->processors as $processor) { + $record = $processor($record); + } + $recordInitialized = true; + } catch (Throwable $e) { + $this->handleException($e, $record); + + return true; + } } + // once the record is initialized, send it to all handlers as long as the bubbling chain is not interrupted try { - foreach ($this->processors as $processor) { - $record = $processor($record); + $handled = true; + if (true === $handler->handle($record)) { + break; } - $recordInitialized = true; } catch (Throwable $e) { $this->handleException($e, $record); @@ -307,20 +334,10 @@ class Logger implements LoggerInterface, ResettableInterface } } - // once the record is initialized, send it to all handlers as long as the bubbling chain is not interrupted - try { - $handled = true; - if (true === $handler->handle($record)) { - break; - } - } catch (Throwable $e) { - $this->handleException($e, $record); - - return true; - } + return $handled; + } finally { + $this->logDepth--; } - - return $handled; } /** diff --git a/tests/Monolog/Formatter/LineFormatterTest.php b/tests/Monolog/Formatter/LineFormatterTest.php index 9e9364ca..7440eda6 100644 --- a/tests/Monolog/Formatter/LineFormatterTest.php +++ b/tests/Monolog/Formatter/LineFormatterTest.php @@ -141,6 +141,52 @@ class LineFormatterTest extends TestCase $this->assertMatchesRegularExpression('{^\['.date('Y-m-d').'] core\.CRITICAL: foobar \{"exception":"\[object] \(RuntimeException\(code: 0\): Foo at '.preg_quote(substr($path, 1, -1)).':'.(__LINE__ - 5).'\)\n\[stacktrace]\n#0}', $message); } + public function testDefFormatWithExceptionAndStacktraceParserFull() + { + $formatter = new LineFormatter(null, 'Y-m-d'); + $formatter->includeStacktraces(true, function ($line) { + return $line; + }); + + $message = $formatter->format($this->getRecord(Level::Critical, context: ['exception' => new \RuntimeException('Foo')])); + + $trace = explode('[stacktrace]', $message, 2)[1]; + + $this->assertStringContainsString('TestCase.php', $trace); + $this->assertStringContainsString('TestResult.php', $trace); + } + + public function testDefFormatWithExceptionAndStacktraceParserCustom() + { + $formatter = new LineFormatter(null, 'Y-m-d'); + $formatter->includeStacktraces(true, function ($line) { + if (strpos($line, 'TestCase.php') === false) { + return $line; + } + }); + + $message = $formatter->format($this->getRecord(Level::Critical, context: ['exception' => new \RuntimeException('Foo')])); + + $trace = explode('[stacktrace]', $message, 2)[1]; + + $this->assertStringNotContainsString('TestCase.php', $trace); + $this->assertStringContainsString('TestResult.php', $trace); + } + + public function testDefFormatWithExceptionAndStacktraceParserEmpty() + { + $formatter = new LineFormatter(null, 'Y-m-d'); + $formatter->includeStacktraces(true, function ($line) { + return null; + }); + + $message = $formatter->format($this->getRecord(Level::Critical, context: ['exception' => new \RuntimeException('Foo')])); + + $trace = explode('[stacktrace]', $message, 2)[1]; + + $this->assertStringNotContainsString('#', $trace); + } + public function testDefFormatWithPreviousException() { $formatter = new LineFormatter(null, 'Y-m-d'); diff --git a/tests/Monolog/Handler/UdpSocketTest.php b/tests/Monolog/Handler/UdpSocketTest.php index 1e9b32f7..58477997 100644 --- a/tests/Monolog/Handler/UdpSocketTest.php +++ b/tests/Monolog/Handler/UdpSocketTest.php @@ -58,10 +58,8 @@ class UdpSocketTest extends TestCase $socket->close(); } - public function testWriteAfterCloseErrors() + public function testWriteAfterCloseReopened() { - $this->expectException(\RuntimeException::class); - $socket = new UdpSocket('127.0.0.1', 514); $socket->close(); $socket->write('foo', "HEADER"); diff --git a/tests/Monolog/LoggerTest.php b/tests/Monolog/LoggerTest.php index 75fdb1f9..7b100e6f 100644 --- a/tests/Monolog/LoggerTest.php +++ b/tests/Monolog/LoggerTest.php @@ -11,6 +11,7 @@ namespace Monolog; +use Monolog\Handler\HandlerInterface; use Monolog\Processor\WebProcessor; use Monolog\Handler\TestHandler; use Monolog\Test\TestCase; @@ -70,6 +71,28 @@ class LoggerTest extends TestCase /** * @covers Logger::addRecord */ + public function testLogPreventsCircularLogging() + { + $logger = new Logger(__METHOD__); + + $loggingHandler = new LoggingHandler($logger); + $testHandler = new TestHandler(); + + $logger->pushHandler($loggingHandler); + $logger->pushHandler($testHandler); + + $logger->addRecord(Level::Alert, 'test'); + + $records = $testHandler->getRecords(); + $this->assertCount(3, $records); + $this->assertSame('ALERT', $records[0]->level->getName()); + $this->assertSame('DEBUG', $records[1]->level->getName()); + $this->assertSame('WARNING', $records[2]->level->getName()); + } + + /** + * @covers Monolog\Logger::addRecord + */ public function testLog() { $logger = new Logger(__METHOD__); @@ -718,3 +741,36 @@ class LoggerTest extends TestCase $this->assertNotSame($uid2, $processorUid2->getUid()); } } + +class LoggingHandler implements HandlerInterface +{ + /** + * @var Logger + */ + private $logger; + + public function __construct(Logger $logger) + { + $this->logger = $logger; + } + + public function isHandling(LogRecord $record): bool + { + return true; + } + + public function handle(LogRecord $record): bool + { + $this->logger->debug('Log triggered while logging'); + + return false; + } + + public function handleBatch(array $records): void + { + } + + public function close(): void + { + } +}