Skip to content

Don't fail the whole request on an unparseable log entry #533

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
MoheyElbaz wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Don't fail the whole request on an unparseable log entry #533

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
98 changes: 86 additions & 12 deletions src/Logs/LaravelLog.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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+)\.|.*?)('
Expand Down
82 changes: 82 additions & 0 deletions tests/Unit/LaravelLogs/LaravelLogsTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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']));
});