From f5c7c375a15dedd07076604c598eaa5565fb3130 Mon Sep 17 00:00:00 2001 From: Behnam RK Date: Sun, 13 Sep 2026 18:48:36 +0330 Subject: [PATCH 1/6] fix(logread): walk past an oversized line instead of stopping at it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- CHANGELOG.md | 14 ++ docs/contribute/testing.md | 10 + internal/logread/logread.go | 175 ++++++++++++++--- internal/logread/logread_test.go | 325 ++++++++++++++++++++++++++++++- internal/redact/json_test.go | 24 +++ internal/redact/redact.go | 12 ++ 6 files changed, 525 insertions(+), 35 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e55e8f5..1419772 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,20 @@ current as you land changes. ### Fixed +- **`dezhban logs` no longer loses the rest of a file to one oversized line.** + 0.15.0 kept the records *before* a line past the 4 MiB cap and said that line and + everything after it in the same file were still lost, because a `bufio.Scanner` + cannot resume past `ErrTooLong`. The reader now walks a long line in pieces + without ever holding it, so the records **after** it come back too, and the + skipped line leaves a `warn` record in its place (`logread.oversized=`) + rather than a silent gap — the same call the parser already makes for a line tail + it cannot read. Because that stand-in is a warning, `--level error` hides it: ask + for `warn`, or for no level at all, to see gaps. A file with such a line is no + longer reported as a partial read; a file that cannot be opened at all still is. + Redaction keeps the marker legible too — `logread.oversized` has a hostname's + shape, and without an exact-match keep a redacted bundle's `log.txt` would have + printed `host-1=`. + - **A redacted bundle no longer replaces dezhban's own file paths with a hostname token.** `doctor`'s control check names the socket it probed, and that path came back as `/var/db/dezhban/host-1` — the answer replaced, and no identity hidden, diff --git a/docs/contribute/testing.md b/docs/contribute/testing.md index 5f8d165..caa66b0 100644 --- a/docs/contribute/testing.md +++ b/docs/contribute/testing.md @@ -1373,6 +1373,16 @@ end up typing a password. - [ ] **Rotation is covered.** Force a rotation (or rename `dezhban.log` to `dezhban.log.1` and restart), then confirm `dezhban logs` still shows the archived records, oldest first. +- [ ] **An oversized line does not swallow the rest of the file.** Append a line + longer than 4 MiB to `dezhban.log` + (`python3 -c "print('x'*5000000)" | sudo tee -a /logs/dezhban.log`), + then write a normal record after it. `dezhban logs` shows the records written + **after** the long line — that is the half that used to be lost — with one + `log line too long to read; skipped` where it was, and **no** "part of the log + could not be read" warning on stderr. `--level error` hides that stand-in; + `--level warn` shows it. Diagnostics → Recent problems shows it too, as a + warning with no timestamp. In a redacted bundle's `log.txt` it still reads + `logread.oversized=…`, not `host-N=…`. - [ ] **The bundle collects.** Export… → pick a folder → Finder reveals `dezhban-report-.zip`. Open it: README.txt, config.json, state.json, learned.json, armed.json, applied-rules.json, doctor.json, diff --git a/internal/logread/logread.go b/internal/logread/logread.go index 28780dd..5309926 100644 --- a/internal/logread/logread.go +++ b/internal/logread/logread.go @@ -10,12 +10,21 @@ // // Read-only and unprivileged by design: the log is 0644 precisely so the GUI and // an ordinary operator can read history without root. +// +// Nothing readable is ever dropped in silence. A line the parser cannot break +// into pairs keeps its tail under UnparsedKey; a line with no level at all +// survives a warn-and-above query; a line too long to hold is skipped and leaves +// a record saying so (OversizedKey) where it was; and a file that cannot be read +// costs only itself, its error travelling back beside the records from the rest +// of the chain. A surface that shows fewer records than the log holds, without +// saying so, is the one failure this package is built not to have. package logread import ( "bufio" "errors" "fmt" + "io" "os" "path/filepath" "strconv" @@ -132,6 +141,69 @@ func ParseLine(line string) Record { // tell dezhban's own words from the daemon's. const UnparsedKey = "logread.unparsed" +// OversizedKey is the attr key on the record readFile puts in place of a line +// past maxLineBytes; its value is that line's length in bytes, not counting the +// line ending. A sibling of UnparsedKey, named for the same reason — a surface +// can tell dezhban's own words from the daemon's, and a caller counting gaps has +// something exact to match on rather than the English in Msg. +const OversizedKey = "logread.oversized" + +// maxLineBytes caps one log line. A stack trace, or a rendered ruleset inside a +// msg, runs far past bufio's 64 KiB default, so the cap is generous; what it +// protects is memory, since a reader that held whatever the file happened to +// contain could be made to hold the whole file. +// +// A line longer than this is SKIPPED and reported in its place — never silently +// dropped, and never held. See readFile and oversizedRecord. +// +// Named rather than written as a literal, for the reason logging.FileBackups is +// exported and internal/vpnimport names maxConfigLine: the number is stated in +// this package's prose, in its tests, and in docs/usage/cli.md, and a limit that +// lives in four places is a limit that drifts. Changing it means changing that +// doc too. +const maxLineBytes = 4 << 20 // 4 MiB + +// lineBufBytes is the window the reader fills per read, NOT a limit: a longer +// line is assembled from as many windows as it takes, and one past maxLineBytes +// is drained through this window without being kept. It is the size the +// bufio.Scanner this replaced started at, so the ordinary path costs what it did. +const lineBufBytes = 64 << 10 // 64 KiB + +// oversizedMsg is what a skipped line says for itself. Prose, because the macOS +// pane renders it as the row's primary text to someone who is not a developer: +// it has to name the cause and the consequence in one line. +const oversizedMsg = "log line too long to read; skipped" + +// oversizedRecord stands in for a line readFile would not hold, carrying how many +// bytes went and what they were measured against. +// +// Raw is a real slog line, not a summary, because `dezhban logs` in text mode and +// the bundle's log.txt print Raw and NOTHING else — a record with an empty Raw +// prints a blank line exactly where the explanation belongs. Writing it in slog's +// own grammar keeps log.txt homogeneous and keeps it readable by the parser that +// produced it: ParseLine(Raw) reconstructs this record field for field. +// +// WARN, not ERROR: dezhban did not fail, one line was too big to read, and +// escalating a reading limit to the loudest row on a diagnostics pane misdirects. +// Not an empty level either — Known("") is false, so no filter could ever drop it +// and `--level error` would show it, which is not what a gap deserves. +// +// The zero Time is the honest one: the `time=` was inside the bytes that went. A +// guessed "now" would sort a gap against real timestamps and let --since include +// it on a fabrication. It also means the Since filter, which tests +// !r.Time.IsZero(), always lets a marker through — right, because a gap that may +// hide in-window records must not itself be hidden by the window. +func oversizedRecord(n int64) Record { + size, limit := strconv.FormatInt(n, 10), strconv.Itoa(maxLineBytes) + return Record{ + Level: "WARN", + Msg: oversizedMsg, + Attrs: []Attr{{Key: OversizedKey, Value: size}, {Key: "limit", Value: limit}}, + Raw: fmt.Sprintf("level=WARN msg=%s %s=%s limit=%s", + strconv.Quote(oversizedMsg), OversizedKey, size, limit), + } +} + // nextPair pulls one key=value off the front of s, honouring slog's quoting: // a value containing a space, a quote, or an equals sign is written as a Go // quoted string. Without that, `msg="rules missing, re-applied" n=2` would parse @@ -152,8 +224,8 @@ func nextPair(s string) (key, value, rest string, ok bool) { s = s[eq+1:] if strings.HasPrefix(s, `"`) { // QuotedPrefix scans for the closing quote ONCE. Trying Unquote on every - // prefix did the same work O(n) times, and the scanner admits lines up to - // 4 MiB, so a long quoted value full of escaped quotes made `dezhban + // prefix did the same work O(n) times, and the reader admits lines up to + // maxLineBytes, so a long quoted value full of escaped quotes made `dezhban // logs` reparse the same megabyte over and over. Same decoder either way, // so escapes are still handled by the code that wrote them. if q, err := strconv.QuotedPrefix(s); err == nil { @@ -193,6 +265,10 @@ type Options struct { // A non-nil error and a non-empty slice arrive TOGETHER when part of the chain // could not be read. Callers must report the error and still use the records — // the whole point is that one unreadable file costs only itself. +// +// A line past the reader's size cap is NOT one of those cases: it is skipped, a +// record marking the gap takes its place, and the read is not an error. Nothing +// before or after such a line is lost. func Read(path string, opt Options) ([]Record, error) { var all []Record var problems []string @@ -242,41 +318,90 @@ func readFile(path string, opt Options) ([]Record, error) { } var out []Record - sc := bufio.NewScanner(f) - // A stack trace or a long attr can exceed bufio's 64KiB default, and a - // scanner that stops mid-file would silently truncate the history. - sc.Buffer(make([]byte, 0, 64*1024), 4*1024*1024) - for sc.Scan() { - line := sc.Text() - if strings.TrimSpace(line) == "" { - continue - } - r := ParseLine(line) + // One gate for every record, synthesised or parsed. A marker that skipped the + // filters would answer a different question than the one asked, and a marker + // the filters could not see would be a record this package had decided was + // exempt from the caller's query. + keep := func(r Record) { // Only a level this build RECOGNISES may be filtered out. A level it // does not know is not evidence the record is unimportant — a newer // daemon, a custom slog level, a hand-edited line — and ranking it as // INFO for ordering must not become a warn-and-above query silently // swallowing it. if Known(r.Level) && Severity(r.Level) < min { - continue + return } if !opt.Since.IsZero() && !r.Time.IsZero() && r.Time.Before(opt.Since) { - continue + return } out = append(out, r) } - // `out`, not nil: a single line past the 4 MiB cap used to cost every record - // already parsed from this file, so one pathological line took the whole - // history with it. The error still travels — it is the caller's to report — - // but it no longer erases what was readable. + + // A bufio.Reader, NOT a Scanner. A Scanner cannot resume past ErrTooLong, so + // one line longer than the cap ended the scan and took every record after it + // in that file with it. ReadLine hands a long line back in PIECES, which is + // what makes it possible to walk past one without ever holding it. + br := bufio.NewReaderSize(f, lineBufBytes) + var ( + line []byte // the line being assembled + dropped int64 // length of an over-cap line being drained; 0 when not draining + readErr error + ) + for { + frag, isPrefix, err := br.ReadLine() + // frag points INTO br's buffer and dies at the next read, so every byte + // kept is copied here and now. + switch { + case dropped > 0: + // Already past the cap: count the rest of the line, keep none of it. + dropped += int64(len(frag)) + case len(line)+len(frag) > maxLineBytes: + // This piece crosses the cap. Release what was held — the line is not + // coming back, and holding it in order to describe it is the + // allocation the cap exists to refuse. + dropped, line = int64(len(line)+len(frag)), nil + default: + line = append(line, frag...) + } + if isPrefix { + continue + } + // A whole line. ReadLine reports isPrefix false for the LAST piece of a + // long line and for a final line the file left without a newline, so both + // arrive here — and this emit has to happen BEFORE the break below, or a + // file ending mid-line loses its last record to the io.EOF. + if dropped > 0 { + keep(oversizedRecord(dropped)) + } else if s := strings.TrimSuffix(string(line), "\r"); strings.TrimSpace(s) != "" { + // ScanLines dropped a trailing \r from every line INCLUDING a final + // one with no newline; ReadLine drops it only before a newline. Same + // line either way, so Raw stays what it has always been. + keep(ParseLine(s)) + } + line, dropped = line[:0], 0 + if err != nil { + // io.EOF is the end, not a problem — the io.Reader contract makes it + // that exact value and bufio does not wrap it. Anything else is a + // genuine read failure and travels back BESIDE the records already + // parsed, exactly as a file that cannot be opened does. + if err != io.EOF { + readErr = err + } + break + } + } + // `out`, not nil — and no error for a line this reader chose to skip. Reading + // SUCCEEDED: the file was walked to its end, one line was not a record, and + // the record standing in its place says so where it happened. // - // What survives is the records BEFORE the oversized line, and only those: a - // bufio.Scanner cannot resume past ErrTooLong, so the rest of that file is - // still lost. Recovering it needs a reader loop that consumes through the - // long line's newline, which is a bigger change than the one this comment - // used to claim to have made. - if err := sc.Err(); err != nil { - return out, fmt.Errorf("read %s: %w", filepath.Base(path), err) + // That is the whole of issue #64. A single line past the cap used to cost + // every record after it in the same file, because a Scanner stops at + // ErrTooLong and cannot be restarted. The error path that remains is the one + // it was built for: a file that could not be opened, or could not be read at + // all — see TestAnUnreadableArchiveDoesNotCostTheLiveFile, which is now the + // only test holding it open. + if readErr != nil { + return out, fmt.Errorf("read %s: %w", filepath.Base(path), readErr) } return out, nil } diff --git a/internal/logread/logread_test.go b/internal/logread/logread_test.go index dd5055f..5033a85 100644 --- a/internal/logread/logread_test.go +++ b/internal/logread/logread_test.go @@ -4,6 +4,9 @@ import ( "fmt" "os" "path/filepath" + "reflect" + "runtime" + "strconv" "strings" "testing" "time" @@ -86,6 +89,16 @@ func TestAnUnknownLevelSortsAsInfoNotDropped(t *testing.T) { } } +// writeRaw writes body verbatim — no trailing newline added. Its whole purpose is +// the file that ends mid-line, which writeLog cannot produce and which is where a +// hand-rolled read loop is easiest to get wrong. +func writeRaw(t *testing.T, path, body string) { + t.Helper() + if err := os.WriteFile(path, []byte(body), 0o644); err != nil { + t.Fatal(err) + } +} + func writeLog(t *testing.T, path string, lines ...string) { t.Helper() var body string @@ -340,25 +353,77 @@ func TestAnUnreadableArchiveDoesNotCostTheLiveFile(t *testing.T) { } } -// A line past the scanner's cap costs that line, not the file. +// A line past the cap costs THAT LINE, and nothing else in the file. // -// sc.Err() used to discard every record already parsed, so one pathological -// line took the whole history with it and `dezhban logs` printed nothing. -func TestALineOverTheCapKeepsTheRecordsBeforeIt(t *testing.T) { +// Two things used to go wrong here, and this pins both. A bufio.Scanner stops at +// ErrTooLong and cannot be restarted, so the records AFTER a long line were lost +// along with it — the `after` assertion is issue #64. And the failed read was +// reported as an error, which said the log could not be read when in fact it had +// been read to the end; that is why `err == nil` below is the reverse of what the +// earlier version of this test asserted. +func TestALineOverTheCapCostsThatLineAndNothingElse(t *testing.T) { dir := t.TempDir() path := filepath.Join(dir, "dezhban.log") - huge := strings.Repeat("x", 5*1024*1024) // over the 4 MiB cap writeLog(t, path, `time=2026-09-08T10:00:00Z level=ERROR msg=before`, - `time=2026-09-08T10:00:01Z level=ERROR msg=`+huge, + `time=2026-09-08T10:00:01Z level=ERROR msg=`+strings.Repeat("x", maxLineBytes+1), + `time=2026-09-08T10:00:02Z level=ERROR msg=after`, ) recs, err := Read(path, Options{}) - if err == nil { - t.Error("a line past the cap must still be reported") + if err != nil { + t.Errorf("err = %v; the file was read to its end, so this is not a partial read", err) + } + if len(recs) != 3 { + t.Fatalf("got %d records, want before + the marker + after: %+v", len(recs), recs) + } + if recs[0].Msg != "before" || recs[2].Msg != "after" { + t.Errorf("got %q and %q, want the records either side of the long line", recs[0].Msg, recs[2].Msg) + } + if recs[1].Msg != oversizedMsg { + t.Errorf("recs[1] = %+v, want the marker in the long line's place", recs[1]) + } +} + +// The marker is a record like any other, and every surface has to be able to +// render it: `dezhban logs` and the bundle's log.txt print Raw and NOTHING else, +// the macOS pane reads Msg and Attrs, and log.txt is re-parseable by the code that +// wrote it. +func TestASkippedLineLeavesAMarkerRecordInItsPlace(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + huge := strings.Repeat("x", maxLineBytes+7) + writeLog(t, path, huge) + + recs, err := Read(path, Options{}) + if err != nil { + t.Fatalf("err = %v, want none", err) } - if len(recs) != 1 || recs[0].Msg != "before" { - t.Fatalf("got %d records, want the one parsed before the long line", len(recs)) + if len(recs) != 1 { + t.Fatalf("got %d records, want just the marker: %+v", len(recs), recs) + } + r := recs[0] + if r.Level != "WARN" { + t.Errorf("level = %q, want WARN so --level warn shows it and --level error does not", r.Level) + } + if !r.Time.IsZero() { + t.Errorf("time = %v, want the zero time — the timestamp was inside the bytes that went", r.Time) + } + if strings.TrimSpace(r.Raw) == "" { + t.Error("Raw is blank; `dezhban logs` and log.txt print Raw and nothing else, so this prints an empty line") + } + var size string + for _, a := range r.Attrs { + if a.Key == OversizedKey { + size = a.Value + } + } + if want := strconv.Itoa(len(huge)); size != want { + t.Errorf("%s = %q, want %q — the length of the line that was skipped", OversizedKey, size, want) + } + // log.txt is read back by the same parser that produced it. + if got := ParseLine(r.Raw); !reflect.DeepEqual(got, r) { + t.Errorf("ParseLine(Raw) did not round-trip:\n got %+v\nwant %+v", got, r) } } @@ -389,3 +454,243 @@ func TestALineWithNoLevelSurvivesAWarnAndAboveQuery(t *testing.T) { t.Fatalf("got %v, want the panic line kept and the INFO record filtered out", msgs) } } + +// A file that ends mid-long-line still ends cleanly. ReadLine reports isPrefix +// false for the last piece of a long line whether a newline follows it or not, so +// the marker has to be emitted before the io.EOF ends the loop. +func TestALongLastLineWithNoTrailingNewlineIsStillSkippedCleanly(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + writeRaw(t, path, "time=2026-09-08T10:00:00Z level=ERROR msg=before\n"+ + strings.Repeat("x", maxLineBytes+1)) + + recs, err := Read(path, Options{}) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + if len(recs) != 2 || recs[0].Msg != "before" || recs[1].Msg != oversizedMsg { + t.Fatalf("got %+v, want the record then the marker", recs) + } +} + +// A final line the writer left without a newline is still a record. +// +// Unlike its siblings this one PASSES against the code it guards — bufio.Scanner +// handled it for free. It is here because the hand-rolled reader that replaced the +// Scanner is exactly where that free behaviour is easiest to lose: emit the record +// after the io.EOF check rather than before it, and this is the only thing that +// notices. +func TestALastLineWithNoTrailingNewlineIsStillRead(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + writeRaw(t, path, "time=2026-09-08T10:00:00Z level=ERROR msg=first\n"+ + "time=2026-09-08T10:00:01Z level=ERROR msg=unterminated") + + recs, err := Read(path, Options{}) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + if len(recs) != 2 || recs[1].Msg != "unterminated" { + t.Fatalf("got %+v, want the unterminated final line kept", recs) + } +} + +// Each long line is counted on its own. A drain counter that did not reset would +// report the second gap as the sum of both. +func TestTwoLongLinesInOneFileEachLeaveTheirOwnMarker(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + first, second := strings.Repeat("x", maxLineBytes+1), strings.Repeat("y", maxLineBytes+9) + writeLog(t, path, + `time=2026-09-08T10:00:00Z level=ERROR msg=before`, + first, + `time=2026-09-08T10:00:01Z level=ERROR msg=middle`, + second, + `time=2026-09-08T10:00:02Z level=ERROR msg=after`, + ) + + recs, err := Read(path, Options{}) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + if len(recs) != 5 { + t.Fatalf("got %d records, want three real ones and two markers: %+v", len(recs), recs) + } + for i, want := range []string{"before", oversizedMsg, "middle", oversizedMsg, "after"} { + if recs[i].Msg != want { + t.Errorf("recs[%d].Msg = %q, want %q", i, recs[i].Msg, want) + } + } + if a, b := sizeAttr(t, recs[1]), sizeAttr(t, recs[3]); a != len(first) || b != len(second) { + t.Errorf("marker sizes = %d and %d, want %d and %d — each marker counts its OWN line", + a, b, len(first), len(second)) + } +} + +// sizeAttr is the byte count a marker record carries. +func sizeAttr(t *testing.T, r Record) int { + t.Helper() + for _, a := range r.Attrs { + if a.Key == OversizedKey { + n, err := strconv.Atoi(a.Value) + if err != nil { + t.Fatalf("%s = %q: %v", OversizedKey, a.Value, err) + } + return n + } + } + t.Fatalf("no %s attr on %+v", OversizedKey, r) + return 0 +} + +// The rotation analogue of TestAnUnreadableArchiveDoesNotCostTheLiveFile: a long +// line in an archive costs neither that archive's own tail nor the live file. +func TestALongLineInAnArchiveDoesNotCostTheLiveFileOrItsOwnTail(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + writeLog(t, path+".1", + `time=2026-09-08T09:00:00Z level=ERROR msg=archived-before`, + strings.Repeat("x", maxLineBytes+1), + `time=2026-09-08T09:00:01Z level=ERROR msg=archived-after`, + ) + writeLog(t, path, `time=2026-09-08T10:00:00Z level=ERROR msg=live`) + + recs, err := Read(path, Options{}) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + var got []string + for _, r := range recs { + got = append(got, r.Msg) + } + want := []string{"archived-before", oversizedMsg, "archived-after", "live"} + if !reflect.DeepEqual(got, want) { + t.Errorf("got %v, want %v — oldest first, with the gap in its place", got, want) + } +} + +// The cap is INCLUSIVE. bufio.Scanner errored when its buffer was full at max, so +// the old true maximum was one byte below the number everything else stated; the +// reader admits exactly maxLineBytes. Pinned so the shift is deliberate. +func TestALineExactlyAtTheCapIsStillARecord(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + const prefix = `time=2026-09-08T10:00:00Z level=ERROR msg=` + writeLog(t, path, prefix+strings.Repeat("x", maxLineBytes-len(prefix))) + + recs, err := Read(path, Options{}) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + if len(recs) != 1 || recs[0].Msg == oversizedMsg { + t.Fatalf("got %+v, want a line exactly at the cap read as a record", recs) + } +} + +// The marker goes THROUGH the level filter, not around it — so a warn-and-above +// query shows the gap and an errors-only query does not. +// +// The cost is stated rather than hidden: the skipped line might itself have been +// an ERROR. Its bytes are gone, so claiming so would rank a guess against real +// records; docs/usage/cli.md says to ask for warn when you want to see gaps. +func TestTheSkippedLineMarkerAnswersAWarnQueryButNotAnErrorQuery(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + writeLog(t, path, + `time=2026-09-08T10:00:00Z level=ERROR msg=before`, + strings.Repeat("x", maxLineBytes+1), + `time=2026-09-08T10:00:01Z level=ERROR msg=after`, + ) + + warn, err := Read(path, Options{MinLevel: "warn"}) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + if len(warn) != 3 || warn[1].Msg != oversizedMsg { + t.Errorf("warn query = %+v, want the gap shown", warn) + } + + errs, err := Read(path, Options{MinLevel: "error"}) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + if len(errs) != 2 { + t.Fatalf("error query = %+v, want only the two ERROR records", errs) + } + for _, r := range errs { + if r.Msg == oversizedMsg { + t.Error("the marker is a WARN and must not answer an errors-only query") + } + } +} + +// A marker survives a time window it has no timestamp for. The gap may hide +// in-window records, so hiding the gap itself because its time is unknown would +// answer the query with a silence it cannot justify. +func TestTheSkippedLineMarkerSurvivesASinceQuery(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + writeLog(t, path, + `time=2020-01-01T00:00:00Z level=ERROR msg=ancient`, + strings.Repeat("x", maxLineBytes+1), + `time=2026-09-08T10:00:01Z level=ERROR msg=recent`, + ) + + recs, err := Read(path, Options{Since: time.Date(2026, 1, 1, 0, 0, 0, 0, time.UTC)}) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + if len(recs) != 2 || recs[0].Msg != oversizedMsg || recs[1].Msg != "recent" { + t.Fatalf("got %+v, want the marker and the in-window record", recs) + } +} + +// Draining a long line costs the cap, not the line. +// +// The claim is not a byte count, it is that cost does not TRACK line length: a +// reader that buffered the line would scale with it, and this one does not. So the +// test compares two reads whose lines differ by 16x and asserts the allocation +// barely moves — which a buffering design cannot satisfy at any threshold. +// +// TotalAlloc, not peak RSS: cumulative is what is stable enough to assert in CI. +// Measured, it is ~20 MiB either way — five times the cap, because append's growth +// factor for large slices is about 1.25 and the intermediate copies add up. Flat is +// the property worth having; the constant factor is transient garbage on a +// pathological line, and buying it down would mean hand-rolling slice growth. +// +// The record assertions are what make this a fix-pin. The allocation comparison +// alone would also pass against the bufio.Scanner this replaced, which allocated to +// the cap and then gave up. +func TestDrainingALongLineCostsTheCapNotTheLine(t *testing.T) { + read := func(lineLen int) (uint64, []Record) { + t.Helper() + path := filepath.Join(t.TempDir(), "dezhban.log") + writeRaw(t, path, "time=2026-09-08T10:00:00Z level=ERROR msg=before\n"+ + strings.Repeat("x", lineLen)+"\ntime=2026-09-08T10:00:01Z level=ERROR msg=after\n") + runtime.GC() + var before, after runtime.MemStats + runtime.ReadMemStats(&before) + recs, err := Read(path, Options{}) + runtime.ReadMemStats(&after) + if err != nil { + t.Fatalf("err = %v, want none", err) + } + return after.TotalAlloc - before.TotalAlloc, recs + } + + small, recs := read(maxLineBytes + 1) + if len(recs) != 3 || recs[0].Msg != "before" || recs[2].Msg != "after" { + t.Fatalf("got %+v, want the records either side of the long line", recs) + } + large, recs := read(16 * maxLineBytes) + if len(recs) != 3 || recs[0].Msg != "before" || recs[2].Msg != "after" { + t.Fatalf("got %+v, want the records either side of the long line", recs) + } + + // 16x the line for no more than 2x the allocation. A design that held the + // line would need 16x. + if large > 2*small { + t.Errorf("a 16x longer line cost %d bytes against %d — allocation is tracking line length", + large, small) + } +} diff --git a/internal/redact/json_test.go b/internal/redact/json_test.go index b394d0f..ebaffb8 100644 --- a/internal/redact/json_test.go +++ b/internal/redact/json_test.go @@ -6,6 +6,8 @@ import ( "strconv" "strings" "testing" + + "github.com/behnam-rk/dezhban/internal/logread" ) // The doctor writes learned entry names — which are the user's profile names — @@ -620,3 +622,25 @@ func TestAUnixGroupNameIsKeptInEveryEntryThatCarriesIt(t *testing.T) { t.Errorf("legend = %v, want nothing minted for a group name or a path", legend) } } + +// logread namespaces its own attr keys with a dot so a surface can tell dezhban's +// words from the daemon's — which gives them a hostname's shape. `logread.oversized` +// reaches a redacted bundle inside a record's Raw, and Raw is what log.txt prints, +// so without an exact-match keep it reads `host-1=5242880` and the legend counts a +// hostname that stands for an attr key. +// +// The spellings come from logread itself, not from a literal here, so the two +// cannot drift apart — the same reason Read walks logging.FileBackups rather than +// restating 2. +func TestDezhbansOwnLogKeysSurviveRedaction(t *testing.T) { + r := New(true) + for _, key := range []string{logread.OversizedKey, logread.UnparsedKey} { + line := "level=WARN msg=\"log line too long to read; skipped\" " + key + "=5242880" + if got := r.Text(line); !strings.Contains(got, key) { + t.Errorf("%s was redacted: %q", key, got) + } + } + if legend := r.Legend(); len(legend) != 0 { + t.Errorf("legend = %v, want nothing minted for dezhban's own attr keys", legend) + } +} diff --git a/internal/redact/redact.go b/internal/redact/redact.go index 7a6c89b..37686d5 100644 --- a/internal/redact/redact.go +++ b/internal/redact/redact.go @@ -606,9 +606,21 @@ var keptSuffixes = []string{ // "which socket did it probe", and the run lock's path rides a startup failure // into the log. Replacing either with `host-N` throws the diagnosis away and hides // nothing, and counts a hostname in the legend that stands for a filename. +// The two logread attr keys are here for the same reason and not because either +// ever named a host: they are namespaced with a dot so a surface can tell +// dezhban's own words from the daemon's, which gives them a hostname's shape. +// `logread.oversized` reaches a redacted bundle inside a record's Raw, and Raw is +// what log.txt prints — without this it would read `host-1=5242880`, and the +// README's legend would count a hostname that stands for an attr key. +// `logread.unparsed` does not reach log.txt today (it lives only in Attrs, and +// reportLog writes Raw), and is listed anyway because the reason is identical and +// the next surface to print attrs should not have to rediscover it. var keptNames = map[string]bool{ "control.sock": true, // controlSocketPath's default basename "dezhban.lock": true, // runLockName, a constant + // Keep in step with internal/logread's UnparsedKey and OversizedKey. + "logread.unparsed": true, + "logread.oversized": true, } // replaceProfileNames rewrites every `"name": "..."` in body. From 4af17580a9735b3eba884aee5d869f5ac224facd Mon Sep 17 00:00:00 2001 From: Behnam RK Date: Sun, 13 Sep 2026 19:01:35 +0330 Subject: [PATCH 2/6] test(logread): pin that the reader agrees with the scanner it replaced MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- internal/logread/logread_diff_test.go | 86 +++++++++++++++++++++++++++ 1 file changed, 86 insertions(+) create mode 100644 internal/logread/logread_diff_test.go diff --git a/internal/logread/logread_diff_test.go b/internal/logread/logread_diff_test.go new file mode 100644 index 0000000..6c25c2a --- /dev/null +++ b/internal/logread/logread_diff_test.go @@ -0,0 +1,86 @@ +package logread + +import ( + "bufio" + "math/rand" + "os" + "path/filepath" + "reflect" + "strings" + "testing" +) + +// scannerRef is the bufio.Scanner loop this package used before, kept verbatim as +// a reference oracle. Duplicated on purpose: the claim it supports is "for a file +// with no over-cap line, NOTHING changed", and the only way to assert that is to +// keep the thing being compared against. It is short, frozen, and has one caller. +func scannerRef(t *testing.T, path string) []Record { + f, err := os.Open(path) + if err != nil { + t.Fatal(err) + } + defer f.Close() + var out []Record + sc := bufio.NewScanner(f) + sc.Buffer(make([]byte, 0, 64*1024), 4*1024*1024) + for sc.Scan() { + line := sc.Text() + if strings.TrimSpace(line) == "" { + continue + } + out = append(out, ParseLine(line)) + } + return out +} + +// The reader agrees with the scanner it replaced, record for record. +// +// Swapping bufio.Scanner for a hand-rolled bufio.Reader loop puts every ordinary +// line at risk to fix a pathological one, and the per-case tests around this one +// each check a single behaviour. This checks the whole of it at once, over random +// files built from the shapes that have caused trouble 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. +// +// Deterministic seed, so a failure is reproducible rather than a story about CI. +func TestTheReaderAgreesWithTheScannerItReplaced(t *testing.T) { + rng := rand.New(rand.NewSource(1)) + alphabet := []string{ + "time=2026-09-08T10:00:00Z level=ERROR msg=hello k=v", + "level=WARN msg=\"quoted value with spaces\" n=2", + "", " ", "\t", + "no level at all, just prose", + "time=bad level=INFO msg=x", + "msg=\"escaped \\\" quote\" tail", + strings.Repeat("z", 70000), // multi-fragment, under the cap + "trailing-cr\r", + "key=\"unterminated", + } + for i := 0; i < 300; i++ { + dir := t.TempDir() + path := filepath.Join(dir, "dezhban.log") + var b strings.Builder + n := rng.Intn(12) + for j := 0; j < n; j++ { + b.WriteString(alphabet[rng.Intn(len(alphabet))]) + b.WriteString("\n") + } + if rng.Intn(2) == 0 && n > 0 { // sometimes no trailing newline + s := b.String() + b.Reset() + b.WriteString(strings.TrimSuffix(s, "\n")) + } + writeRaw(t, path, b.String()) + + want := scannerRef(t, path) + got, err := readFile(path, Options{}) + if err != nil { + t.Fatalf("iteration %d: err = %v", i, err) + } + if !reflect.DeepEqual(got, want) { + t.Fatalf("iteration %d disagrees with the scanner\nbody %q\n got %+v\nwant %+v", + i, b.String(), got, want) + } + } +} From f5190fed4ee641208d830c29e2b59e783f159e57 Mon Sep 17 00:00:00 2001 From: Behnam RK Date: Sun, 13 Sep 2026 19:07:56 +0330 Subject: [PATCH 3/6] docs(logread): state the line cap where the code says it is stated MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- docs/usage/cli.md | 7 +++++++ internal/logread/logread_test.go | 22 ++++++++++++++++++++++ 2 files changed, 29 insertions(+) diff --git a/docs/usage/cli.md b/docs/usage/cli.md index e62a232..398dfee 100644 --- a/docs/usage/cli.md +++ b/docs/usage/cli.md @@ -449,6 +449,13 @@ level — is never filtered out, whatever `--level` you asked for: a level dezhban cannot rank is not evidence the record is unimportant, and a log reader that silently drops lines is worse than none. +A single line too long to read — past a 4 MiB per-line cap, which is what stops +one pathological line from making the reader hold a whole file — is skipped +rather than read, and a `warn` record saying so takes its place, in the position +that line held. Nothing before it and nothing after it is lost, and the file +still counts as read. Because the stand-in is a warning, `--level error` hides +it: ask for `warn`, or for no level at all, when you want to see gaps. + ### Collecting a bug report ```sh diff --git a/internal/logread/logread_test.go b/internal/logread/logread_test.go index 5033a85..eed1ca0 100644 --- a/internal/logread/logread_test.go +++ b/internal/logread/logread_test.go @@ -694,3 +694,25 @@ func TestDrainingALongLineCostsTheCapNotTheLine(t *testing.T) { large, small) } } + +// maxLineBytes' doc comment says the number is stated in docs/usage/cli.md, and +// that a change to it means changing the doc too. This makes the claim checkable +// instead of hopeful. +// +// It exists because the claim was FALSE when it was written: the doc edit was +// dropped on the way in and nothing noticed, because prose is not compiled and the +// gate has nothing to say about it. 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. +func TestTheDocumentedLineCapMatchesTheCode(t *testing.T) { + const doc = "../../docs/usage/cli.md" + body, err := os.ReadFile(doc) + if err != nil { + t.Fatal(err) + } + // The doc states the cap the way a reader says it, not the way Go writes it. + want := strconv.Itoa(maxLineBytes>>20) + " MiB" + if !strings.Contains(string(body), want) { + t.Errorf("%s does not state the per-line cap as %q; maxLineBytes is %d and its comment says this doc names it", + doc, want, maxLineBytes) + } +} From 54b4cca0a668448a65c0c96b8c1334d0c3dd6cc0 Mon Sep 17 00:00:00 2001 From: Behnam RK Date: Sun, 13 Sep 2026 20:48:38 +0330 Subject: [PATCH 4/6] test(gui): pin that the app can render a log gap, not just decode one MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .../DezhbanCoreTests/LogRecordsTests.swift | 28 +++++++++++++++++++ 1 file changed, 28 insertions(+) diff --git a/gui/macos/Tests/DezhbanCoreTests/LogRecordsTests.swift b/gui/macos/Tests/DezhbanCoreTests/LogRecordsTests.swift index 5d3f25c..a881f46 100644 --- a/gui/macos/Tests/DezhbanCoreTests/LogRecordsTests.swift +++ b/gui/macos/Tests/DezhbanCoreTests/LogRecordsTests.swift @@ -95,3 +95,31 @@ struct LogRecordsZeroTimeTests { #expect(recs[0].time != nil) } } + +extension LogRecordsTests { + /// The record logread puts in place of a line it could not read. + /// + /// It is the one record shape with no timestamp that a person actually sees — + /// Recent problems fetches `--level warn`, so a gap lands in that list. The Go + /// side pins what it emits; this pins that the pane can render it: a warning + /// rather than an error, a date the row knows to omit (problemRow's + /// `if let t = r.time` drops the column), and a detail line carrying how much + /// was lost. + @Test func theOversizedLineMarkerDecodesAsAWarningWithNoDate() throws { + let json = """ + [{"time":"0001-01-01T00:00:00Z","level":"WARN", + "msg":"log line too long to read; skipped", + "attrs":[{"key":"logread.oversized","value":"5242880"}, + {"key":"limit","value":"4194304"}], + "raw":"level=WARN msg=\\"log line too long to read; skipped\\" logread.oversized=5242880 limit=4194304"}] + """.data(using: .utf8)! + + let recs = try #require(LogRecord.decodeList(json)) + let r = try #require(recs.first) + #expect(r.time == nil) + #expect(r.isWarning) + #expect(!r.isError) + #expect(!r.msg.isEmpty) + #expect(r.detail.contains("logread.oversized=5242880")) + } +} From 2f86f44c46b0a409cd87125fb40d96681ed00bdc Mon Sep 17 00:00:00 2001 From: Behnam RK Date: Sun, 13 Sep 2026 21:01:09 +0330 Subject: [PATCH 5/6] refactor(help): keep the doc-vs-code check where this repo keeps them MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- internal/help/help_test.go | 27 ++++++++++++++++ internal/logread/logread.go | 29 ++++++++++-------- internal/logread/logread_diff_test.go | 10 ++++++ internal/logread/logread_test.go | 44 +++++++-------------------- 4 files changed, 65 insertions(+), 45 deletions(-) diff --git a/internal/help/help_test.go b/internal/help/help_test.go index 89abbdd..52afc13 100644 --- a/internal/help/help_test.go +++ b/internal/help/help_test.go @@ -5,9 +5,12 @@ import ( "os" "path/filepath" "regexp" + "strconv" "strings" "testing" + "github.com/behnam-rk/dezhban/internal/logread" + "github.com/behnam-rk/dezhban/internal/config" ) @@ -475,3 +478,27 @@ func TestIndexDecodes(t *testing.T) { t.Error("no page is in the tutorial track, so a first-time reader has no starting point") } } + +// logread.MaxLineBytes' doc comment says the number is stated in +// docs/usage/cli.md, and that changing it means changing that doc too. This is +// where that promise is kept, beside TestEveryTunableDocAnchorResolves — which +// validates a claim internal/config makes, for the same reason and in the same +// place. "The docs still say what the code does" is this package's business; a +// package growing its own ../../docs reader is how that stops being true of any +// one place. +// +// It exists because the claim was FALSE when it was written: the doc edit was +// dropped on the way in and nothing noticed, because prose is not compiled. +func TestTheDocumentedLogLineCapMatchesTheCode(t *testing.T) { + const page = "usage/cli.md" + body, err := os.ReadFile(filepath.Join(docsDir, filepath.FromSlash(page))) + if err != nil { + t.Fatal(err) + } + // The doc states the cap the way a reader says it, not the way Go writes it. + want := strconv.Itoa(logread.MaxLineBytes>>20) + " MiB" + if !strings.Contains(string(body), want) { + t.Errorf("%s does not state the per-line log cap as %q; logread.MaxLineBytes is %d and its comment says this page names it", + page, want, logread.MaxLineBytes) + } +} diff --git a/internal/logread/logread.go b/internal/logread/logread.go index 5309926..1bacf11 100644 --- a/internal/logread/logread.go +++ b/internal/logread/logread.go @@ -142,13 +142,13 @@ func ParseLine(line string) Record { const UnparsedKey = "logread.unparsed" // OversizedKey is the attr key on the record readFile puts in place of a line -// past maxLineBytes; its value is that line's length in bytes, not counting the +// past MaxLineBytes; its value is that line's length in bytes, not counting the // line ending. A sibling of UnparsedKey, named for the same reason — a surface // can tell dezhban's own words from the daemon's, and a caller counting gaps has // something exact to match on rather than the English in Msg. const OversizedKey = "logread.oversized" -// maxLineBytes caps one log line. A stack trace, or a rendered ruleset inside a +// MaxLineBytes caps one log line. A stack trace, or a rendered ruleset inside a // msg, runs far past bufio's 64 KiB default, so the cap is generous; what it // protects is memory, since a reader that held whatever the file happened to // contain could be made to hold the whole file. @@ -156,15 +156,20 @@ const OversizedKey = "logread.oversized" // A line longer than this is SKIPPED and reported in its place — never silently // dropped, and never held. See readFile and oversizedRecord. // -// Named rather than written as a literal, for the reason logging.FileBackups is -// exported and internal/vpnimport names maxConfigLine: the number is stated in -// this package's prose, in its tests, and in docs/usage/cli.md, and a limit that -// lives in four places is a limit that drifts. Changing it means changing that -// doc too. -const maxLineBytes = 4 << 20 // 4 MiB +// Named rather than written as a literal, for the reason internal/vpnimport names +// maxConfigLine: the number is stated in this package's prose, in its tests, and +// in docs/usage/cli.md, and a limit that lives in four places is a limit that +// drifts. Changing it means changing that doc too. +// +// Exported for the same reason logging.FileBackups is — so the one place that +// checks the doc against the code does not have to restate the number. That check +// lives in internal/help, which is where this repo keeps "the docs still say what +// the code does": see TestTheDocumentedLogLineCapMatchesTheCode there, alongside +// the Tunable.DocAnchor check that validates a claim internal/config makes. +const MaxLineBytes = 4 << 20 // 4 MiB // lineBufBytes is the window the reader fills per read, NOT a limit: a longer -// line is assembled from as many windows as it takes, and one past maxLineBytes +// line is assembled from as many windows as it takes, and one past MaxLineBytes // is drained through this window without being kept. It is the size the // bufio.Scanner this replaced started at, so the ordinary path costs what it did. const lineBufBytes = 64 << 10 // 64 KiB @@ -194,7 +199,7 @@ const oversizedMsg = "log line too long to read; skipped" // !r.Time.IsZero(), always lets a marker through — right, because a gap that may // hide in-window records must not itself be hidden by the window. func oversizedRecord(n int64) Record { - size, limit := strconv.FormatInt(n, 10), strconv.Itoa(maxLineBytes) + size, limit := strconv.FormatInt(n, 10), strconv.Itoa(MaxLineBytes) return Record{ Level: "WARN", Msg: oversizedMsg, @@ -225,7 +230,7 @@ func nextPair(s string) (key, value, rest string, ok bool) { if strings.HasPrefix(s, `"`) { // QuotedPrefix scans for the closing quote ONCE. Trying Unquote on every // prefix did the same work O(n) times, and the reader admits lines up to - // maxLineBytes, so a long quoted value full of escaped quotes made `dezhban + // MaxLineBytes, so a long quoted value full of escaped quotes made `dezhban // logs` reparse the same megabyte over and over. Same decoder either way, // so escapes are still handled by the code that wrote them. if q, err := strconv.QuotedPrefix(s); err == nil { @@ -355,7 +360,7 @@ func readFile(path string, opt Options) ([]Record, error) { case dropped > 0: // Already past the cap: count the rest of the line, keep none of it. dropped += int64(len(frag)) - case len(line)+len(frag) > maxLineBytes: + case len(line)+len(frag) > MaxLineBytes: // This piece crosses the cap. Release what was held — the line is not // coming back, and holding it in order to describe it is the // allocation the cap exists to refuse. diff --git a/internal/logread/logread_diff_test.go b/internal/logread/logread_diff_test.go index 6c25c2a..b7d52dc 100644 --- a/internal/logread/logread_diff_test.go +++ b/internal/logread/logread_diff_test.go @@ -14,6 +14,16 @@ import ( // a reference oracle. Duplicated on purpose: the claim it supports is "for a file // with no over-cap line, NOTHING changed", and the only way to assert that is to // keep the thing being compared against. It is short, frozen, and has one caller. +// +// IF THIS TEST FAILS, THE READER CHANGED — do not edit the oracle to match. An +// oracle edited to agree with the thing it checks is not an oracle, and the next +// reader of this file will believe it is. Either the change to readFile was +// unintended, or it was intended and this test should be deleted along with the +// claim it makes. Both are decisions; silently re-aligning the copy is not. +// +// Note the oracle calls the REAL ParseLine and the real filters are not exercised +// here (Options{} is empty), so a change to either does not rot this quietly: it +// either fails loudly or is out of scope. func scannerRef(t *testing.T, path string) []Record { f, err := os.Open(path) if err != nil { diff --git a/internal/logread/logread_test.go b/internal/logread/logread_test.go index eed1ca0..8920edd 100644 --- a/internal/logread/logread_test.go +++ b/internal/logread/logread_test.go @@ -366,7 +366,7 @@ func TestALineOverTheCapCostsThatLineAndNothingElse(t *testing.T) { path := filepath.Join(dir, "dezhban.log") writeLog(t, path, `time=2026-09-08T10:00:00Z level=ERROR msg=before`, - `time=2026-09-08T10:00:01Z level=ERROR msg=`+strings.Repeat("x", maxLineBytes+1), + `time=2026-09-08T10:00:01Z level=ERROR msg=`+strings.Repeat("x", MaxLineBytes+1), `time=2026-09-08T10:00:02Z level=ERROR msg=after`, ) @@ -392,7 +392,7 @@ func TestALineOverTheCapCostsThatLineAndNothingElse(t *testing.T) { func TestASkippedLineLeavesAMarkerRecordInItsPlace(t *testing.T) { dir := t.TempDir() path := filepath.Join(dir, "dezhban.log") - huge := strings.Repeat("x", maxLineBytes+7) + huge := strings.Repeat("x", MaxLineBytes+7) writeLog(t, path, huge) recs, err := Read(path, Options{}) @@ -462,7 +462,7 @@ func TestALongLastLineWithNoTrailingNewlineIsStillSkippedCleanly(t *testing.T) { dir := t.TempDir() path := filepath.Join(dir, "dezhban.log") writeRaw(t, path, "time=2026-09-08T10:00:00Z level=ERROR msg=before\n"+ - strings.Repeat("x", maxLineBytes+1)) + strings.Repeat("x", MaxLineBytes+1)) recs, err := Read(path, Options{}) if err != nil { @@ -500,7 +500,7 @@ func TestALastLineWithNoTrailingNewlineIsStillRead(t *testing.T) { func TestTwoLongLinesInOneFileEachLeaveTheirOwnMarker(t *testing.T) { dir := t.TempDir() path := filepath.Join(dir, "dezhban.log") - first, second := strings.Repeat("x", maxLineBytes+1), strings.Repeat("y", maxLineBytes+9) + first, second := strings.Repeat("x", MaxLineBytes+1), strings.Repeat("y", MaxLineBytes+9) writeLog(t, path, `time=2026-09-08T10:00:00Z level=ERROR msg=before`, first, @@ -550,7 +550,7 @@ func TestALongLineInAnArchiveDoesNotCostTheLiveFileOrItsOwnTail(t *testing.T) { path := filepath.Join(dir, "dezhban.log") writeLog(t, path+".1", `time=2026-09-08T09:00:00Z level=ERROR msg=archived-before`, - strings.Repeat("x", maxLineBytes+1), + strings.Repeat("x", MaxLineBytes+1), `time=2026-09-08T09:00:01Z level=ERROR msg=archived-after`, ) writeLog(t, path, `time=2026-09-08T10:00:00Z level=ERROR msg=live`) @@ -571,12 +571,12 @@ func TestALongLineInAnArchiveDoesNotCostTheLiveFileOrItsOwnTail(t *testing.T) { // The cap is INCLUSIVE. bufio.Scanner errored when its buffer was full at max, so // the old true maximum was one byte below the number everything else stated; the -// reader admits exactly maxLineBytes. Pinned so the shift is deliberate. +// reader admits exactly MaxLineBytes. Pinned so the shift is deliberate. func TestALineExactlyAtTheCapIsStillARecord(t *testing.T) { dir := t.TempDir() path := filepath.Join(dir, "dezhban.log") const prefix = `time=2026-09-08T10:00:00Z level=ERROR msg=` - writeLog(t, path, prefix+strings.Repeat("x", maxLineBytes-len(prefix))) + writeLog(t, path, prefix+strings.Repeat("x", MaxLineBytes-len(prefix))) recs, err := Read(path, Options{}) if err != nil { @@ -598,7 +598,7 @@ func TestTheSkippedLineMarkerAnswersAWarnQueryButNotAnErrorQuery(t *testing.T) { path := filepath.Join(dir, "dezhban.log") writeLog(t, path, `time=2026-09-08T10:00:00Z level=ERROR msg=before`, - strings.Repeat("x", maxLineBytes+1), + strings.Repeat("x", MaxLineBytes+1), `time=2026-09-08T10:00:01Z level=ERROR msg=after`, ) @@ -632,7 +632,7 @@ func TestTheSkippedLineMarkerSurvivesASinceQuery(t *testing.T) { path := filepath.Join(dir, "dezhban.log") writeLog(t, path, `time=2020-01-01T00:00:00Z level=ERROR msg=ancient`, - strings.Repeat("x", maxLineBytes+1), + strings.Repeat("x", MaxLineBytes+1), `time=2026-09-08T10:00:01Z level=ERROR msg=recent`, ) @@ -678,11 +678,11 @@ func TestDrainingALongLineCostsTheCapNotTheLine(t *testing.T) { return after.TotalAlloc - before.TotalAlloc, recs } - small, recs := read(maxLineBytes + 1) + small, recs := read(MaxLineBytes + 1) if len(recs) != 3 || recs[0].Msg != "before" || recs[2].Msg != "after" { t.Fatalf("got %+v, want the records either side of the long line", recs) } - large, recs := read(16 * maxLineBytes) + large, recs := read(16 * MaxLineBytes) if len(recs) != 3 || recs[0].Msg != "before" || recs[2].Msg != "after" { t.Fatalf("got %+v, want the records either side of the long line", recs) } @@ -694,25 +694,3 @@ func TestDrainingALongLineCostsTheCapNotTheLine(t *testing.T) { large, small) } } - -// maxLineBytes' doc comment says the number is stated in docs/usage/cli.md, and -// that a change to it means changing the doc too. This makes the claim checkable -// instead of hopeful. -// -// It exists because the claim was FALSE when it was written: the doc edit was -// dropped on the way in and nothing noticed, because prose is not compiled and the -// gate has nothing to say about it. 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. -func TestTheDocumentedLineCapMatchesTheCode(t *testing.T) { - const doc = "../../docs/usage/cli.md" - body, err := os.ReadFile(doc) - if err != nil { - t.Fatal(err) - } - // The doc states the cap the way a reader says it, not the way Go writes it. - want := strconv.Itoa(maxLineBytes>>20) + " MiB" - if !strings.Contains(string(body), want) { - t.Errorf("%s does not state the per-line cap as %q; maxLineBytes is %d and its comment says this doc names it", - doc, want, maxLineBytes) - } -} From 539dccc6bcd9d3c9e519ac3e2972b26673b934a4 Mon Sep 17 00:00:00 2001 From: Behnam RK Date: Mon, 14 Sep 2026 11:39:35 +0330 Subject: [PATCH 6/6] docs(logread): say that a gap marker carries no timestamp MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- docs/usage/cli.md | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/docs/usage/cli.md b/docs/usage/cli.md index 398dfee..cbde45e 100644 --- a/docs/usage/cli.md +++ b/docs/usage/cli.md @@ -454,7 +454,11 @@ one pathological line from making the reader hold a whole file — is skipped rather than read, and a `warn` record saying so takes its place, in the position that line held. Nothing before it and nothing after it is lost, and the file still counts as read. Because the stand-in is a warning, `--level error` hides -it: ask for `warn`, or for no level at all, when you want to see gaps. +it: ask for `warn`, or for no level at all, when you want to see gaps. It is the +one record with **no timestamp** — the `time=` was inside the bytes that went, and +guessing one would sort a gap against real records — so `--json` reports its +`time` as Go's zero value, `0001-01-01T00:00:00Z`, and a surface rendering the +output should read that as "no time" rather than as the year 1. ### Collecting a bug report