Skip to content

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

Open
MoheyElbaz wants to merge 1 commit into
opcodesio:mainfrom
MoheyElbaz:fix/unparseable-entry
Open

Don't fail the whole request on an unparseable log entry#533
MoheyElbaz wants to merge 1 commit into
opcodesio:mainfrom
MoheyElbaz:fix/unparseable-entry

Conversation

@MoheyElbaz

Copy link
Copy Markdown

Fixes #529. Replaces #532, which I closed because my own patch had three defects in it.

LaravelLog::parseText() reads $matches[1] straight after preg_match without checking whether it matched:

preg_match(static::regexPattern(), array_shift($firstLineSplit), $matches);

$this->datetime = Carbon::parse($matches[1])?->setTimezone(LogViewer::timezone());

When the chunk isn't a Laravel entry — the reporter had a run of null bytes from a partial write on a shared volume — $matches is empty, Laravel turns the undefined key into an ErrorException, and /log-viewer/api/logs returns a 500 for the whole file rather than for the one bad entry.

There are two ways into that crash, not one

The pattern is stricter than the one that indexed the entry. regexPattern() demands \d{6} for fractional seconds and is anchored at ^\[, while Log::matches() accepted the entry using the looser static::$regex. Both of these match $regex and fail regexPattern():

[2022-08-25 11:16:17.123] local.ERROR: boom      millisecond precision
 [2022-08-25 11:16:17] local.ERROR: boom         anything before the '['

And a matched timestamp can still throw. regexPattern() uses bare \d{2} for month, day and hour, so [2022-13-45 11:16:17] local.ERROR: x matches and Carbon::parse() then raises DateMalformedStringException — the same whole-request failure by a different route. There are tests for both.

What this does

On either failure, fall back to static::$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.

Three details that matter:

  • The fallback works from the same 1000-char chunk the strict branch matches against. The remainder of a long first line is appended back further down, so handing the fallback the whole $firstLine writes its tail twice — a 2500-char line renders 1500 characters duplicated. That was a bug in Don't fail the whole request on an unparseable log entry #532; there is now a test for it.
  • It returns into the shared code path, so the maxLogSize() cap and the first-line-only message still apply. An early return instead left unparseable entries uncapped at 600,021 bytes with log_text_incomplete unset, and put the entire entry in message.
  • Control bytes are stripped as \p{Cc}, not \p{C}. The wider class also takes 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. Also a bug in Don't fail the whole request on an unparseable log entry #532, also now tested.

I left IndexedLogReader::next() alone: its empty($text) check returns null, which ends iteration rather than skipping, so changing it there would silently truncate log lists.

Tests

15 cases added to LaravelLogsTest — the corrupt shapes, the unreadable timestamps, the loose-pattern recovery, the duplication, the message bound, the bidi marks, the size cap, and that a valid entry is untouched.

main       337 passed (1038 assertions)
this PR    352 passed (1077 assertions)
pint       passed

14 of the new cases fail against main.

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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Undefined array key 1 in LaravelLog when entry is corrupt/null bytes → HTTP 500

1 participant