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/docs/usage/cli.md b/docs/usage/cli.md index e62a232..cbde45e 100644 --- a/docs/usage/cli.md +++ b/docs/usage/cli.md @@ -449,6 +449,17 @@ 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. 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 ```sh 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")) + } +} 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 28780dd..1bacf11 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,74 @@ 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 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 +// 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 +229,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 +270,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 +323,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_diff_test.go b/internal/logread/logread_diff_test.go new file mode 100644 index 0000000..b7d52dc --- /dev/null +++ b/internal/logread/logread_diff_test.go @@ -0,0 +1,96 @@ +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. +// +// 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 { + 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) + } + } +} diff --git a/internal/logread/logread_test.go b/internal/logread/logread_test.go index dd5055f..8920edd 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.