From f82e8d66e3ace218d968be05913c083ccc5d5018 Mon Sep 17 00:00:00 2001 From: michalsn Date: Tue, 7 Jul 2026 16:00:41 +0200 Subject: [PATCH 1/2] fix: safely interpolate logger context values --- system/Log/Logger.php | 57 ++++++- tests/system/Log/LoggerTest.php | 158 ++++++++++++++++++++ user_guide_src/source/changelogs/v4.7.5.rst | 2 + 3 files changed, 212 insertions(+), 5 deletions(-) diff --git a/system/Log/Logger.php b/system/Log/Logger.php index 011920e15bd1..323f46b6e660 100644 --- a/system/Log/Logger.php +++ b/system/Log/Logger.php @@ -13,6 +13,7 @@ namespace CodeIgniter\Log; +use CodeIgniter\Entity\Entity; use CodeIgniter\Exceptions\RuntimeException; use CodeIgniter\Log\Exceptions\LogException; use CodeIgniter\Log\Handlers\HandlerInterface; @@ -298,14 +299,14 @@ protected function interpolate($message, array $context = []) $replace = []; foreach ($context as $key => $val) { - // Verify that the 'exception' key is actually an exception - // or error, both of which implement the 'Throwable' interface. - if ($key === 'exception' && $val instanceof Throwable) { - $val = $val->getMessage() . ' ' . clean_path($val->getFile()) . ':' . $val->getLine(); + $placeholder = '{' . $key . '}'; + + if (! str_contains($message, $placeholder)) { + continue; } // todo - sanitize input before writing to file? - $replace['{' . $key . '}'] = $val; + $replace[$placeholder] = $this->stringifyContextValue($key, $val); } $replace['{post_vars}'] = '$_POST: ' . print_r(service('superglobals')->getPostArray(), true); @@ -337,6 +338,52 @@ protected function interpolate($message, array $context = []) return strtr($message, $replace); } + /** + * Converts context values to strings without raising PHP errors. + */ + protected function stringifyContextValue(int|string $key, mixed $value): string + { + // Verify that the 'exception' key is actually an exception + // or error, both of which implement the 'Throwable' interface. + if ($key === 'exception' && $value instanceof Throwable) { + return $value->getMessage() . ' ' . clean_path($value->getFile()) . ':' . $value->getLine(); + } + + if ($value === null || is_scalar($value)) { + return (string) $value; + } + + if ($value instanceof Stringable) { + try { + return (string) $value; + } catch (Throwable) { + return '[object ' . $value::class . ']'; + } + } + + if (is_array($value)) { + return print_r($value, true); + } + + if ($value instanceof Entity) { + try { + return print_r($value->toArray(), true); + } catch (Throwable) { + return '[object ' . $value::class . ']'; + } + } + + if (is_object($value)) { + return '[object ' . $value::class . ']'; + } + + if (is_resource($value)) { + return '[resource ' . get_resource_type($value) . ']'; + } + + return '[' . gettype($value) . ']'; + } + /** * Determines the file and line that the logging call * was made from by analyzing the backtrace. diff --git a/tests/system/Log/LoggerTest.php b/tests/system/Log/LoggerTest.php index 80d42d6c83b3..5301b29e497a 100644 --- a/tests/system/Log/LoggerTest.php +++ b/tests/system/Log/LoggerTest.php @@ -13,6 +13,7 @@ namespace CodeIgniter\Log; +use CodeIgniter\Entity\Entity; use CodeIgniter\Exceptions\FrameworkException; use CodeIgniter\Exceptions\RuntimeException; use CodeIgniter\I18n\Time; @@ -22,6 +23,8 @@ use PHPUnit\Framework\Attributes\Group; use ReflectionMethod; use ReflectionNamedType; +use stdClass; +use Stringable; use Tests\Support\Log\Handlers\TestHandler; /** @@ -123,6 +126,161 @@ public function testLogInterpolatesMessage(): void $this->assertSame($expected, $logs[0]); } + public function testLogInterpolatesArrayContextValue(): void + { + $config = new LoggerConfig(); + $logger = new Logger($config); + + Time::setTestNow('2023-11-25 12:00:00'); + + $payload = ['id' => 123, 'status' => 'created']; + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message ' . print_r($payload, true); + + $logger->log('debug', 'Test message {payload}', ['payload' => $payload]); + + $logs = TestHandler::getLogs(); + + $this->assertCount(1, $logs); + $this->assertSame($expected, $logs[0]); + } + + public function testLogInterpolatesOnlyExactDottedContextKey(): void + { + $config = new LoggerConfig(); + $logger = new Logger($config); + + Time::setTestNow('2023-11-25 12:00:00'); + + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message literal'; + + $logger->log('debug', 'Test message {foo.bar}', [ + 'foo.bar' => 'literal', + 'foo' => ['bar' => 'nested'], + ]); + + $logs = TestHandler::getLogs(); + + $this->assertCount(1, $logs); + $this->assertSame($expected, $logs[0]); + } + + public function testLogIgnoresUnusedArrayContextValueDuringInterpolation(): void + { + $config = new LoggerConfig(); + $logger = new Logger($config); + + Time::setTestNow('2023-11-25 12:00:00'); + + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message value'; + + $logger->log('debug', 'Test message {name}', [ + 'name' => 'value', + 'payload' => ['id' => 123], + ]); + + $logs = TestHandler::getLogs(); + + $this->assertCount(1, $logs); + $this->assertSame($expected, $logs[0]); + } + + public function testLogInterpolatesStringableContextValue(): void + { + $config = new LoggerConfig(); + $logger = new Logger($config); + + Time::setTestNow('2023-11-25 12:00:00'); + + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message stringable'; + + $logger->log('debug', 'Test message {value}', [ + 'value' => new class () implements Stringable { + public function __toString(): string + { + return 'stringable'; + } + }, + ]); + + $logs = TestHandler::getLogs(); + + $this->assertCount(1, $logs); + $this->assertSame($expected, $logs[0]); + } + + public function testLogInterpolatesTimeContextValue(): void + { + $config = new LoggerConfig(); + $logger = new Logger($config); + + Time::setTestNow('2023-11-25 12:00:00'); + + $time = Time::parse('2024-01-02 03:04:05', 'UTC'); + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message 2024-01-02 03:04:05'; + + $logger->log('debug', 'Test message {time}', ['time' => $time]); + + $logs = TestHandler::getLogs(); + + $this->assertCount(1, $logs); + $this->assertSame($expected, $logs[0]); + } + + public function testLogInterpolatesNonStringableObjectContextValue(): void + { + $config = new LoggerConfig(); + $logger = new Logger($config); + + Time::setTestNow('2023-11-25 12:00:00'); + + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message [object stdClass]'; + + $logger->log('debug', 'Test message {value}', ['value' => new stdClass()]); + + $logs = TestHandler::getLogs(); + + $this->assertCount(1, $logs); + $this->assertSame($expected, $logs[0]); + } + + public function testLogInterpolatesResourceContextValue(): void + { + $config = new LoggerConfig(); + $logger = new Logger($config); + + Time::setTestNow('2023-11-25 12:00:00'); + + $resource = fopen('php://memory', 'rb'); + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message [resource stream]'; + + $logger->log('debug', 'Test message {value}', ['value' => $resource]); + + fclose($resource); + + $logs = TestHandler::getLogs(); + + $this->assertCount(1, $logs); + $this->assertSame($expected, $logs[0]); + } + + public function testLogInterpolatesEntityContextValue(): void + { + $config = new LoggerConfig(); + $logger = new Logger($config); + + Time::setTestNow('2023-11-25 12:00:00'); + + $entity = new Entity(['id' => 123, 'name' => 'Ada']); + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message ' . print_r($entity->toArray(), true); + + $logger->log('debug', 'Test message {entity}', ['entity' => $entity]); + + $logs = TestHandler::getLogs(); + + $this->assertCount(1, $logs); + $this->assertSame($expected, $logs[0]); + } + public function testLogInterpolatesPost(): void { $config = new LoggerConfig(); diff --git a/user_guide_src/source/changelogs/v4.7.5.rst b/user_guide_src/source/changelogs/v4.7.5.rst index e379b7b0cfd1..c4bb7900e07a 100644 --- a/user_guide_src/source/changelogs/v4.7.5.rst +++ b/user_guide_src/source/changelogs/v4.7.5.rst @@ -30,6 +30,8 @@ Deprecations Bugs Fixed ********** +- **Logger:** Fixed a bug where interpolating a log message with array or non-stringable context values could raise PHP warnings or errors. + See the repo's `CHANGELOG.md `_ for a complete list of bugs fixed. From dcffcccdcefbed54d5f9f556e932c7590be616a6 Mon Sep 17 00:00:00 2001 From: michalsn Date: Tue, 7 Jul 2026 16:32:00 +0200 Subject: [PATCH 2/2] apply code suggestion Co-authored-by: John Paul E Balandan --- system/Log/Logger.php | 6 +----- tests/system/Log/LoggerTest.php | 2 +- 2 files changed, 2 insertions(+), 6 deletions(-) diff --git a/system/Log/Logger.php b/system/Log/Logger.php index 323f46b6e660..6b61837fa22b 100644 --- a/system/Log/Logger.php +++ b/system/Log/Logger.php @@ -377,11 +377,7 @@ protected function stringifyContextValue(int|string $key, mixed $value): string return '[object ' . $value::class . ']'; } - if (is_resource($value)) { - return '[resource ' . get_resource_type($value) . ']'; - } - - return '[' . gettype($value) . ']'; + return '[' . get_debug_type($value) . ']'; } /** diff --git a/tests/system/Log/LoggerTest.php b/tests/system/Log/LoggerTest.php index 5301b29e497a..bbdf304acf8c 100644 --- a/tests/system/Log/LoggerTest.php +++ b/tests/system/Log/LoggerTest.php @@ -251,7 +251,7 @@ public function testLogInterpolatesResourceContextValue(): void Time::setTestNow('2023-11-25 12:00:00'); $resource = fopen('php://memory', 'rb'); - $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message [resource stream]'; + $expected = 'DEBUG - ' . Time::now()->format('Y-m-d') . ' --> Test message [resource (stream)]'; $logger->log('debug', 'Test message {value}', ['value' => $resource]);