From d3bb3d2a855766a2f0bc24da64f7cc504791257f Mon Sep 17 00:00:00 2001 From: Mohey Elbaz Date: Wed, 9 Sep 2026 19:38:39 +0300 Subject: [PATCH] Don't fail the whole request on an unparseable entry LaravelLog::parseText() read $matches[1] straight after preg_match without checking whether it matched. A chunk that isn't a Laravel entry, such as a run of null bytes from a partial write, left $matches empty, and Laravel turned the undefined key into an ErrorException. The logs API then returned a 500 for the whole file instead of for the one bad entry. Two ways in, not one. regexPattern() is stricter than the static::$regex the indexer used to accept the entry, so a millisecond precision timestamp or anything printed before the '[' also lands here. And the pattern accepts any two digits for month, day and hour, so '[2022-13-45 11:16:17]' matches and then Carbon::parse() throws instead. Both now fall back to $regex and keep the datetime, level and environment it finds. Only content matching neither is marked unparseable, with no severity and the printable part of its first line as the message. The fallback works from the same 1000-char chunk the strict branch matches against, since the remainder is appended back further down; passing the whole first line would write its tail twice. Returning into the shared code path also keeps the maxLogSize() cap and the first-line message. Control bytes are stripped as \p{Cc} rather than \p{C}, so bidi marks and zero-width joiners survive - dropping those reorders mixed Arabic and Latin lines and breaks emoji sequences. --- src/Logs/LaravelLog.php | 98 +++++++++++++++++++--- tests/Unit/LaravelLogs/LaravelLogsTest.php | 82 ++++++++++++++++++ 2 files changed, 168 insertions(+), 12 deletions(-) diff --git a/src/Logs/LaravelLog.php b/src/Logs/LaravelLog.php index f95ca22c..571dfff8 100644 --- a/src/Logs/LaravelLog.php +++ b/src/Logs/LaravelLog.php @@ -36,25 +36,45 @@ protected function parseText(array &$matches = []): void // so in order to properly match, we must have a smaller first line... $firstLineSplit = mb_str_split($firstLine, 1000); - preg_match(static::regexPattern(), array_shift($firstLineSplit), $matches); + // Only this first chunk is matched against, and the rest is appended back + // further down, so every path below must work from the chunk rather than + // from $firstLine - otherwise the tail past 1000 chars is written twice. + $firstChunk = array_shift($firstLineSplit) ?? ''; + + $firstLineText = null; + + if (preg_match(static::regexPattern(), $firstChunk, $matches) === 1) { + // The pattern accepts any two digits for month, day and hour, so a + // malformed timestamp reaches Carbon and throws. That crash is the + // one this guard exists to prevent, so fall back rather than fail. + try { + $this->datetime = Carbon::parse($matches[1])?->setTimezone(LogViewer::timezone()); + } catch (\Exception) { + $this->datetime = null; + } - $this->datetime = Carbon::parse($matches[1])?->setTimezone(LogViewer::timezone()); + if (! is_null($this->datetime)) { + // $matches[2] contains microseconds, which is already handled + // $matches[3] contains timezone offset, which is already handled - // $matches[2] contains microseconds, which is already handled - // $matches[3] contains timezone offset, which is already handled + $this->extra['environment'] = $matches[5] ?? null; - $this->extra['environment'] = $matches[5] ?? null; + // There might be something in the middle between the timestamp + // and the environment/level. Let's put that at the beginning of the first line. + $middle = trim(rtrim($matches[4] ?? '', $this->extra['environment'].'.')); - // There might be something in the middle between the timestamp - // and the environment/level. Let's put that at the beginning of the first line. - $middle = trim(rtrim($matches[4] ?? '', $this->extra['environment'].'.')); + $this->level = strtoupper($matches[6] ?? ''); - $this->level = strtoupper($matches[6] ?? ''); + $firstLineText = $matches[7]; - $firstLineText = $matches[7]; + if (! empty($middle)) { + $firstLineText = $middle.' '.$firstLineText; + } + } + } - if (! empty($middle)) { - $firstLineText = $middle.' '.$firstLineText; + if (is_null($firstLineText)) { + $firstLineText = $this->parseFirstLineLoosely($firstChunk); } $this->message = trim($firstLineText); @@ -86,6 +106,60 @@ protected function fillMatches(array $matches = []): void // } + /** + * Called when the strict pattern did not match, or matched a timestamp + * Carbon could not read. Previously $matches was left empty and $matches[1] + * became an undefined key, an ErrorException that failed the whole request + * instead of the one entry. + * + * Falls back to static::$regex, the looser expression the indexer already + * used to accept this entry, so a line with millisecond precision or + * something in front of the timestamp keeps its datetime, level and + * environment. Content matching neither is kept with no severity. + * + * @return string The first line's message text. + */ + protected function parseFirstLineLoosely(string $firstChunk): string + { + if (preg_match(static::$regex, $firstChunk, $matches) === 1) { + try { + $this->datetime = static::parseDateTime($matches['datetime'] ?? null) + ?->setTimezone(LogViewer::timezone()); + } catch (\Exception) { + $this->datetime = null; + } + + if (! is_null($this->datetime)) { + $this->extra['environment'] = $matches['environment'] ?? null; + $this->level = strtoupper($matches['level'] ?? ''); + + return $matches['message'] ?? ''; + } + } + + $this->datetime = null; + $this->level = LaravelLogLevel::None; + $this->extra['unparseable'] = true; + + return $this->printableText($firstChunk); + } + + /** + * Raw control bytes would reach the JSON response and the UI, so drop them. + * + * Only the Cc class: \p{C} would also take Cf, which includes the bidi + * marks that keep mixed Arabic and Latin log lines in the right order, and + * the zero-width joiner that holds emoji sequences together. + */ + protected function printableText(string $text): string + { + return trim( + preg_replace('/[^\P{Cc}\n\t]+/u', '', $text) + ?? preg_replace('/[\x00-\x08\x0B\x0C\x0E-\x1F\x7F]+/', '', $text) + ?? '' + ); + } + protected static function regexPattern(): string { return '/^\[(\d{4}-\d{2}-\d{2}[T ]\d{2}:\d{2}:\d{2}\.?(\d{6}([\+-]\d\d:\d\d)?)?)\](.*?(\w+)\.|.*?)(' diff --git a/tests/Unit/LaravelLogs/LaravelLogsTest.php b/tests/Unit/LaravelLogs/LaravelLogsTest.php index f9294f72..8490ea84 100644 --- a/tests/Unit/LaravelLogs/LaravelLogsTest.php +++ b/tests/Unit/LaravelLogs/LaravelLogsTest.php @@ -321,3 +321,85 @@ ->and($log->context['exception'])->toContain('/vendor/symfony/http-kernel/') ->and($log->context['exception'])->toContain('/vendor/laravel/framework/'); }); + +it('does not fail on an entry it cannot parse', function (string $text) { + $log = new LaravelLog($text, 'laravel.log', 512608, 0); + + assertEquals(null, $log->datetime); + assertEquals(LaravelLogLevel::None, $log->level); + assertEquals(true, $log->extra['unparseable']); +})->with([ + 'null bytes' => str_repeat("\x00", 328), + 'binary noise' => "\x01\x02\x03\x04", + 'a plain line' => 'not a laravel log line at all', + 'a truncated entry' => '[2022-08-25 11:16:17', + 'empty' => '', +]); + +it('does not fail on a timestamp Carbon cannot read', function (string $text) { + $log = new LaravelLog($text, 'laravel.log', 0, 0); + + assertEquals(null, $log->datetime); + assertEquals(true, $log->extra['unparseable']); +})->with([ + 'month 13' => '[2022-13-45 11:16:17] local.ERROR: x', + 'hour 25' => '[2022-08-25 25:99:99] local.ERROR: x', +]); + +it('falls back to the looser pattern the indexer used', function (string $text) { + $log = new LaravelLog($text, 'laravel.log', 0, 0); + + assertEquals(LaravelLogLevel::Error, $log->level); + assertEquals('local', $log->extra['environment']); + assertEquals('2022-08-25 11:16:17', $log->datetime->toDateTimeString()); + assertEquals('boom', $log->message); + assertEquals(false, isset($log->extra['unparseable'])); +})->with([ + 'millisecond precision' => '[2022-08-25 11:16:17.123] local.ERROR: boom', + 'something before the timestamp' => ' [2022-08-25 11:16:17] local.ERROR: boom', +]); + +it('does not duplicate the tail of a long unparseable first line', function () { + $firstLine = str_repeat('A', 1000).str_repeat('B', 1500); + + $log = new LaravelLog($firstLine, 'laravel.log', 0, 0); + $text = $log->getOriginalText(); + + assertEquals(1000, substr_count($text, 'A')); + assertEquals(1500, substr_count($text, 'B')); +}); + +it('bounds the message of an entry whose first line is huge', function () { + $log = new LaravelLog(str_repeat('x', 600000), 'laravel.log', 0, 0); + + assertEquals(true, strlen($log->message) <= 1000); +}); + +it('keeps bidi marks and joiners in an unparseable entry', function () { + $arabic = "طلب \u{200F}العميل مكتمل"; + + $log = new LaravelLog("\x00".$arabic, 'laravel.log', 0, 0); + + assertEquals(true, str_contains($log->message, "\u{200F}")); +}); + +it('keeps only the printable part of an unparseable entry', function () { + $log = new LaravelLog("\x00\x01some readable text", 'laravel.log', 0, 0); + + assertEquals('some readable text', $log->message); +}); + +it('still limits the size of an unparseable entry', function () { + $log = new LaravelLog("no timestamp here\n".str_repeat('x', 600000), 'laravel.log', 0, 0); + + assertEquals(true, $log->extra['log_text_incomplete']); + assertEquals(true, strlen($log->getOriginalText()) < 600000); +}); + +it('does not mark a valid entry as unparseable', function () { + $log = new LaravelLog('[2022-08-25 11:16:17] local.DEBUG: Example log entry', 'laravel.log', 0, 0); + + assertEquals(LaravelLogLevel::Debug, $log->level); + assertEquals('Example log entry', $log->message); + assertEquals(false, isset($log->extra['unparseable'])); +});