From c49e92808a4c2f053e570c8974f68180e12ea8b3 Mon Sep 17 00:00:00 2001 From: Alex Standiford Date: Tue, 16 Jun 2026 07:49:54 -0400 Subject: [PATCH] fix: preserve chained exception cause in logException logException previously logged only the outer exception's message and discarded the chain. Infrastructure exceptions (e.g. the PDO datastore backend) deliberately surface a stable, client-safe message and carry the real cause as a chained previous exception, so every datastore failure logged only "Failed to execute query." with the actual SQL error dropped. Walk the $e->getPrevious() chain and fold each non-empty message into the logged line. A level is skipped when its message is already embedded in a collected part (some wrappers embed the cause's text and also chain it), and the walk is bounded by a depth cap plus a cycle guard so the message can't grow without limit. Also drop the leading " - " separator that appeared when no prefix message was supplied. --- composer.json | 2 +- lib/Traits/CanLogException.php | 74 +++++++++++++- tests/Unit/CanLogExceptionTest.php | 157 +++++++++++++++++++++++++++++ 3 files changed, 229 insertions(+), 4 deletions(-) create mode 100644 tests/Unit/CanLogExceptionTest.php diff --git a/composer.json b/composer.json index f025c49..da92d82 100644 --- a/composer.json +++ b/composer.json @@ -1,7 +1,7 @@ { "name": "phpnomad/logger", "description": "", - "version": "1.2.1", + "version": "1.2.2", "type": "library", "homepage": "https://github.com/phpnomad/core", "readme": "README.md", diff --git a/lib/Traits/CanLogException.php b/lib/Traits/CanLogException.php index f8327db..c4f98d1 100644 --- a/lib/Traits/CanLogException.php +++ b/lib/Traits/CanLogException.php @@ -5,16 +5,84 @@ use Exception; use PHPNomad\Logger\Enums\LoggerLevel; use PHPNomad\Logger\Interfaces\LoggerStrategy; +use Throwable; trait CanLogException { + /** + * Hard cap on how many levels of the exception chain are folded into the + * logged message, guarding against pathologically deep chains. + */ + protected int $maxLoggedExceptionDepth = 10; + public function logException(Exception $e, string $message = '', array $context = [], $level = null) { - if(!$level){ + if (!$level) { $level = LoggerLevel::Critical; } $context['exception'] = $e; - $this->$level(implode(' - ', [$message, $e->getMessage()]), $context); + $this->$level(implode(' - ', $this->buildExceptionMessageParts($e, $message)), $context); + } + + /** + * Flattens the prefix message and the exception chain into the message + * parts that get logged. + * + * Datastore and other infrastructure exceptions deliberately surface a + * stable, client-safe message and carry the real cause (e.g. the SQL + * driver error) as a chained previous exception. Logging only the outer + * message would discard that cause, so the chain is walked here. + * + * A chain message is skipped when it is already contained in a part we + * have collected — some wrappers embed the cause's message in their own + * text *and* chain the cause, which would otherwise log it twice. The + * walk is also bounded by {@see $maxLoggedExceptionDepth} and a cycle + * guard so the message can never grow without limit. + * + * @return list + */ + protected function buildExceptionMessageParts(Throwable $e, string $message): array + { + $parts = []; + + if ($message !== '') { + $parts[] = $message; + } + + $seen = []; + $current = $e; + $depth = 0; + + while ($current instanceof Throwable && $depth < $this->maxLoggedExceptionDepth && !in_array($current, $seen, true)) { + $seen[] = $current; + $depth++; + + $currentMessage = $current->getMessage(); + if ($currentMessage !== '' && !$this->messageAlreadyCollected($currentMessage, $parts)) { + $parts[] = $currentMessage; + } + + $current = $current->getPrevious(); + } + + return $parts; + } + + /** + * Whether a chain message is already represented in the collected parts, + * so wrappers that embed their cause's message aren't logged twice. + * + * @param list $parts + */ + protected function messageAlreadyCollected(string $message, array $parts): bool + { + foreach ($parts as $part) { + if (strpos($part, $message) !== false) { + return true; + } + } + + return false; } -} \ No newline at end of file +} diff --git a/tests/Unit/CanLogExceptionTest.php b/tests/Unit/CanLogExceptionTest.php new file mode 100644 index 0000000..afb8275 --- /dev/null +++ b/tests/Unit/CanLogExceptionTest.php @@ -0,0 +1,157 @@ +logged = [ + 'level' => $name, + 'message' => $arguments[0] ?? '', + 'context' => $arguments[1] ?? [], + ]; + } + }; + } + + public function testLogsAtCriticalByDefault(): void + { + $logger = $this->makeLogger(); + + $logger->logException(new Exception('boom')); + + $this->assertSame(LoggerLevel::Critical, $logger->logged['level']); + } + + public function testRespectsExplicitLevel(): void + { + $logger = $this->makeLogger(); + + $logger->logException(new Exception('boom'), '', [], LoggerLevel::Warning); + + $this->assertSame(LoggerLevel::Warning, $logger->logged['level']); + } + + public function testKeepsExceptionInContext(): void + { + $logger = $this->makeLogger(); + $e = new Exception('boom'); + + $logger->logException($e); + + $this->assertSame($e, $logger->logged['context']['exception']); + } + + public function testPreservesProvidedContext(): void + { + $logger = $this->makeLogger(); + + $logger->logException(new Exception('boom'), '', ['orgId' => 7]); + + $this->assertSame(7, $logger->logged['context']['orgId']); + } + + public function testIncludesPrefixMessageAndExceptionMessage(): void + { + $logger = $this->makeLogger(); + + $logger->logException(new Exception('boom'), 'while saving'); + + $this->assertStringContainsString('while saving', $logger->logged['message']); + $this->assertStringContainsString('boom', $logger->logged['message']); + } + + public function testWalksChainedCauseIntoMessage(): void + { + $logger = $this->makeLogger(); + + // Mirrors the datastore backend: a stable, client-safe outer message + // with the real driver error chained as the previous exception. + $cause = new Exception('SQLSTATE[42S22]: Column not found: 1054 Unknown column "foo"'); + $outer = new Exception('Failed to execute query.', 0, $cause); + + $logger->logException($outer); + + $message = $logger->logged['message']; + $this->assertStringContainsString('Failed to execute query.', $message); + $this->assertStringContainsString('Unknown column "foo"', $message); + } + + public function testWalksMultiLevelChain(): void + { + $logger = $this->makeLogger(); + + $root = new Exception('root cause'); + $mid = new Exception('mid layer', 0, $root); + $outer = new Exception('outer', 0, $mid); + + $logger->logException($outer); + + $message = $logger->logged['message']; + $this->assertStringContainsString('outer', $message); + $this->assertStringContainsString('mid layer', $message); + $this->assertStringContainsString('root cause', $message); + } + + public function testEmptyPrefixDoesNotProduceLeadingSeparator(): void + { + $logger = $this->makeLogger(); + + $logger->logException(new Exception('boom')); + + $this->assertSame('boom', $logger->logged['message']); + } + + public function testDoesNotRepeatCauseAlreadyEmbeddedInWrapperMessage(): void + { + $logger = $this->makeLogger(); + + // Mirrors QueryStrategy: the wrapper embeds the driver message in its + // own text AND chains the driver exception as the cause. + $driverMessage = 'SQLSTATE[42S22]: Unknown column "foo"'; + $cause = new Exception($driverMessage); + $outer = new Exception('Invalid query: ' . $driverMessage, 0, $cause); + + $logger->logException($outer); + + $this->assertSame( + 1, + substr_count($logger->logged['message'], $driverMessage), + 'The chained cause should not be logged twice when the wrapper already embeds it.' + ); + } + + public function testBoundsPathologicallyDeepChains(): void + { + $logger = $this->makeLogger(); + + $e = new Exception('level-0'); + for ($i = 1; $i <= 50; $i++) { + $e = new Exception('level-' . $i, 0, $e); + } + + $logger->logException($e); + + // Default cap is 10 levels: the outermost is kept, deeper roots dropped. + $this->assertStringContainsString('level-50', $logger->logged['message']); + $this->assertStringNotContainsString('level-0', $logger->logged['message']); + $this->assertSame(10, substr_count($logger->logged['message'], 'level-')); + } +}