Skip to content

Commit e08562d

Browse files
michalsnmichalsn
authored
feat: add per-call context logging with Throwable normalization (#10027)
* feat: add per-call context logging with Throwable normalization * add docs * add changelog * normalize Throwable only in the exception context key per PSR-3
1 parent 570acae commit e08562d

File tree

8 files changed

+364
-1
lines changed

8 files changed

+364
-1
lines changed

‎app/Config/Logger.php‎

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,41 @@ class Logger extends BaseConfig
6767
*/
6868
public bool $logGlobalContext = false;
6969

70+
/**
71+
* --------------------------------------------------------------------------
72+
* Whether to log per-call context data
73+
* --------------------------------------------------------------------------
74+
*
75+
* When enabled, context keys not used as placeholders in the message are
76+
* passed to handlers as structured data. Per PSR-3, any ``Throwable`` instance
77+
* in the ``exception`` key is automatically normalized to an array representation.
78+
*/
79+
public bool $logContext = false;
80+
81+
/**
82+
* --------------------------------------------------------------------------
83+
* Whether to include the stack trace for Throwables in context
84+
* --------------------------------------------------------------------------
85+
*
86+
* When enabled, the stack trace is included when normalizing a Throwable
87+
* in the ``exception`` context key. Only relevant when $logContext is true.
88+
*/
89+
public bool $logContextTrace = false;
90+
91+
/**
92+
* --------------------------------------------------------------------------
93+
* Whether to keep context keys that were used as placeholders
94+
* --------------------------------------------------------------------------
95+
*
96+
* By default, context keys that were interpolated into the message as
97+
* {placeholder} are stripped before passing context to handlers, since
98+
* their values are already present in the message text. Set to true to
99+
* keep them as structured data as well.
100+
*
101+
* Only relevant when $logContext is true.
102+
*/
103+
public bool $logContextUsedKeys = false;
104+
70105
/**
71106
* --------------------------------------------------------------------------
72107
* Log Handlers

‎system/Log/Logger.php‎

Lines changed: 76 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -121,6 +121,27 @@ class Logger implements LoggerInterface
121121
*/
122122
protected bool $logGlobalContext = false;
123123

124+
/**
125+
* Whether to log per-call context data passed to log methods.
126+
*
127+
* Set in app/Config/Logger.php
128+
*/
129+
protected bool $logContext = false;
130+
131+
/**
132+
* Whether to include the stack trace when a Throwable is in the context.
133+
*
134+
* Set in app/Config/Logger.php
135+
*/
136+
protected bool $logContextTrace = false;
137+
138+
/**
139+
* Whether to keep context keys that were already used as placeholders.
140+
*
141+
* Set in app/Config/Logger.php
142+
*/
143+
protected bool $logContextUsedKeys = false;
144+
124145
/**
125146
* Constructor.
126147
*
@@ -162,7 +183,10 @@ public function __construct($config, bool $debug = CI_DEBUG)
162183
$this->logCache = [];
163184
}
164185

165-
$this->logGlobalContext = $config->logGlobalContext ?? $this->logGlobalContext;
186+
$this->logGlobalContext = $config->logGlobalContext ?? $this->logGlobalContext;
187+
$this->logContext = $config->logContext ?? $this->logContext;
188+
$this->logContextTrace = $config->logContextTrace ?? $this->logContextTrace;
189+
$this->logContextUsedKeys = $config->logContextUsedKeys ?? $this->logContextUsedKeys;
166190
}
167191

168192
/**
@@ -259,8 +283,26 @@ public function log($level, string|Stringable $message, array $context = []): vo
259283
return;
260284
}
261285

286+
$interpolatedKeys = array_keys(array_filter(
287+
$context,
288+
static fn ($key): bool => str_contains((string) $message, '{' . $key . '}'),
289+
ARRAY_FILTER_USE_KEY,
290+
));
291+
262292
$message = $this->interpolate($message, $context);
263293

294+
if ($this->logContext) {
295+
if (! $this->logContextUsedKeys) {
296+
foreach ($interpolatedKeys as $key) {
297+
unset($context[$key]);
298+
}
299+
}
300+
301+
$context = $this->normalizeContext($context);
302+
} else {
303+
$context = [];
304+
}
305+
264306
if ($this->logGlobalContext) {
265307
$globalContext = service('context')->getAll();
266308
if ($globalContext !== []) {
@@ -290,6 +332,39 @@ public function log($level, string|Stringable $message, array $context = []): vo
290332
}
291333
}
292334

335+
/**
336+
* Normalizes context values for structured logging.
337+
* Per PSR-3, if an Exception is given to produce a stack trace, it MUST be
338+
* in a key named "exception". Only that key is converted into an array
339+
* representation.
340+
*
341+
* @param array<string, mixed> $context
342+
*
343+
* @return array<string, mixed>
344+
*/
345+
protected function normalizeContext(array $context): array
346+
{
347+
if (isset($context['exception']) && $context['exception'] instanceof Throwable) {
348+
$value = $context['exception'];
349+
350+
$normalized = [
351+
'class' => $value::class,
352+
'message' => $value->getMessage(),
353+
'code' => $value->getCode(),
354+
'file' => clean_path($value->getFile()),
355+
'line' => $value->getLine(),
356+
];
357+
358+
if ($this->logContextTrace) {
359+
$normalized['trace'] = $value->getTraceAsString();
360+
}
361+
362+
$context['exception'] = $normalized;
363+
}
364+
365+
return $context;
366+
}
367+
293368
/**
294369
* Replaces any placeholders in the message with variables
295370
* from the context, as well as a few special items like:

‎tests/system/Log/LoggerTest.php‎

Lines changed: 170 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -505,4 +505,174 @@ public function testDoesNotLogHiddenGlobalContext(): void
505505
$this->assertCount(1, $logs);
506506
$this->assertSame($expected, $logs[0]);
507507
}
508+
509+
public function testContextNotPassedToHandlersByDefault(): void
510+
{
511+
$config = new LoggerConfig();
512+
$logger = new Logger($config);
513+
514+
$logger->log('debug', 'Test message', ['foo' => 'bar', 'baz' => 'qux']);
515+
516+
$contexts = TestHandler::getContexts();
517+
518+
$this->assertSame([[]], $contexts);
519+
}
520+
521+
public function testLogContextPassesNonInterpolatedKeysToHandlers(): void
522+
{
523+
$config = new LoggerConfig();
524+
$config->logContext = true;
525+
526+
$logger = new Logger($config);
527+
528+
$logger->log('debug', 'Hello {name}', ['name' => 'World', 'user_id' => 42]);
529+
530+
$contexts = TestHandler::getContexts();
531+
532+
$this->assertArrayNotHasKey('name', $contexts[0]);
533+
$this->assertSame(42, $contexts[0]['user_id']);
534+
}
535+
536+
public function testLogContextStripsInterpolatedKeysByDefault(): void
537+
{
538+
$config = new LoggerConfig();
539+
$config->logContext = true;
540+
541+
$logger = new Logger($config);
542+
543+
$logger->log('debug', 'Hello {name}', ['name' => 'World']);
544+
545+
$contexts = TestHandler::getContexts();
546+
547+
$this->assertSame([[]], $contexts);
548+
}
549+
550+
public function testLogContextKeepsInterpolatedKeysWhenEnabled(): void
551+
{
552+
$config = new LoggerConfig();
553+
$config->logContext = true;
554+
$config->logContextUsedKeys = true;
555+
556+
$logger = new Logger($config);
557+
558+
$logger->log('debug', 'Hello {name}', ['name' => 'World']);
559+
560+
$contexts = TestHandler::getContexts();
561+
562+
$this->assertArrayHasKey('name', $contexts[0]);
563+
$this->assertSame('World', $contexts[0]['name']);
564+
}
565+
566+
public function testLogContextNormalizesThrowable(): void
567+
{
568+
$config = new LoggerConfig();
569+
$config->logContext = true;
570+
571+
$logger = new Logger($config);
572+
573+
try {
574+
throw new RuntimeException('Something went wrong', 42);
575+
} catch (RuntimeException $e) {
576+
$logger->log('error', 'An error occurred', ['exception' => $e]);
577+
}
578+
579+
$contexts = TestHandler::getContexts();
580+
581+
$this->assertArrayHasKey('exception', $contexts[0]);
582+
583+
$normalized = $contexts[0]['exception'];
584+
585+
$this->assertSame(RuntimeException::class, $normalized['class']);
586+
$this->assertSame('Something went wrong', $normalized['message']);
587+
$this->assertSame(42, $normalized['code']);
588+
$this->assertArrayHasKey('file', $normalized);
589+
$this->assertArrayHasKey('line', $normalized);
590+
$this->assertArrayNotHasKey('trace', $normalized);
591+
}
592+
593+
public function testLogContextDoesNotNormalizeThrowableUnderArbitraryKey(): void
594+
{
595+
$config = new LoggerConfig();
596+
$config->logContext = true;
597+
598+
$logger = new Logger($config);
599+
600+
try {
601+
throw new RuntimeException('Something went wrong');
602+
} catch (RuntimeException $e) {
603+
$logger->log('error', 'An error occurred', ['error' => $e]);
604+
}
605+
606+
$contexts = TestHandler::getContexts();
607+
608+
// Per PSR-3, only the 'exception' key is normalized; other keys are left as-is.
609+
$this->assertInstanceOf(RuntimeException::class, $contexts[0]['error']);
610+
}
611+
612+
public function testLogContextNormalizesThrowableWithTrace(): void
613+
{
614+
$config = new LoggerConfig();
615+
$config->logContext = true;
616+
$config->logContextTrace = true;
617+
618+
$logger = new Logger($config);
619+
620+
try {
621+
throw new RuntimeException('Something went wrong');
622+
} catch (RuntimeException $e) {
623+
$logger->log('error', 'An error occurred', ['exception' => $e]);
624+
}
625+
626+
$contexts = TestHandler::getContexts();
627+
628+
$this->assertArrayHasKey('exception', $contexts[0]);
629+
$this->assertArrayHasKey('trace', $contexts[0]['exception']);
630+
$this->assertIsString($contexts[0]['exception']['trace']);
631+
}
632+
633+
public function testLogContextNormalizesInterpolatedThrowableWhenUsedKeysEnabled(): void
634+
{
635+
$config = new LoggerConfig();
636+
$config->logContext = true;
637+
$config->logContextUsedKeys = true;
638+
639+
$logger = new Logger($config);
640+
641+
try {
642+
throw new RuntimeException('Something went wrong');
643+
} catch (RuntimeException $e) {
644+
$logger->log('error', '[ERROR] {exception}', ['exception' => $e]);
645+
}
646+
647+
$contexts = TestHandler::getContexts();
648+
649+
$this->assertArrayHasKey('exception', $contexts[0]);
650+
651+
$normalized = $contexts[0]['exception'];
652+
653+
$this->assertIsArray($normalized);
654+
$this->assertSame(RuntimeException::class, $normalized['class']);
655+
$this->assertSame('Something went wrong', $normalized['message']);
656+
}
657+
658+
public function testLogContextDisabledStillAllowsGlobalContext(): void
659+
{
660+
$config = new LoggerConfig();
661+
$config->logContext = false;
662+
$config->logGlobalContext = true;
663+
664+
$logger = new Logger($config);
665+
666+
Time::setTestNow('2026-02-18 12:00:00');
667+
668+
service('context')->set('request_id', 'abc123');
669+
670+
$logger->log('debug', 'Test message', ['extra' => 'data']);
671+
672+
$contexts = TestHandler::getContexts();
673+
674+
$this->assertArrayNotHasKey('extra', $contexts[0]);
675+
$this->assertArrayHasKey('_ci_context', $contexts[0]);
676+
$this->assertSame(['request_id' => 'abc123'], $contexts[0]['_ci_context']);
677+
}
508678
}

‎user_guide_src/source/changelogs/v4.8.0.rst‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -176,6 +176,7 @@ Libraries
176176

177177
- **Context**: This new feature allows you to easily set and retrieve normal or hidden contextual data for the current request. See :ref:`Context <context>` for details.
178178
- **Logging:** Log handlers now receive the full context array as a third argument to ``handle()``. When ``$logGlobalContext`` is enabled, the CI global context is available under the ``HandlerInterface::GLOBAL_CONTEXT_KEY`` key. Built-in handlers append it to the log output; custom handlers can use it for structured logging.
179+
- **Logging:** Added :ref:`per-call context logging <logging-per-call-context>` with three new ``Config\Logger`` options (``$logContext``, ``$logContextTrace``, ``$logContextUsedKeys``). Per PSR-3, a ``Throwable`` in the ``exception`` context key is automatically normalized to a meaningful array. All options default to ``false``.
179180

180181
Helpers and Functions
181182
=====================

‎user_guide_src/source/general/logging.rst‎

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -147,6 +147,41 @@ This would produce a log entry like:
147147

148148
See :ref:`context` for full documentation on storing and managing context data.
149149

150+
.. _logging-per-call-context:
151+
152+
Per-Call Context Logging
153+
------------------------
154+
155+
.. versionadded:: 4.8.0
156+
157+
By default, context values passed to ``log_message()`` are only used for placeholder
158+
interpolation and are not stored anywhere. You can enable structured context logging
159+
by setting ``$logContext = true`` in **app/Config/Logger.php**:
160+
161+
.. literalinclude:: logging/009.php
162+
163+
When enabled, any context key that is **not** referenced as a ``{placeholder}`` in the
164+
message is passed to handlers as structured data. Keys that were interpolated into the
165+
message are stripped by default (since their values are already present in the message
166+
text), but you can keep them by setting ``$logContextUsedKeys = true``.
167+
168+
.. literalinclude:: logging/007.php
169+
170+
**Throwable normalization**
171+
172+
Per PSR-3, a ``Throwable`` instance must be passed under the ``exception`` key to be
173+
handled specially. When found there, it is automatically normalized into a meaningful
174+
array instead of being serialized as an empty object:
175+
176+
.. literalinclude:: logging/008.php
177+
178+
The normalized array contains ``class``, ``message``, ``code``, ``file``, and ``line``.
179+
To also include the full stack trace, set ``$logContextTrace = true``.
180+
181+
.. note:: ``$logContext`` and ``$logGlobalContext`` are independent. You can enable either
182+
or both. When both are enabled, per-call context and global context are merged before
183+
being passed to handlers.
184+
150185
Using Third-Party Loggers
151186
=========================
152187

‎user_guide_src/source/general/logging/007.php‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
<?php
2+
3+
// With $logContext = true in Config\Logger.
4+
// 'user_id' is not used as a placeholder, so it is passed to handlers as structured data.
5+
log_message('error', 'Payment failed for order {order_id}', [
6+
'order_id' => 'ord_999', // interpolated into the message, stripped from context by default
7+
'user_id' => 42, // not in message, kept and passed to handlers
8+
]);
9+
10+
// Handlers receive context: ['user_id' => 42]

0 commit comments

Comments
 (0)