Skip to content

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

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

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

Conversation

@MoheyElbaz

Copy link
Copy Markdown

Fixes #529.

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.

This isn't limited to corrupt bytes

regexPattern() is stricter than the static::$regex that Log::matches() already used to accept and index the entry. Both of these match $regex but fail regexPattern():

[2022-08-25 11:16:17.123] local.ERROR: boom      millisecond precision, it wants \d{6}
 [2022-08-25 11:16:17] local.ERROR: boom         anything printed before the '['

So ordinary entries hit this path too.

What this does

On a failed strict match, 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.

The fallback returns into the same code path as a normal match, so the maxLogSize() cap and the first-line message still apply. I tried an early return first and it was worse: unparseable entries came back uncapped at 600,021 bytes with log_text_incomplete unset, and message held the entire entry rather than a preview — with 25 entries a page, one corrupt region becomes a multi-hundred-MB response.

before after
600 KB unparseable entry 600,021 bytes, uncapped 131,075, capped
its message 600,021 bytes 20 (first line)
[…17.123] local.ERROR: boom 500 level ERROR, env local, message boom

Tests

11 added to LaravelLogsTest, covering the corrupt shapes, the loose-pattern recovery, the size cap, the first-line message, and that a valid entry is untouched. All 10 of the new assertions fail with Undefined array key 1 against current main.

main       337 passed (1038 assertions)
this PR    348 passed (1070 assertions)
pint       passed

Left alone deliberately

  • IndexedLogReader::next() — its empty($text) check returns null, which ends iteration rather than skipping, so changing it there would silently truncate log lists.
  • $this->text still holds the original bytes. Stripping control characters from the stored text would destroy legitimate content such as ANSI colour codes, and the size cap already bounds the payload.
  • HorizonLog, HorizonOldLog and RedisLog index $matches['level'] and friends without guards and will 500 the same way on a line they can't parse. That's the same class of bug and arguably belongs in Log::parseText(), but it needs its own tests, so I kept this PR to Undefined array key 1 in LaravelLog when entry is corrupt/null bytes → HTTP 500 #529. Happy to follow up if you want it.

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.

regexPattern() is stricter than the static::$regex the indexer used to
accept the entry in the first place, so this also hit ordinary lines: a
millisecond precision timestamp, or anything printed before the '[', match
$regex but not regexPattern().

So on a failed match, fall back to $regex and keep the datetime, level and
environment it finds. Only content that matches neither is marked
unparseable, with no severity and the printable part of its first line as
the message.

The fallback returns into the same code path as a normal match, so the
maxLogSize() cap and the first-line message still apply. Handling it with
an early return instead left unparseable entries uncapped, which turned one
corrupt region into a multi-hundred-MB response.

Fixes opcodesio#529
@MoheyElbaz

Copy link
Copy Markdown
Author

Closing this myself — I found three defects in my own patch while re-reviewing it.

  1. Text duplication. I pass the full $firstLine to the fallback, but the line that assembles $text still appends implode("", $firstLineSplit) — the characters past 1000 that the strict branch deliberately held back. A 2500-character first line renders 1500 of those characters twice. The strict branch is correct because it only ever uses array_shift($firstLineSplit); my fallback should get that same chunk.
  2. The crash is still reachable. [2022-13-45 11:16:17] local.ERROR: x matches regexPattern() — it uses bare \d{2} for month and day, so 13 and 45 pass — and then Carbon::parse() throws DateMalformedStringException on the unguarded strict path. I wrapped only the fallback in try/catch, so the whole-request failure this PR is named for survives for malformed dates.
  3. \p{C} is too broad. It strips the whole Unicode C category, including U+200F (RTL mark) and U+200D (ZWJ). On Arabic or mixed-direction log lines that reorders the rendered text and breaks emoji sequences. It should be \p{Cc}.

Issue #529 is still real and I will open a fresh PR with all three fixed, plus a first-line-length test — my existing size test put the payload on the second line, so it never exercised the unbounded message.

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