Skip to content

fix(logread): walk past an oversized line instead of stopping at it - #72

Merged
Behnam-RK merged 6 commits into
mainfrom
fix/logread-resume-past-an-oversized-line
Sep 14, 2026
Merged

Behnam-RK merged 6 commits into
mainfrom
fix/logread-resume-past-an-oversized-line

Conversation

@Behnam-RK

@Behnam-RK Behnam-RK commented Sep 13, 2026

Copy link
Copy Markdown
Owner

Closes #64.

A bufio.Scanner cannot resume past ErrTooLong, so one line over the 4 MiB cap ended the scan: the records before it survived, and that line and every record after it in the same file did not. 0.15.0 shipped that as a documented limit (CHANGELOG.md:191-198).

A bufio.Reader hands a long line back in pieces (ReadLine's isPrefix), which is what makes it possible to walk past one without ever holding it. The loop drains the pieces, counts the bytes, and keeps going.

The skipped line leaves a record, not a gap

time=2026-09-13T10:00:00Z level=ERROR msg=before
level=WARN msg="log line too long to read; skipped" logread.oversized=5000000 limit=4194304
time=2026-09-13T10:00:02Z level=ERROR msg=after

That middle line is new; the third line is what is lost today.

  • Raw is a real slog line, because dezhban logs in text mode (logs.go:93-95) and the bundle's log.txt (report.go:341-343) print Raw and nothing else — a marker with an empty Raw prints a blank line exactly where the explanation belongs. ParseLine(Raw) round-trips it, so log.txt stays readable by the code that wrote it.
  • Time is zero, because the timestamp was inside the bytes that went. That also means a --since query cannot hide a gap whose position it has no way to know. Swift's isGoZero already renders it as no date.
  • WARN, not ERROR. dezhban did not fail, and the skipped line might have been anything — claiming ERROR would rank a guess against real records. The cost is stated in cli.md: --level error hides the stand-in, so ask for warn when you want to see gaps.

A pinned behaviour is deliberately reversed

Such a file is no longer reported as a partial read. It was read to its end; one line was not a record.

TestALineOverTheCapKeepsTheRecordsBeforeIt asserted the opposite —

if err == nil { t.Error("a line past the cap must still be reported") }

— so its name and its assertion are both reversed here. That is a choice, not a break, and it is called out rather than buried under a green suite. The error path stays for what it was built for, and TestAnUnreadableArchiveDoesNotCostTheLiveFile is now the only test holding it open, which its comment now says.

Also in this change

  • The 4 MiB literal becomes maxLineBytes. It was restated in this package's prose, in two tests and in a doc; a limit living in four places is one that drifts. The cap also becomes inclusiveScanner errored when its buffer was full at max, so the old true maximum was one byte below the number everything else stated (pinned by TestALineExactlyAtTheCapIsStillARecord).
  • internal/redact keeps logread's attr keys out of the hostname pass. They are namespaced with a dot, which gives them a hostname's shape, and logread.oversized reaches a bundle inside Raw — without an exact-match keep, log.txt read host-1=5242880 and the legend counted a hostname standing for an attr key. logread.unparsed is listed alongside for the identical reason, not because it leaks today: it lives only in Attrs, and reportLog writes Raw.

Tests

Nine of the ten new tests fail against the code they guard. The tenth, TestALastLineWithNoTrailingNewlineIsStillRead, passes both ways and is kept anyway: the Scanner handled that case for free, and a hand-rolled loop that emits after the io.EOF check rather than before it is exactly how it gets lost.

Coverage: resumption; the marker's shape and Raw round-trip; a long line as the unterminated last line; two long lines each carrying their own count; a long line in a rotated archive costing neither its own tail nor the live file; the inclusive cap; the level filter in both directions; the --since behaviour; and memory.

Memory — measured, and the plan's number was wrong

I predicted ~8 MiB. It is ~20 MiB cumulative, five times the cap, because append's growth factor for large slices is about 1.25 and the intermediate copies add up.

What matters is that it is flat:

line allocated
4 MiB 20,264,336
8 MiB 20,248,248
16 MiB 20,253,664
64 MiB 20,248,248

So TestDrainingALongLineCostsTheCapNotTheLine compares two reads whose lines differ by 16× and asserts the allocation barely moves — which a buffering design cannot satisfy at any threshold — instead of pinning a constant nobody can defend.

Review loop

Round Reviewer Findings Pre-existing Loop-introduced Defects fixed
0 me, before asking 1 0 1 1
1 read-only subagent 1 0 1 1

Neither round found a correctness defect in the reader. Both found something worth having, and both were about this branch's own output — named rather than absorbed:

  • Round 0 (mine): nothing pinned the half of this change that is pure risk — that ordinary files still read identically. The per-case tests each check one behaviour. Added logread_diff_test.go, a differential over 300 random files against a verbatim copy of the old Scanner loop, built from the shapes that have caused trouble in this package before.
  • Round 1 (reviewer): maxLineBytes' doc comment claims the cap is stated in docs/usage/cli.md and that changing it means changing the doc. The claim was false — the paragraph never landed. An edit script's assert fired on an earlier hunk, I took it for the later one, and nothing caught it afterwards because prose is not compiled. Fixed the paragraph and added TestTheDocumentedLineCapMatchesTheCode, which fails by name without it. This was the second doc edit in the session to disappear the same way, which is the argument for a test over a retype.

The reviewer worked the loop by hand for a lone over-cap line, an over-cap first line, back-to-back long lines, a length landing on a buffer boundary, a \r straddling a read, and an archive tail — plus the int64/int conversion, capacity retention, the marker across all four consumers, and which tests bite. No BUG or RISK.

Verification

task check, GOOS=linux/windows go vet, swift test (270). Plus a real 5 MB-line fixture through all four surfaces: the record after the long line comes back, stderr is silent, --level error hides the marker, --json carries the zero time Swift decodes as nil, and log.txt keeps logread.oversized=5000000 with an empty legend.

One honest limit on that last check: dezhban logs resolves its state directory from a fixed path with no env override, so the fixture was driven through logread.Read and redact.Text directly rather than through the installed binary. The CLI's own contribution to those paths is fmt.Println(r.Raw) and the stderr warning, both of which the assertions above cover. The on-host checklist item added to docs/contribute/testing.md is the version a human runs against the real thing.

🤖 Generated with Claude Code

A bufio.Scanner cannot resume past ErrTooLong, so one line over the 4 MiB cap
ended the scan: the records before it survived, and that line AND EVERY RECORD
AFTER IT IN THE SAME FILE did not. 0.15.0 shipped that as a documented limit.

A bufio.Reader hands a long line back in pieces, which is what makes it possible
to walk past one without ever holding it. The loop drains the pieces, counts the
bytes, and keeps going.

The skipped line leaves a WARN record in its place rather than a silent gap —
the call ParseLine already makes for a line tail it cannot read. It carries the
byte count under logread.oversized, and its Raw is a real slog line because
`dezhban logs` in text mode and the bundle's log.txt print Raw and nothing else;
a marker with an empty Raw prints a blank line exactly where the explanation
belongs. Its Time is zero because the timestamp was inside the bytes that went,
which also means a --since query cannot hide a gap whose position it cannot
know. WARN, not ERROR: dezhban did not fail, and the skipped line might have
been anything — claiming ERROR would rank a guess against real records.

And such a file is no longer reported as a partial read. It was read to its end.
TestALineOverTheCapKeepsTheRecordsBeforeIt asserted the opposite, so its name and
its assertion are both reversed here — deliberately, and called out rather than
buried under a green suite. The error path stays for what it was built for, and
TestAnUnreadableArchiveDoesNotCostTheLiveFile is now the only test holding it
open, which its comment now says.

The 4 MiB literal becomes maxLineBytes. It was restated in this package's prose,
in two tests and in a doc, and a limit living in four places is one that drifts.
The cap also becomes inclusive: Scanner errored when its buffer was full at max,
so the old true maximum was one byte below the number everything else stated.

internal/redact keeps logread's own attr keys out of the hostname pass. They are
namespaced with a dot, which gives them a hostname's shape, and logread.oversized
reaches a bundle inside Raw — without this, log.txt read host-1=5242880 and the
legend counted a hostname standing for an attr key. logread.unparsed is listed
alongside for the identical reason, not because it leaks today: it lives only in
Attrs, and reportLog writes Raw.

Nine of the ten new tests fail against the code they guard. The tenth,
TestALastLineWithNoTrailingNewlineIsStillRead, passes both ways and is kept
anyway: the Scanner handled that case for free, and a hand-rolled loop that emits
after the io.EOF check rather than before it is exactly how it gets lost.

Memory was measured rather than asserted, and the plan's number was wrong: it is
~20 MiB of cumulative allocation, five times the cap, because append's growth
factor for large slices is about 1.25. What matters is that it is FLAT — a 4 MiB
line and a 64 MiB line cost the same — so the test compares two reads whose lines
differ by 16x instead of pinning a constant no one can defend.

Verified: task check, GOOS=linux/windows go vet, swift test (270), and a real
5 MB-line fixture through all four surfaces — the record after the long line
comes back, stderr is silent, --level error hides the marker, --json carries the
zero time Swift decodes as nil, and log.txt keeps logread.oversized=5000000 with
an empty legend.

Closes #64

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@Behnam-RK Behnam-RK added the run-ci Run CI on this PR (gates .github/workflows/ci.yml) label Sep 13, 2026
Behnam-RK and others added 5 commits September 13, 2026 19:01
Round 0 of the review loop, before asking anyone. Swapping bufio.Scanner for a
hand-rolled bufio.Reader loop puts every ORDINARY line at risk in order to fix a
pathological one, and nothing pinned that half: the per-case tests each check one
behaviour, and the suite passing is evidence rather than proof.

A differential test over 300 random files, built from the shapes that have caused
trouble in this package before — blank and whitespace-only lines, a line with no
level, an unparseable line, a quoted value with an escaped quote, an unterminated
quote, a trailing CR, a line long enough to span several reads, and half the time
a file with no closing newline — asserts the reader and the old scanner produce
identical records.

The old loop is duplicated verbatim as the oracle, deliberately: the claim is that
nothing changed, and asserting that means keeping the thing being compared against.
Deterministic seed, so a failure is reproducible rather than a story about CI.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Round 1 of the review loop. maxLineBytes' doc comment says the number is stated
in docs/usage/cli.md and that changing it means changing that doc too. The claim
was false: the paragraph never landed.

It never landed because a python assert fired on an earlier hunk of the same
edit script, I took it for the later one, fixed that, and moved on. Nothing
caught it afterwards — prose is not compiled, so the gate has nothing to say, and
both the code comment and the CHANGELOG went on describing a paragraph that did
not exist.

So the fix is the paragraph AND a test. TestTheDocumentedLineCapMatchesTheCode
reads the doc and fails if it does not state the cap, by name and with the
number. A comment that names a file is a promise about that file, and the
cheapest way to keep a promise is to fail without it. This is the second doc edit
in this session to disappear the same way, which is the argument for making it
checkable rather than just writing it again.

Fails against main's cli.md:
  ../../docs/usage/cli.md does not state the per-line cap as "4 MiB";
  maxLineBytes is 4194304 and its comment says this doc names it

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Round 0 of another review pass, on the one dimension the earlier rounds never
touched: the marker record has NO TIMESTAMP, and Recent problems fetches
`--level warn`, so a gap lands in the list a person actually looks at. Every
assertion about that so far has been mine rather than a test's.

Reading it: problemRow's `if let t = r.time` drops the timestamp column cleanly,
`isError` is false for WARN so the row gets the orange triangle rather than the
red octagon, and `detail` joins the attrs into the monospaced second line. The
rendering is right. Nothing was holding it that way.

So: a test that decodes the exact JSON logread emits and asserts the three things
the row depends on — no date, warning not error, and a detail line naming how
much was lost. It fails on a marker that claims ERROR, which is the edit someone
makes when they decide a gap should be louder.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Round 2 of the review loop, on the question no earlier round asked: is this
proportionate, and what will it cost to live with?

The answer was mostly yes — no redundant tests, and the comment density that
looks high on the new content leaves the file at 44%, the same as runner.go and
below redact.go. One coupling was wrong, though.

TestTheDocumentedLineCapMatchesTheCode read ../../docs/usage/cli.md from a
package test in internal/logread, so moving a doc would have broken a package
that has nothing to do with docs, and a second package growing its own docs
reader is how "where do doc checks live" stops having an answer. It moves to
internal/help, which already owns that question: it sits beside
TestEveryTunableDocAnchorResolves, which validates a claim internal/config makes,
for the same reason and in the same place.

That needs the cap exported, so maxLineBytes becomes logread.MaxLineBytes —
the precedent being logging.FileBackups, exported precisely so logread need not
restate the number it depends on.

The differential test's frozen oracle now says what to do when it fails: the
reader changed, and the oracle must not be edited to agree with it. An oracle
edited to match the thing it checks is not an oracle, and nothing in the file
said so. (The reviewer's specific rot scenario — a ParseLine change — does not
apply, because the oracle calls the real ParseLine.)

Declined, with reasons: the relative path did not fail silently, it used
os.ReadFile with t.Fatal; and dropping `limit` from Attrs while keeping it in Raw
would break the ParseLine(Raw) round-trip that keeps log.txt readable by the
parser that wrote it.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Round 3 of the review loop, on the last question nobody had asked: what does
this change do to the system around it, and what happens on hostile input?

Two hypotheses, both confirmed rather than refuted. A forged gap is unreachable:
the marker's msg is a const, every daemon log call uses a literal msg so no
attacker-influenced value can become one, and the log is 0644 root-owned inside a
0755 root-owned directory, so an unprivileged user can neither write it nor plant
an archive. And markers cannot crowd out records: Limit keeps the TAIL, so a
burst of them displaces only older entries. Degenerate files are fine too — a
10 GiB single line drains through the 64 KiB window with no growth.

The one gap was the contract. cli.md offers --json as "structured, for another
surface to render", and the marker is the one record with no timestamp: a
third-party renderer would have read 0001-01-01T00:00:00Z as the year 1 rather
than as "no time". The macOS app already reads it correctly, through
LogRecords.swift's isGoZero, which is exactly why nothing noticed.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@Behnam-RK
Behnam-RK merged commit 3b06f55 into main Sep 14, 2026
6 checks passed
@Behnam-RK
Behnam-RK deleted the fix/logread-resume-past-an-oversized-line branch September 14, 2026 08:10
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

run-ci Run CI on this PR (gates .github/workflows/ci.yml)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

logread: an oversized line still costs the rest of that file

1 participant