fix(logread): walk past an oversized line instead of stopping at it - #72
Merged
Merged
Conversation
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>
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>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #64.
A
bufio.Scannercannot resume pastErrTooLong, 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.Readerhands a long line back in pieces (ReadLine'sisPrefix), 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
That middle line is new; the third line is what is lost today.
Rawis a real slog line, becausedezhban logsin text mode (logs.go:93-95) and the bundle'slog.txt(report.go:341-343) printRawand nothing else — a marker with an emptyRawprints a blank line exactly where the explanation belongs.ParseLine(Raw)round-trips it, solog.txtstays readable by the code that wrote it.Timeis zero, because the timestamp was inside the bytes that went. That also means a--sincequery cannot hide a gap whose position it has no way to know. Swift'sisGoZeroalready renders it as no date.WARN, notERROR. dezhban did not fail, and the skipped line might have been anything — claimingERRORwould rank a guess against real records. The cost is stated incli.md:--level errorhides the stand-in, so ask forwarnwhen 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.
TestALineOverTheCapKeepsTheRecordsBeforeItasserted the opposite —— 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
TestAnUnreadableArchiveDoesNotCostTheLiveFileis now the only test holding it open, which its comment now says.Also in this change
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 inclusive —Scannererrored when its buffer was full at max, so the old true maximum was one byte below the number everything else stated (pinned byTestALineExactlyAtTheCapIsStillARecord).internal/redactkeeps logread's attr keys out of the hostname pass. They are namespaced with a dot, which gives them a hostname's shape, andlogread.oversizedreaches a bundle insideRaw— without an exact-match keep,log.txtreadhost-1=5242880and the legend counted a hostname standing for an attr key.logread.unparsedis listed alongside for the identical reason, not because it leaks today: it lives only inAttrs, andreportLogwritesRaw.Tests
Nine of the ten new tests fail against the code they guard. The tenth,
TestALastLineWithNoTrailingNewlineIsStillRead, passes both ways and is kept anyway: theScannerhandled that case for free, and a hand-rolled loop that emits after theio.EOFcheck rather than before it is exactly how it gets lost.Coverage: resumption; the marker's shape and
Rawround-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--sincebehaviour; 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:
So
TestDrainingALongLineCostsTheCapNotTheLinecompares 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
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:
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.maxLineBytes' doc comment claims the cap is stated indocs/usage/cli.mdand 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 addedTestTheDocumentedLineCapMatchesTheCode, 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
\rstraddling a read, and an archive tail — plus theint64/intconversion, 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 errorhides the marker,--jsoncarries the zero time Swift decodes asnil, andlog.txtkeepslogread.oversized=5000000with an empty legend.One honest limit on that last check:
dezhban logsresolves its state directory from a fixed path with no env override, so the fixture was driven throughlogread.Readandredact.Textdirectly rather than through the installed binary. The CLI's own contribution to those paths isfmt.Println(r.Raw)and the stderr warning, both of which the assertions above cover. The on-host checklist item added todocs/contribute/testing.mdis the version a human runs against the real thing.🤖 Generated with Claude Code