Skip to content

Commit 7d84cd7

Browse files
committed
Keep each log entry of the module on one line
LoggerService wrote the message as given and the context with var_export(), which keeps line breaks, and SimpleSAMLphp's logger writes what it is given. So a value sent in a request could add lines of its own to the OP's log, at levels the shipped configuration writes. It takes only a client ID and a redirect URI: ScopeRule logs ignored scope values at notice even for a request it accepts, CodeChallengeMethodRule and ClientRedirectUriRule log what they refuse, and ErrorResponder logs a hint which can quote the request. 32f5929 closed this on the client authentication path only. Fix it in LoggerService, which the openid library logs through too, and every line of the module except three in the cron hook, which hold exception messages from its own steps. The context is now one line of JSON, which keeps a line break in a value as its escape, and control characters, format characters such as bidirectional overrides, and the line and paragraph separators left in the line give way to a space. A line which is not valid UTF-8 keeps printable ASCII only. An object in the context is written as var_export() writes it, as text in the JSON. JSON would write the Result and response mode objects which AuthCodeGrant logs as {}, and would run jsonSerialize(). The log format changes, so the upgrade guide says so. The resolver's forLog() stays, for its 1,000-byte bound. Assisted-by: Claude Code (claude-opus-5-5, implementation & unit tests) Assisted-by: OpenAI Codex (gpt-6.1-sol, xhigh review) Assisted-by: Google Antigravity (gemini-3.8-flash-high, review)
1 parent 32f5929 commit 7d84cd7

4 files changed

Lines changed: 375 additions & 16 deletions

File tree

‎docs/6-oidc-upgrade.md‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -411,6 +411,13 @@ attribute, clients relying on the previously inconsistent value may see a
411411
changed `sub` in flows where the claims were not released.
412412
- Logging has been improved for authentication flows. It should now be easier
413413
to find information about what went wrong by looking at the relevant log entries.
414+
- Each log entry of the module now stays on one line, so that a value sent in a
415+
request can not add lines of its own to the log. The context of an entry is
416+
no longer written in the multi-line `var_export()` format, but as JSON, which
417+
keeps line breaks in its values as escapes. Anything left which could break the
418+
line or disguise the text (control characters, format characters such as
419+
bidirectional overrides) is replaced with a space. If you parse these log
420+
entries, adjust your parser.
414421

415422
New configuration options:
416423

‎src/Services/LoggerService.php‎

Lines changed: 58 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -12,51 +12,71 @@
1212

1313
class LoggerService implements LoggerInterface
1414
{
15+
/**
16+
* What a line of the log may not hold: control characters, among them the C0 line breaks and U+0085, format
17+
* characters, among them the bidirectional overrides which make text read in another order, and the line and
18+
* paragraph separators. A run of them gives way to one space.
19+
*/
20+
protected const string NOT_IN_A_LOG_LINE = '/[\p{Cc}\p{Cf}\p{Zl}\p{Zp}]+/u';
21+
22+
/**
23+
* The same for a line which is not valid UTF-8, which the pattern above can not read: only printable ASCII stays.
24+
*/
25+
protected const string NOT_IN_A_LOG_LINE_WHICH_IS_NOT_UTF8 = '/[^\x20-\x7E]+/';
26+
27+
/**
28+
* Text stays readable, and a context which can not be encoded in full is written as far as it can be: a value of
29+
* another kind should not cost the whole log entry.
30+
*/
31+
protected const int CONTEXT_ENCODING = JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE |
32+
JSON_INVALID_UTF8_SUBSTITUTE | JSON_PARTIAL_OUTPUT_ON_ERROR;
33+
34+
1535
public function emergency(string|Stringable $message, array $context = []): void
1636
{
17-
Logger::emergency((string)$message . ($context ? " " . var_export($context, true) : ""));
37+
Logger::emergency($this->asOneLine($message, $context));
1838
}
1939

2040

2141
public function alert(string|Stringable $message, array $context = []): void
2242
{
23-
Logger::alert((string)$message . ($context ? " " . var_export($context, true) : ""));
43+
Logger::alert($this->asOneLine($message, $context));
2444
}
2545

2646

2747
public function critical(string|Stringable $message, array $context = []): void
2848
{
29-
Logger::critical((string)$message . ($context ? " " . var_export($context, true) : ""));
49+
Logger::critical($this->asOneLine($message, $context));
3050
}
3151

3252

3353
public function error(string|Stringable $message, array $context = []): void
3454
{
35-
Logger::error((string)$message . ($context ? " " . var_export($context, true) : ""));
55+
Logger::error($this->asOneLine($message, $context));
3656
}
3757

3858

3959
public function warning(string|Stringable $message, array $context = []): void
4060
{
41-
Logger::warning((string)$message . ($context ? " " . var_export($context, true) : ""));
61+
Logger::warning($this->asOneLine($message, $context));
4262
}
4363

4464

4565
public function notice(string|Stringable $message, array $context = []): void
4666
{
47-
Logger::notice((string)$message . ($context ? " " . var_export($context, true) : ""));
67+
Logger::notice($this->asOneLine($message, $context));
4868
}
4969

5070

5171
public function info(string|Stringable $message, array $context = []): void
5272
{
53-
Logger::info((string)$message . ($context ? " " . var_export($context, true) : ""));
73+
Logger::info($this->asOneLine($message, $context));
5474
}
5575

5676

5777
public function debug(string|Stringable $message, array $context = []): void
5878
{
59-
Logger::debug((string)$message . ($context ? " " . var_export($context, true) : ""));
79+
Logger::debug($this->asOneLine($message, $context));
6080
}
6181

6282

@@ -80,4 +100,34 @@ public static function getInstance(): self
80100
{
81101
return new self();
82102
}
103+
104+
105+
/**
106+
* A message and its context as the one line they are written on. Both often hold what a request sent, whether or
107+
* not the request goes on to be accepted, and SimpleSAMLphp's logger writes what it is given, so a line break in
108+
* such a value would let the sender add lines of their own to the log. The context is JSON, which writes C0
109+
* control characters, U+2028 and U+2029 as escapes, so a value holding those can still be read, and what is left
110+
* of the disallowed characters gives way to a space.
111+
*
112+
* An object in the context is written as var_export() writes it, as text in the JSON: with its private properties
113+
* and without running any of its code, where JSON would show its public properties only, or whatever its
114+
* jsonSerialize() answers or throws.
115+
*/
116+
protected function asOneLine(string|Stringable $message, array $context): string
117+
{
118+
$line = (string)$message;
119+
120+
if ($context !== []) {
121+
array_walk_recursive($context, static function (mixed &$value): void {
122+
if (is_object($value)) {
123+
$value = var_export($value, true);
124+
}
125+
});
126+
127+
$line .= ' ' . (string)json_encode($context, self::CONTEXT_ENCODING);
128+
}
129+
130+
return preg_replace(self::NOT_IN_A_LOG_LINE, ' ', $line) ??
131+
(string)preg_replace(self::NOT_IN_A_LOG_LINE_WHICH_IS_NOT_UTF8, ' ', $line);
132+
}
83133
}

‎tests/integration/src/Flows/ConfidentialClientTokenEndpointTest.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -440,7 +440,7 @@ protected function tokenRequest(array $params): ServerRequest
440440
/**
441441
* The reason for the refusal is in the log, and what it quotes did not get a line of its own: every entry holding
442442
* the text is short, has it joined to what came before it, and has no line break or other control character ahead
443-
* of it. The entry may have line breaks after it, as LoggerService writes the context there with var_export().
443+
* of it.
444444
*/
445445
protected function assertForgedLineLoggedAsPartOfTheReason(string $expectedQuote): void
446446
{

0 commit comments

Comments
 (0)