Skip to content

Commit e663b1e

Browse files
michalsnJulianAtkins
michalsn
authored and
JulianAtkins
committed
feat: pass log context as structured data to handlers instead of appending to message (#10017)
1 parent 67f9b9b commit e663b1e

File tree

14 files changed

+221
-24
lines changed

14 files changed

+221
-24
lines changed

‎system/Log/Handlers/BaseHandler.php‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,8 @@
1313

1414
namespace CodeIgniter\Log\Handlers;
1515

16+
use JsonException;
17+
1618
/**
1719
* Base class for logging
1820
*/
@@ -58,4 +60,20 @@ public function setDateFormat(string $format): HandlerInterface
5860

5961
return $this;
6062
}
63+
64+
/**
65+
* Encodes the context array as a JSON string.
66+
* Returns the JSON string on success, or a descriptive error string if
67+
* encoding fails (e.g. context contains a resource or invalid UTF-8).
68+
*
69+
* @param array<string, mixed> $context
70+
*/
71+
protected function encodeContext(array $context): string
72+
{
73+
try {
74+
return json_encode($context, JSON_UNESCAPED_UNICODE | JSON_THROW_ON_ERROR);
75+
} catch (JsonException $e) {
76+
return '[context: JSON encoding failed - ' . $e->getMessage() . ']';
77+
}
78+
}
6179
}

‎system/Log/Handlers/ChromeLoggerHandler.php‎

Lines changed: 18 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@
1414
namespace CodeIgniter\Log\Handlers;
1515

1616
use CodeIgniter\HTTP\ResponseInterface;
17+
use JsonException;
1718

1819
/**
1920
* Allows for logging items to the Chrome console for debugging.
@@ -99,10 +100,11 @@ public function __construct(array $config = [])
99100
* will stop. Any handlers that have not run, yet, will not
100101
* be run.
101102
*
102-
* @param string $level
103-
* @param string $message
103+
* @param string $level
104+
* @param string $message
105+
* @param array<string, mixed> $context
104106
*/
105-
public function handle($level, $message): bool
107+
public function handle($level, $message, array $context = []): bool
106108
{
107109
$message = $this->format($message);
108110

@@ -121,7 +123,9 @@ public function handle($level, $message): bool
121123
$type = $this->levels[$level];
122124
}
123125

124-
$this->json['rows'][] = [[$message], $backtraceMessage, $type];
126+
$logArgs = $context !== [] ? [$message, $context] : [$message];
127+
128+
$this->json['rows'][] = [$logArgs, $backtraceMessage, $type];
125129

126130
$this->sendLogs();
127131

@@ -162,8 +166,17 @@ public function sendLogs(?ResponseInterface &$response = null)
162166
$response = service('response', null, true);
163167
}
164168

169+
try {
170+
$encoded = json_encode($this->json, JSON_THROW_ON_ERROR);
171+
} catch (JsonException) {
172+
$encoded = json_encode($this->json, JSON_PARTIAL_OUTPUT_ON_ERROR);
173+
if ($encoded === false) {
174+
return;
175+
}
176+
}
177+
165178
$data = base64_encode(
166-
mb_convert_encoding(json_encode($this->json), 'UTF-8', mb_list_encodings()),
179+
mb_convert_encoding($encoded, 'UTF-8', mb_list_encodings()),
167180
);
168181

169182
$response->setHeader($this->header, $data);

‎system/Log/Handlers/ErrorlogHandler.php‎

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -66,11 +66,16 @@ public function __construct(array $config = [])
6666
* will stop. Any handlers that have not run, yet, will not
6767
* be run.
6868
*
69-
* @param string $level
70-
* @param string $message
69+
* @param string $level
70+
* @param string $message
71+
* @param array<string, mixed> $context
7172
*/
72-
public function handle($level, $message): bool
73+
public function handle($level, $message, array $context = []): bool
7374
{
75+
if ($context !== []) {
76+
$message .= ' ' . $this->encodeContext($context);
77+
}
78+
7479
$message = strtoupper($level) . ' --> ' . $message . "\n";
7580

7681
return $this->errorLog($message, $this->messageType);

‎system/Log/Handlers/FileHandler.php‎

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -69,12 +69,13 @@ public function __construct(array $config = [])
6969
* will stop. Any handlers that have not run, yet, will not
7070
* be run.
7171
*
72-
* @param string $level
73-
* @param string $message
72+
* @param string $level
73+
* @param string $message
74+
* @param array<string, mixed> $context
7475
*
7576
* @throws Exception
7677
*/
77-
public function handle($level, $message): bool
78+
public function handle($level, $message, array $context = []): bool
7879
{
7980
$filepath = $this->path . 'log-' . date('Y-m-d') . '.' . $this->fileExtension;
8081

@@ -104,6 +105,10 @@ public function handle($level, $message): bool
104105
$date = date($this->dateFormat);
105106
}
106107

108+
if ($context !== []) {
109+
$message .= ' ' . $this->encodeContext($context);
110+
}
111+
107112
$msg .= strtoupper($level) . ' - ' . $date . ' --> ' . $message . "\n";
108113

109114
flock($fp, LOCK_EX);

‎system/Log/Handlers/HandlerInterface.php‎

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -18,16 +18,25 @@
1818
*/
1919
interface HandlerInterface
2020
{
21+
/**
22+
* The reserved key under which global CI context data is stored
23+
* in the log context array. This data comes from the Context service
24+
* and is injected by the Logger when $logGlobalContext is enabled.
25+
*/
26+
public const GLOBAL_CONTEXT_KEY = '_ci_context';
27+
2128
/**
2229
* Handles logging the message.
2330
* If the handler returns false, then execution of handlers
2431
* will stop. Any handlers that have not run, yet, will not
2532
* be run.
2633
*
27-
* @param string $level
28-
* @param string $message
34+
* @param string $level
35+
* @param string $message
36+
* @param array<string, mixed> $context Full context array; may contain
37+
* GLOBAL_CONTEXT_KEY with CI global data
2938
*/
30-
public function handle($level, $message): bool;
39+
public function handle($level, $message, array $context = []): bool;
3140

3241
/**
3342
* Checks whether the Handler will handle logging items of this

‎system/Log/Logger.php‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -264,7 +264,7 @@ public function log($level, string|Stringable $message, array $context = []): vo
264264
if ($this->logGlobalContext) {
265265
$globalContext = service('context')->getAll();
266266
if ($globalContext !== []) {
267-
$message .= ' ' . json_encode($globalContext);
267+
$context[HandlerInterface::GLOBAL_CONTEXT_KEY] = $globalContext;
268268
}
269269
}
270270

@@ -284,7 +284,7 @@ public function log($level, string|Stringable $message, array $context = []): vo
284284
}
285285

286286
// If the handler returns false, then we don't execute any other handlers.
287-
if (! $handler->setDateFormat($this->dateFormat)->handle($level, $message)) {
287+
if (! $handler->setDateFormat($this->dateFormat)->handle($level, $message, $context)) {
288288
break;
289289
}
290290
}

‎tests/_support/Log/Handlers/TestHandler.php‎

Lines changed: 23 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,13 @@ class TestHandler extends FileHandler
3131
*/
3232
protected static $logs = [];
3333

34+
/**
35+
* Local storage for log contexts.
36+
*
37+
* @var array<int, array<string, mixed>>
38+
*/
39+
protected static array $contexts = [];
40+
3441
protected string $destination;
3542

3643
/**
@@ -45,7 +52,8 @@ public function __construct(array $config)
4552
$this->handles = $config['handles'] ?? [];
4653
$this->destination = $this->path . 'log-' . Time::now()->format('Y-m-d') . '.' . $this->fileExtension;
4754

48-
self::$logs = [];
55+
self::$logs = [];
56+
self::$contexts = [];
4957
}
5058

5159
/**
@@ -54,14 +62,16 @@ public function __construct(array $config)
5462
* will stop. Any handlers that have not run, yet, will not
5563
* be run.
5664
*
57-
* @param string $level
58-
* @param string $message
65+
* @param string $level
66+
* @param string $message
67+
* @param array<string, mixed> $context
5968
*/
60-
public function handle($level, $message): bool
69+
public function handle($level, $message, array $context = []): bool
6170
{
6271
$date = Time::now()->format($this->dateFormat);
6372

64-
self::$logs[] = strtoupper($level) . ' - ' . $date . ' --> ' . $message;
73+
self::$logs[] = strtoupper($level) . ' - ' . $date . ' --> ' . $message;
74+
self::$contexts[] = $context;
6575

6676
return true;
6777
}
@@ -70,4 +80,12 @@ public static function getLogs()
7080
{
7181
return self::$logs;
7282
}
83+
84+
/**
85+
* @return array<int, array<string, mixed>>
86+
*/
87+
public static function getContexts(): array
88+
{
89+
return self::$contexts;
90+
}
7391
}

‎tests/system/Log/Handlers/ChromeLoggerHandlerTest.php‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -74,6 +74,26 @@ public function testSetDateFormat(): void
7474
$this->assertSame('F j, Y', $this->getPrivateProperty($logger, 'dateFormat'));
7575
}
7676

77+
public function testHandleIncludesContextInRow(): void
78+
{
79+
Services::injectMock('response', new MockResponse());
80+
$response = service('response');
81+
82+
$config = new LoggerConfig();
83+
$config->handlers['CodeIgniter\Log\Handlers\TestHandler']['handles'] = ['debug'];
84+
85+
$logger = new ChromeLoggerHandler($config->handlers['CodeIgniter\Log\Handlers\TestHandler']);
86+
$logger->handle('debug', 'Test message', [HandlerInterface::GLOBAL_CONTEXT_KEY => ['foo' => 'bar']]);
87+
88+
$this->assertTrue($response->hasHeader('X-ChromeLogger-Data'));
89+
90+
$decoded = json_decode(base64_decode($response->getHeaderLine('X-ChromeLogger-Data'), true), true);
91+
$logArgs = $decoded['rows'][0][0];
92+
93+
$this->assertSame('Test message', $logArgs[0]);
94+
$this->assertSame([HandlerInterface::GLOBAL_CONTEXT_KEY => ['foo' => 'bar']], $logArgs[1]);
95+
}
96+
7797
public function testChromeLoggerHeaderSent(): void
7898
{
7999
Services::injectMock('response', new MockResponse());

‎tests/system/Log/Handlers/ErrorlogHandlerTest.php‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,15 @@ public function testErrorLoggingWithErrorLog(): void
3838
$this->assertTrue($logger->handle('error', 'Test message.'));
3939
}
4040

41+
public function testErrorLoggingAppendsContextAsJson(): void
42+
{
43+
$logger = $this->getMockedHandler(['handles' => ['critical', 'error']]);
44+
$logger->method('errorLog')->willReturn(true);
45+
$logger->expects($this->once())->method('errorLog')
46+
->with("ERROR --> Test message. {\"_ci_context\":{\"foo\":\"bar\"}}\n", 0);
47+
$this->assertTrue($logger->handle('error', 'Test message.', [HandlerInterface::GLOBAL_CONTEXT_KEY => ['foo' => 'bar']]));
48+
}
49+
4150
/**
4251
* @param array{handles?: list<string>, messageType?: int} $config
4352
*

‎tests/system/Log/Handlers/FileHandlerTest.php‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -79,6 +79,24 @@ public function testHandleCreateFile(): void
7979
$this->assertStringContainsString($expectedResult, (string) $line);
8080
}
8181

82+
public function testHandleAppendsContextAsJson(): void
83+
{
84+
$config = new LoggerConfig();
85+
$config->handlers[TestHandler::class]['path'] = $this->start;
86+
$logger = new MockFileLogger($config->handlers[TestHandler::class]);
87+
88+
$logger->setDateFormat('Y-m-d');
89+
$expected = 'log-' . date('Y-m-d') . '.log';
90+
vfsStream::newFile($expected)->at(vfsStream::setup('root'))->withContent('');
91+
$logger->handle('debug', 'Test message', [HandlerInterface::GLOBAL_CONTEXT_KEY => ['foo' => 'bar']]);
92+
93+
$fp = fopen($config->handlers[TestHandler::class]['path'] . $expected, 'rb');
94+
$line = fgets($fp);
95+
fclose($fp);
96+
97+
$this->assertStringContainsString('Test message {"_ci_context":{"foo":"bar"}}', (string) $line);
98+
}
99+
82100
public function testHandleDateTimeCorrectly(): void
83101
{
84102
$config = new LoggerConfig();

0 commit comments

Comments
 (0)