From 2a8c7dffdf0c4f7dd58ae1e7f74b9a3eb93f1ad9 Mon Sep 17 00:00:00 2001 From: Jordi Boggiano Date: Mon, 9 May 2022 00:16:47 +0200 Subject: [PATCH 1/5] Also allow for slow ES8 start --- .github/workflows/continuous-integration.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/continuous-integration.yml b/.github/workflows/continuous-integration.yml index 6f8a4f11..ff2cc1a6 100644 --- a/.github/workflows/continuous-integration.yml +++ b/.github/workflows/continuous-integration.yml @@ -210,7 +210,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 }}" From c709906d0a41790b000625ce70b0c6430add266d Mon Sep 17 00:00:00 2001 From: Lito Date: Mon, 9 May 2022 22:37:14 +0200 Subject: [PATCH 2/5] [2.X] Allow stacktraces parser on LineFormatter (#1665) * Allow stacktraces parser on LineFormatter * Added includeStacktraces parse tests --- src/Monolog/Formatter/LineFormatter.php | 23 ++++++- tests/Monolog/Formatter/LineFormatterTest.php | 67 +++++++++++++++++++ 2 files changed, 88 insertions(+), 2 deletions(-) diff --git a/src/Monolog/Formatter/LineFormatter.php b/src/Monolog/Formatter/LineFormatter.php index a855c525..d0b4de94 100644 --- a/src/Monolog/Formatter/LineFormatter.php +++ b/src/Monolog/Formatter/LineFormatter.php @@ -33,6 +33,8 @@ class LineFormatter extends NormalizerFormatter protected $ignoreEmptyContextAndExtra; /** @var bool */ protected $includeStacktraces; + /** @var ?callable */ + protected $stacktracesParser; /** * @param string|null $format The format of the message @@ -49,11 +51,12 @@ class LineFormatter extends NormalizerFormatter parent::__construct($dateFormat); } - public function includeStacktraces(bool $include = true): self + public function includeStacktraces(bool $include = true, ?callable $parser = null): self { $this->includeStacktraces = $include; if ($this->includeStacktraces) { $this->allowInlineLineBreaks = true; + $this->stacktracesParser = $parser; } return $this; @@ -209,9 +212,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) { + $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/tests/Monolog/Formatter/LineFormatterTest.php b/tests/Monolog/Formatter/LineFormatterTest.php index 86d22d38..d4d7c658 100644 --- a/tests/Monolog/Formatter/LineFormatterTest.php +++ b/tests/Monolog/Formatter/LineFormatterTest.php @@ -155,6 +155,73 @@ class LineFormatterTest extends \PHPUnit\Framework\TestCase $this->assertRegexp('{^\['.date('Y-m-d').'] core\.CRITICAL: foobar \{"exception":"\[object] \(RuntimeException\(code: 0\): Foo at '.preg_quote(substr($path, 1, -1)).':'.(__LINE__ - 8).'\)\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([ + 'level_name' => 'CRITICAL', + 'channel' => 'core', + 'context' => ['exception' => new \RuntimeException('Foo')], + 'datetime' => new \DateTimeImmutable, + 'extra' => [], + 'message' => 'foobar', + ]); + + $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([ + 'level_name' => 'CRITICAL', + 'channel' => 'core', + 'context' => ['exception' => new \RuntimeException('Foo')], + 'datetime' => new \DateTimeImmutable, + 'extra' => [], + 'message' => 'foobar', + ]); + + $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([ + 'level_name' => 'CRITICAL', + 'channel' => 'core', + 'context' => ['exception' => new \RuntimeException('Foo')], + 'datetime' => new \DateTimeImmutable, + 'extra' => [], + 'message' => 'foobar', + ]); + + $trace = explode('[stacktrace]', $message, 2)[1]; + + $this->assertStringNotContainsString('#', $trace); + } + public function testDefFormatWithPreviousException() { $formatter = new LineFormatter(null, 'Y-m-d'); From 5d43fd52d34230b973b482482e354acf598a4330 Mon Sep 17 00:00:00 2001 From: Jordi Boggiano Date: Tue, 10 May 2022 10:19:45 +0200 Subject: [PATCH 3/5] Allow UdpSocket to reconnect after close() --- src/Monolog/Handler/SyslogUdp/UdpSocket.php | 40 ++++++++++++++------- tests/Monolog/Handler/UdpSocketTest.php | 4 +-- 2 files changed, 28 insertions(+), 16 deletions(-) diff --git a/src/Monolog/Handler/SyslogUdp/UdpSocket.php b/src/Monolog/Handler/SyslogUdp/UdpSocket.php index 30b5186b..dbd8ef69 100644 --- a/src/Monolog/Handler/SyslogUdp/UdpSocket.php +++ b/src/Monolog/Handler/SyslogUdp/UdpSocket.php @@ -23,20 +23,12 @@ class UdpSocket /** @var int */ protected $port; /** @var resource|Socket|null */ - protected $socket; + protected $socket = null; public function __construct(string $ip, int $port = 514) { $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; - } - $this->socket = socket_create($domain, SOCK_DGRAM, $protocol) ?: null; } /** @@ -57,12 +49,34 @@ class UdpSocket } } + /** + * @return resource|Socket + */ + protected function getSocket() + { + 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; + } + + $this->socket = socket_create($domain, SOCK_DGRAM, $protocol) ?: null; + if (null === $this->socket) { + throw new \RuntimeException('The UdpSocket to '.$this->ip.':'.$this->port.' could not be opened via socket_create'); + } + + return $this->socket; + } + protected function send(string $chunk): void { - if (!is_resource($this->socket) && !$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/tests/Monolog/Handler/UdpSocketTest.php b/tests/Monolog/Handler/UdpSocketTest.php index c14fa8d4..98c65dc2 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"); From a5d65f6ec48b6ec5f4aefeea59073ac48432d753 Mon Sep 17 00:00:00 2001 From: Jordi Boggiano Date: Tue, 10 May 2022 11:10:07 +0200 Subject: [PATCH 4/5] Fix infinite loops when a log handler triggers logging itself --- src/Monolog/Logger.php | 79 ++++++++++++++++++++++-------------- tests/Monolog/LoggerTest.php | 56 +++++++++++++++++++++++++ 2 files changed, 104 insertions(+), 31 deletions(-) diff --git a/src/Monolog/Logger.php b/src/Monolog/Logger.php index 1f4ef7f1..0c2240e2 100644 --- a/src/Monolog/Logger.php +++ b/src/Monolog/Logger.php @@ -147,6 +147,11 @@ class Logger implements LoggerInterface, ResettableInterface */ protected $exceptionHandler; + /** + * @var int Keeps track of depth to prevent infinite logging loops + */ + private $logDepth = 0; + /** * @psalm-param array $processors * @@ -291,30 +296,51 @@ class Logger implements LoggerInterface, ResettableInterface */ public function addRecord(int $level, string $message, array $context = []): bool { - $record = null; + $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; + } - foreach ($this->handlers as $handler) { - if (null === $record) { - // skip creating the record as long as no handler is going to handle it - if (!$handler->isHandling(['level' => $level])) { - continue; + try { + $record = null; + + foreach ($this->handlers as $handler) { + if (null === $record) { + // skip creating the record as long as no handler is going to handle it + if (!$handler->isHandling(['level' => $level])) { + continue; + } + + $levelName = static::getLevelName($level); + + $record = [ + 'message' => $message, + 'context' => $context, + 'level' => $level, + 'level_name' => $levelName, + 'channel' => $this->name, + 'datetime' => new DateTimeImmutable($this->microsecondTimestamps, $this->timezone), + 'extra' => [], + ]; + + try { + foreach ($this->processors as $processor) { + $record = $processor($record); + } + } catch (Throwable $e) { + $this->handleException($e, $record); + + return true; + } } - $levelName = static::getLevelName($level); - - $record = [ - 'message' => $message, - 'context' => $context, - 'level' => $level, - 'level_name' => $levelName, - 'channel' => $this->name, - 'datetime' => new DateTimeImmutable($this->microsecondTimestamps, $this->timezone), - 'extra' => [], - ]; - + // once the record exists, send it to all handlers as long as the bubbling chain is not interrupted try { - foreach ($this->processors as $processor) { - $record = $processor($record); + if (true === $handler->handle($record)) { + break; } } catch (Throwable $e) { $this->handleException($e, $record); @@ -322,17 +348,8 @@ class Logger implements LoggerInterface, ResettableInterface return true; } } - - // once the record exists, send it to all handlers as long as the bubbling chain is not interrupted - try { - if (true === $handler->handle($record)) { - break; - } - } catch (Throwable $e) { - $this->handleException($e, $record); - - return true; - } + } finally { + $this->logDepth--; } return null !== $record; diff --git a/tests/Monolog/LoggerTest.php b/tests/Monolog/LoggerTest.php index bd5ae20d..bec548fd 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; @@ -84,6 +85,28 @@ class LoggerTest extends \PHPUnit\Framework\TestCase $this->assertEquals('foo', $record['channel']); } + /** + * @covers Monolog\Logger::addRecord + */ + public function testLogPreventsCircularLogging() + { + $logger = new Logger(__METHOD__); + + $loggingHandler = new LoggingHandler($logger); + $testHandler = new TestHandler(); + + $logger->pushHandler($loggingHandler); + $logger->pushHandler($testHandler); + + $logger->addRecord(Logger::ALERT, 'test'); + + $records = $testHandler->getRecords(); + $this->assertCount(3, $records); + $this->assertSame('ALERT', $records[0]['level_name']); + $this->assertSame('DEBUG', $records[1]['level_name']); + $this->assertSame('WARNING', $records[2]['level_name']); + } + /** * @covers Monolog\Logger::addRecord */ @@ -717,3 +740,36 @@ class LoggerTest extends \PHPUnit\Framework\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(array $record): bool + { + return true; + } + + public function handle(array $record): bool + { + $this->logger->debug('Log triggered while logging'); + + return false; + } + + public function handleBatch(array $records): void + { + } + + public function close(): void + { + } +} From 247918972acd74356b0a91dfaa5adcaec069b6c0 Mon Sep 17 00:00:00 2001 From: Jordi Boggiano Date: Tue, 10 May 2022 11:36:00 +0200 Subject: [PATCH 5/5] Update changelog --- CHANGELOG.md | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index d04ab53f..e374fa78 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,12 @@ +### 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)