From 82cc6be8388e2120c80e6104f49eb01601e68ce5 Mon Sep 17 00:00:00 2001 From: "@permadeath.com" Date: Wed, 26 Aug 2026 13:28:21 -0400 Subject: [PATCH] fix(logs): apply the filters, survive a bad byte, refuse an unrepresentable span MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `--incident` built its filters and never used them, so every verdict was drawn from the whole file while the text advised narrowing with `--since`. A single invalid byte took a whole generation with it, and `--since` with a huge number multiplied before it range-checked — a panic with overflow checks on, and a window in the future with them off. Change-Id: I2737bfcfcac59353d7a4e429d033926d5bfc709d --- plan/logs.md | 28 ++++++++ src/cmd/logs/render.rs | 153 +++++++++++++++++++++++++++++++++++++++-- 2 files changed, 174 insertions(+), 7 deletions(-) diff --git a/plan/logs.md b/plan/logs.md index 21a344b..7f61179 100644 --- a/plan/logs.md +++ b/plan/logs.md @@ -75,6 +75,34 @@ which is an argv. ## Done +- [x] Three defects in the reader, found by audit rather than by a report. + **`--incident` ignored every filter on the command line.** The filters + were built and then never applied on that path, so the analysis ran + over both generations — months of history — while the verdict it + printed advised narrowing with `--since`, which changed nothing. Every + conclusion an incident view draws is about a *population*: which + invocations overlapped, whether more than one login is in the window, + how often a refresh token was seen. `--lines` deliberately still does + not apply, since a verdict that moved with how many rows fit on a + screen would be worse than one drawn from too much. + **One invalid byte discarded a whole generation.** The read was + `read_to_string`, which is all-or-nothing on encoding, so the writer + killed mid-`write` that `read_all`'s doc promises to survive — cut + inside a multi-byte character — turned every well-formed line behind it + into "nothing has been recorded yet". Bytes and a lossy decode now + leave the damage in the one line it belongs to, and `live_len` is taken + off the bytes, since it is the file offset `--follow` resumes from and + a zero there reprints the file. + **`--since 99999999999999999d` multiplied before it range-checked.** + `n * seconds` on a value `parse::` accepts happily: a panic in a + build with overflow checks and, in one without, a wrapped negative + delta that subtracts to an instant in the *future* — so the window + excludes everything and the command reports "no events matched" over a + log that has them. It is a `checked_mul` into the same `Usage` refusal + every other unreadable spec gets. This reaches `--since` and `--until` + on all three `logs` subcommands and on `atgc search`, which is the same + blast radius as the byte-split bug above it in this list + - [x] Append-only OAuth event log at ~/.config/atgc/oauth.jsonl, mode 0600 — typed events for every token request (with the client_id actually sent), refusal (with the OAuth error code and a scrubbed body), store diff --git a/src/cmd/logs/render.rs b/src/cmd/logs/render.rs index acf4d80..47c6e61 100644 --- a/src/cmd/logs/render.rs +++ b/src/cmd/logs/render.rs @@ -401,9 +401,31 @@ pub(crate) fn parse_time(spec: &str, now: DateTime) -> Result _ => None, } { - let n: i64 = digits.parse().context("duration too large")?; - let delta = chrono::TimeDelta::try_seconds(n * seconds).context("duration too large")?; - return now.checked_sub_signed(delta).context("duration too large"); + // `checked_mul` and not `n * seconds`: `n` is bounded only by `i64` + // and `seconds` is up to a week's worth, so the product overflows + // for a value `parse::` accepts happily. That is not a + // theoretical edge — it is `--since 99999999999999999d`, one key + // held down. Unchecked it panics in a build with overflow checks and + // wraps in one without, and a wrapped negative delta reads as an + // instant in the *future*, which filters every event out and reports + // "no events matched" over a log that has them. + let delta = digits + .parse::() + .ok() + .and_then(|n| n.checked_mul(seconds)) + .and_then(chrono::TimeDelta::try_seconds) + .ok_or_else(|| { + crate::exit::fail( + crate::exit::Exit::Usage, + format!("{spec:?} is longer than any time this can name"), + ) + })?; + return now.checked_sub_signed(delta).ok_or_else(|| { + crate::exit::fail( + crate::exit::Exit::Usage, + format!("{spec:?} is longer than any time this can name"), + ) + }); } if let Ok(t) = DateTime::parse_from_rfc3339(spec) { @@ -721,8 +743,17 @@ fn read_all(paths: &[PathBuf]) -> (Vec>, Vec, u64) { let mut bad = Vec::new(); let mut live_len = 0; for (n, path) in paths.iter().enumerate() { - let text = match std::fs::read_to_string(path) { - Ok(text) => text, + // Bytes and a lossy decode, not `read_to_string`, which is + // all-or-nothing on encoding. A writer killed mid-`write` can leave + // one line truncated inside a multi-byte character — which is one of + // the two cases the doc above promises to survive — and a strict + // read turns that single bad byte into "this whole generation is + // unreadable", losing every well-formed line behind it and printing + // "nothing has been recorded yet" over a log full of events. + // Decoding leniently leaves the damage in the one line it belongs + // to, where `parse_line` reports it as the `Bad` entry it is. + let raw = match std::fs::read(path) { + Ok(raw) => raw, Err(e) => { bad.push(Bad { path: path.clone(), @@ -735,10 +766,14 @@ fn read_all(paths: &[PathBuf]) -> (Vec>, Vec, u64) { }; // The offset `--follow` picks up from is the byte length of the live // file as it was when we read it, not a fresh `stat` afterwards: - // anything appended between the two would be skipped silently. + // anything appended between the two would be skipped silently. Taken + // off the bytes rather than off the decoded string, because it is a + // file offset and a replacement character is not the width of what + // it replaced. if n + 1 == paths.len() { - live_len = text.len() as u64; + live_len = raw.len() as u64; } + let text = String::from_utf8_lossy(&raw); for (line_no, line) in text.lines().enumerate() { if line.trim().is_empty() { continue; @@ -879,6 +914,19 @@ pub(super) fn run( let mut out = std::io::stdout().lock(); if let Some(analyze) = analyze { + // Filtered, like every other view. An analysis draws conclusions + // from the *population* it is given — which invocations overlapped, + // whether more than one login is in the window, how often a refresh + // token was seen — so handing it the whole file while the command + // line said `--since 2h` answers a question nobody asked. The + // incident text itself tells people to narrow with `--since`, and + // doing so used to change nothing at all. + // + // `--lines` deliberately does not apply here: it is a display limit, + // and a verdict that changed with how many rows fit on a screen + // would be worse than one drawn from too much. + let mut entries = entries; + entries.retain(|e| filters.keep(e)); write!(out, "{}", analyze(&entries, &p))?; return Ok(()); } @@ -1301,6 +1349,97 @@ mod tests { } } + /// One invalid byte does not take a whole generation with it. + /// + /// `read_to_string` is all-or-nothing on encoding, so a single bad byte + /// — which is what a writer killed mid-`write` leaves when the cut lands + /// inside a multi-byte character, one of the two cases `read_all`'s own + /// doc promises to survive — used to collapse the entire file into one + /// `Bad` entry. Every well-formed line in it vanished, and the command + /// printed "nothing has been recorded yet" over a log full of events. + /// + /// Driven through a real file because `read_all` takes paths; that is + /// also what makes the `live_len` half checkable, and `live_len` is the + /// offset `--follow` resumes from, so a zero there reprints the file. + #[test] + fn one_invalid_byte_does_not_discard_the_lines_around_it() { + let dir = tempfile::tempdir().expect("a scratch dir"); + let path = dir.path().join("git.jsonl"); + let good = br#"{"ts":"2026-08-06T08:55:01Z","inv":"abc","seq":1,"event":"invocation","pid":1,"version":"0","subcommand":"pr"}"#; + let mut raw = Vec::new(); + raw.extend_from_slice(good); + raw.push(b'\n'); + // A line cut inside a two-byte character: the lead byte with nothing + // after it. + raw.extend_from_slice(b"{\"ts\":\"2026-08-06T08:55:02Z\",\"inv\":\"ab\xd0"); + raw.push(b'\n'); + raw.extend_from_slice(good); + raw.push(b'\n'); + std::fs::write(&path, &raw).expect("write the fixture"); + + let (entries, bad, live_len) = + read_all::(std::slice::from_ref(&path)); + assert_eq!( + entries.len(), + 2, + "the good lines were lost with the bad one" + ); + assert_eq!(bad.len(), 1, "the damaged line should be reported, once"); + assert_eq!( + live_len, + raw.len() as u64, + "the follow offset must be the file's own byte length" + ); + } + + /// A duration too large to represent is refused, not multiplied. + /// + /// The same shape as the byte-split above, one arithmetic operation + /// later: `n` is bounded only by `i64` and the unit multiplies it, so a + /// value `parse::` accepts can still overflow the product. This + /// build has overflow checks on and would panic; a release build has + /// them off and wraps, and a wrapped negative delta subtracts to an + /// instant in the *future*, so `--since` filters out every event and + /// reports "no events matched" over a log that has them. Both are worse + /// than the refusal every other unreadable spec gets. + #[test] + fn a_duration_too_large_to_represent_is_refused_rather_than_wrapped() { + for spec in [ + "99999999999999999d", + "9223372036854775807w", + "10000000000000000h", + ] { + match parse_time(spec, now()) { + Ok(t) => panic!("{spec} parsed as {t}"), + Err(err) => assert_eq!(classify(&err), Exit::Usage, "{spec}"), + } + } + } + + /// And the durations that do fit still work, in every unit. + /// + /// The guard above is a `checked_mul` in the middle of the one path that + /// answers `--since 2h`, so it is worth proving it did not narrow what + /// the flag accepts. + #[test] + fn the_durations_that_fit_are_unaffected() { + let now = now(); + for (spec, secs) in [ + ("30s", 30), + ("30m", 1800), + ("2h", 7200), + ("3d", 259_200), + ("1w", 604_800), + ] { + let parsed = parse_time(spec, now).unwrap_or_else(|e| panic!("{spec}: {e}")); + assert_eq!( + now - parsed, + TimeDelta::try_seconds(secs).unwrap(), + "{spec}" + ); + } + } + /// The same split with nothing in front of the unit: a single non-ASCII /// character is one byte short of a boundary all on its own, and `--since /// ✓` panicked where `--since x` had always refused. -- 2.51.2