From 81411256ee5845517016ebcc295dca57749f00af Mon Sep 17 00:00:00 2001 From: "@permadeath.com" Date: Sat, 15 Aug 2026 10:35:08 -0400 Subject: [PATCH] fix(logging): scrub stderr the way oauth.jsonl is already scrubbed MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `logging/oauth.rs` states that nothing secret is ever written to the log and makes that structural with `Fp`. The `--debug` channel made no such promise and kept none: `dump_err` printed `{e:#?}` raw on the same jacquard error the next line in `auth.rs` passed through `scrub_text` on its way to the log, at some thirty call sites. Both entry points into `logging/debug` scrub now, so the guarantee belongs to the channel rather than to whoever wrote the call, and `dump_err` routes through `log`, which gives a `{:#?}` dump the one-`[debug]`-per-line shape this module documents. `scrub_text` itself only blanked *quoted* values, so `access_token=abc123` walked through whole: the `=` and then the letters of the value were skipped as punctuation and the scan gave up on the first digit. The shape is reachable — `RequestError` carries the request URL, query string and all, and `{:#?}` prints it. Bare values are blanked too now, but only after an `=`, which keeps `refresh_token: None` and the word "code" in a pull request body readable under `--debug`. The doc claimed the opposite of what the code did and now says what happened. Also the one site in `auth.rs` that printed an `oauth-state` nonce in full, where every other one fingerprints it through `redact_key`. Co-Authored-By: Claude Opus 5 (1M context) --- src/auth.rs | 9 +- src/logging/debug.rs | 35 +++++- src/logging/oauth.rs | 277 +++++++++++++++++++++++++++++++++++++------ 3 files changed, 281 insertions(+), 40 deletions(-) diff --git a/src/auth.rs b/src/auth.rs index 116a4c1..95b2c6b 100644 --- a/src/auth.rs +++ b/src/auth.rs @@ -1031,7 +1031,14 @@ async fn discard_auth_state(state: Option<&str>) { Ok(()) => crate::logging::oauth::emit(crate::logging::oauth::Event::AuthStateDeleted { state: crate::logging::oauth::Fp::of(state), }), - Err(e) => crate::logging::debug::log(format!("could not discard {key}: {e}")), + // `redact_key`, not `key`: this is the one site that printed the + // nonce itself, and it prints it on the failure path of a login that + // has already gone wrong — which is exactly when someone is watching + // with `--debug` on. + Err(e) => crate::logging::debug::log(format!( + "could not discard {}: {e}", + crate::logging::oauth::redact_key(&key) + )), } } diff --git a/src/logging/debug.rs b/src/logging/debug.rs index d532f7b..72a8a84 100644 --- a/src/logging/debug.rs +++ b/src/logging/debug.rs @@ -13,18 +13,42 @@ pub fn enabled() -> bool { crate::term::say::debug_wanted() } +/// Print a message to stderr, one `[debug]` per line, scrubbed. +/// +/// The scrubbing is here rather than at the callers for the same reason [`Fp`] +/// is a type rather than a habit: a rule a hundred call sites have to remember +/// is not a rule. `oauth.jsonl` states that nothing secret is ever written to +/// it and makes that structural; this channel stated nothing and checked +/// nothing, and a token endpoint's error body reached stderr through +/// [`dump_err`] on precisely the value the next line in `auth.rs` scrubbed on +/// its way to the log. Every entry point into this module now scrubs, so the +/// promise belongs to the channel and not to whoever wrote the call. +/// +/// [`Fp`]: crate::logging::file::Fp pub fn log(msg: impl AsRef) { if enabled() { - for line in msg.as_ref().lines() { + for line in crate::logging::oauth::scrub_text(msg.as_ref()).lines() { eprintln!("[debug] {line}"); } } } /// Dump an error's full structure (jacquard errors carry the XRPC error body). +/// +/// Which is the reason it is scrubbed. `RequestError::HttpStatusWithBody` +/// formats the token endpoint's response body into both `Display` and +/// `Debug`, and `OAuthError::Request` and `session::Error::ServerAgent` are +/// both `#[error(transparent)]`, so a server that echoed the request +/// parameters back into its error arrives here whole. Values are blanked and +/// structure is kept: the flag exists to say what happened, and a dump with +/// the shape taken out of it would be no use to anyone. +/// +/// Routed through [`log`] rather than printing directly, which also makes a +/// `{:#?}` dump obey this module's one-`[debug]`-per-line rule; it used to +/// prefix the first line and leave the rest bare. pub fn dump_err(context: &str, err: &impl std::fmt::Debug) { if enabled() { - eprintln!("[debug] {context}: {err:#?}"); + log(format!("{context}: {err:#?}")); } } @@ -48,6 +72,13 @@ pub fn pretty(value: &impl serde::Serialize) -> String { /// Decode a JWT's payload segment for display. Debug aid only — no /// signature verification. +/// +/// It takes a live bearer token and is the obvious place for one to escape, +/// so: only the second of the three segments is ever returned, the signature +/// is never touched, and a token that does not decode comes back as +/// `` rather than as itself. What is left is a service-auth +/// token's `iss`, `aud`, `lxm` and `exp`, none of which is a credential — +/// and it reaches stderr through [`log`], which scrubs. pub fn jwt_claims(token: &str) -> String { fn b64url(seg: &str) -> Option> { const ALPHABET: &[u8] = b"ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz0123456789-_"; diff --git a/src/logging/oauth.rs b/src/logging/oauth.rs index fd12a2c..28bac90 100644 --- a/src/logging/oauth.rs +++ b/src/logging/oauth.rs @@ -673,53 +673,41 @@ fn granted_scope(raw: &[u8]) -> Option { /// Redact sensitive values out of arbitrary text. /// -/// [`redact_body`] handles a well-formed JSON body. This is for the other -/// route a server's words reach the log: the `Debug` and `Display` strings of -/// a jacquard error, which embed the token endpoint's response body but are -/// not themselves JSON — `HttpStatusWithBody { status: 400, body: Object -/// {"error": String("invalid_grant"), ...} }`. Without this, an error body +/// [`redact_body`] handles a well-formed JSON body. This is for every other +/// route a server's words take: the `Debug` and `Display` strings of a +/// jacquard error, which embed the token endpoint's response body but are not +/// themselves JSON — `HttpStatusWithBody { status: 400, body: Object +/// {"error": String("invalid_grant"), ...} }`. Without it, an error body /// scrubbed on the `token_refused` line would come back unscrubbed on the -/// `restore_failed` line that follows it. +/// `restore_failed` line that follows it, on stderr under `--debug`, and in +/// the sentence the failure prints for the user. /// -/// Crude by design: it finds a known key, skips whatever punctuation the -/// formatter put between the key and its value, and blanks the quoted string -/// that follows. It cannot parse, so it over-matches rather than under-matches -/// — the cost of a false positive is one unreadable field, and the cost of a -/// false negative is a credential on disk. +/// Crude by design: it finds a known key, steps over whatever punctuation the +/// formatter put between the key and its value, and blanks the value. It +/// cannot parse, so it over-matches rather than under-matches — the cost of a +/// false positive is one unreadable field, and the cost of a false negative is +/// a credential on disk. +/// +/// That claim used to be false in the direction that mattered. Only a +/// *quoted* value was blanked, so `access_token=abc123` survived whole: the +/// `=` and then the letters of the value itself were skipped as punctuation, +/// the scan halted on the first digit, and the site was abandoned because the +/// digit was not a quote. The shape is not hypothetical: jacquard's +/// `RequestError` carries the request URI in a `url` field, query string and +/// all, and `{:#?}` prints it. Both forms are handled now, and both are +/// pinned by tests. pub fn scrub_text(s: &str) -> String { let haystack = s.to_ascii_lowercase(); - let bytes = s.as_bytes(); - // (start, end) byte ranges of quoted values to blank, left to right. + // (start, end) byte ranges of values to blank, collected per key and + // merged left to right below. let mut spans: Vec<(usize, usize)> = Vec::new(); for key in SECRET_KEYS { let mut from = 0; while let Some(at) = haystack[from..].find(key) { let after = from + at + key.len(); from = after; - // The key's own closing quote, when it was written as a JSON key, - // has to be stepped over first or it is mistaken for the start of - // the value. - let mut i = after; - if i < bytes.len() && bytes[i] == b'"' { - i += 1; - } - // Skip the punctuation a formatter can put between a key and its - // value: `":`, ` = `, `: Some(`, `: String(`, and so on. - let skip = |b: u8| b.is_ascii_alphabetic() || b" \t\r\n\":=(".contains(&b); - while i < bytes.len() && skip(bytes[i]) && bytes[i] != b'"' { - i += 1; - } - if i >= bytes.len() || bytes[i] != b'"' { - continue; - } - let start = i + 1; - let mut end = start; - while end < bytes.len() && bytes[end] != b'"' { - // A backslash escapes the next byte, quote included. - end += if bytes[end] == b'\\' { 2 } else { 1 }; - } - if end <= bytes.len() && end > start { - spans.push((start, end.min(bytes.len()))); + if let Some(span) = value_after(s, after) { + spans.push(span); } } } @@ -741,6 +729,101 @@ pub fn scrub_text(s: &str) -> String { out } +/// The span of the value belonging to a secret key that ends at `after`, or +/// `None` when nothing there reads as one. +/// +/// Split out of [`scrub_text`] because it is the whole of the guesswork: the +/// outer function only finds candidate keys and stitches the result back +/// together. +fn value_after(s: &str, after: usize) -> Option<(usize, usize)> { + let bytes = s.as_bytes(); + let mut i = after; + // A JSON key's own closing quote has to be stepped over first, or it is + // mistaken for the start of the value. + if bytes.get(i) == Some(&b'"') { + i += 1; + } + // Then the punctuation a formatter puts between a key and its value: + // `":`, ` = `, `=`. At least one byte of it is required, which is what + // stops `keys_before: 3` and the `/token` in an endpoint path from being + // read as a key with a value hanging off it. + let punctuation = i; + let mut form_encoded = false; + while let Some(b) = bytes.get(i) { + match b { + b'=' => form_encoded = true, + b' ' | b'\t' | b'\r' | b'\n' | b':' => {} + _ => break, + } + i += 1; + } + if i == punctuation { + return None; + } + // Then any number of `Debug` wrappers — `Some(`, `String(` — before the + // value itself. + loop { + match bytes.get(i)? { + b'"' => return quoted_value(s, i + 1), + b if b.is_ascii_alphabetic() => { + let word = i; + while bytes + .get(i) + .is_some_and(|c| c.is_ascii_alphanumeric() || *c == b'_') + { + i += 1; + } + if bytes.get(i) != Some(&b'(') { + return form_encoded.then(|| bare_value(s, word)).flatten(); + } + i += 1; + while matches!(bytes.get(i), Some(b' ' | b'\t' | b'\r' | b'\n')) { + i += 1; + } + } + // A digit, or anything else a bare value can start with. + _ => return form_encoded.then(|| bare_value(s, i)).flatten(), + } + } +} + +/// A quoted value, from just past its opening quote to its closing one. +fn quoted_value(s: &str, start: usize) -> Option<(usize, usize)> { + let bytes = s.as_bytes(); + let mut end = start; + while end < bytes.len() && bytes[end] != b'"' { + // A backslash escapes the next byte, quote included. The boundary + // walk after it is what keeps `\` before a multi-byte character from + // producing a span that panics when it is sliced. + end += if bytes[end] == b'\\' { 2 } else { 1 }; + while end < bytes.len() && !s.is_char_boundary(end) { + end += 1; + } + } + (end > start).then_some((start, end.min(bytes.len()))) +} + +/// A bare value, blanked to the first byte that cannot be part of one. +/// +/// Only reached for `key=value`, never for `key: value`. A bare value after a +/// colon is a formatter's word — `None`, `null`, an enum variant — because +/// every `Debug` and `Display` in this chain quotes a string; a bare value +/// after an equals sign is a query parameter or a form field, which is +/// exactly where a credential travels. Gating on the `=` is what lets +/// `--debug` keep printing `refresh_token: None` and the word "code" in a +/// pull request body while `access_token=abc123` still goes. +fn bare_value(s: &str, at: usize) -> Option<(usize, usize)> { + let bytes = s.as_bytes(); + let mut end = at; + while bytes + .get(end) + .is_some_and(|b| !b"&, \t\r\n\"})];#".contains(b)) + { + end += 1; + } + (end > at).then_some((at, end)) +} + fn scrub(value: &mut serde_json::Value) { match value { serde_json::Value::Object(map) => { @@ -1190,6 +1273,126 @@ mod tests { assert_eq!(scrub_text("http status: 502"), "http status: 502"); } + /// The shape that used to walk straight through: a bare value with no + /// quotes around it. `access_token=abc123` survived the old scan + /// intact — the `=` and then `a`, `b`, `c` were all skipped as + /// punctuation, the scan stopped on `1`, and the site was abandoned + /// because `1` is not a quote. + #[test] + fn form_encoded_values_are_scrubbed_too() { + assert_eq!(scrub_text("access_token=abc123"), "access_token="); + assert_eq!( + scrub_text("grant_type=refresh_token&refresh_token=secret123"), + "grant_type=refresh_token&refresh_token=", + ); + // A value that is all digits, and one at the end of a query string. + assert_eq!( + scrub_text("client_id=http://localhost/&code=90210&state=xyz"), + "client_id=http://localhost/&code=&state=xyz", + ); + } + + /// The route that made the bare shape reachable at all: jacquard's + /// `RequestError` keeps the request URI in a `url` field, and `{:#?}` + /// prints the query string with it. The token endpoint never sees this + /// scrubbed — it is the copy atgc prints and records that matters. + #[test] + fn a_url_field_in_a_debug_dump_loses_its_query_secrets() { + #[derive(Debug)] + #[allow(dead_code)] + struct RequestError { + status: u16, + url: Option, + } + let e = RequestError { + status: 400, + url: Some( + "https://pds.example/oauth/token\ + ?grant_type=refresh_token&refresh_token=secret123" + .into(), + ), + }; + let out = scrub_text(&format!("{e:#?}")); + assert!(!out.contains("secret123"), "{out}"); + // Structure, endpoint and grant type all survive: `--debug` exists to + // say what happened, and a scrubber that blanks the line defeats it. + assert!(out.contains("status: 400"), "{out}"); + assert!(out.contains("oauth/token"), "{out}"); + assert!(out.contains("grant_type=refresh_token"), "{out}"); + } + + /// The over-matching the doc claims, bounded so that `--debug` stays + /// worth reading. A bare value is only taken after `=`, so the words a + /// formatter writes after a colon — and the word "code" in someone's + /// pull request body — come through untouched. + #[test] + fn structure_survives_the_scrubber() { + for intact in [ + "refresh_token: None", + "access_token: null", + "StoreWrite { keys_before: 4, keys_after: 3 }", + "see the code in question", + "endpoint: https://pds.example/oauth/token", + ] { + assert_eq!(scrub_text(intact), intact); + } + } + + /// The leak, built out of the real types instead of a string that looks + /// like them. + /// + /// `RequestError::HttpStatusWithBody` formats the token endpoint's + /// response body into its own `Display`, `RequestError` keeps the request + /// URL beside it, and `session::Error::ServerAgent` is + /// `#[error(transparent)]` — so an echoed credential and a query string + /// both arrive whole, in `Display` and in `Debug`. The two asserts before + /// the loop are deliberate: if upstream ever stops embedding the body, + /// they go red and say so rather than letting the rest of this test pass + /// while proving nothing. + #[test] + fn a_real_jacquard_refusal_is_scrubbed_in_both_renderings() { + use jacquard::oauth::request::RequestError; + use jacquard::oauth::session; + + let refusal = RequestError::http_status_with_body( + http::StatusCode::BAD_REQUEST, + serde_json::json!({"error": "invalid_grant", "access_token": "secret123"}), + ) + .with_url( + "https://pds.example/oauth/token\ + ?grant_type=refresh_token&refresh_token=secret456", + ); + let e = session::Error::from(refusal); + + assert!(e.to_string().contains("secret123"), "{e}"); + assert!(format!("{e:#?}").contains("secret456"), "{e:#?}"); + + for rendering in [scrub_text(&e.to_string()), scrub_text(&format!("{e:#?}"))] { + assert!(!rendering.contains("secret123"), "{rendering}"); + assert!(!rendering.contains("secret456"), "{rendering}"); + // The two facts a person needs off this error, still there. + assert!(rendering.contains("invalid_grant"), "{rendering}"); + assert!(rendering.contains("400"), "{rendering}"); + } + } + + /// A multi-byte character inside a value being blanked. The span is + /// computed in bytes and then used to slice a `&str`, so landing on a + /// continuation byte would panic — in the one code path whose whole job + /// is to run when something has already gone wrong. + #[test] + fn a_multibyte_value_does_not_split_a_character() { + let out = scrub_text(r#"{"access_token":"tok-🧬-1","error":"invalid_grant"}"#); + assert!(!out.contains("🧬"), "{out}"); + assert!(out.contains("invalid_grant"), "{out}"); + assert_eq!( + scrub_text(r#"note = "🧬" access_token=🧬secret"#) + .matches('🧬') + .count(), + 1 + ); + } + #[test] fn non_json_error_bodies_are_kept_but_bounded() { let raw = "x".repeat(5000); -- 2.51.2