//! An append-only, structured record of every OAuth operation atgc performs. //! //! # Why this exists //! //! Twice in one day a live OAuth session was destroyed without warning: //! `~/.config/atgc/sessions.json` was found emptied to `{}`. An audit of the //! code established *how* that can happen — jacquard's `SessionRegistry` //! deletes a session outright when a refresh fails with an error it //! classifies as permanent (`vendor/jacquard-oauth/src/session.rs`, the //! `e.is_permanent()` branch) — but not *why* it happened, because there are //! two plausible causes and no evidence to tell them apart: //! //! 1. **A `client_id` mismatch on refresh.** `cmd::auth::login` builds client //! metadata whose loopback `client_id` embeds an ephemeral-port redirect //! URI; every other command builds it with `None` and gets a different //! `client_id`. If the authorization server ties the grant to the //! `client_id` it was issued to, refresh presents the wrong one, gets //! `invalid_grant`, and the session is deleted. The random port makes it //! unreproducible by hand. //! 2. **A cross-process race.** Refresh tokens are single-use and rotating, //! `sessions.json` is read-modify-written whole with no locking from two //! independent code paths, and `prune_stale_sessions` deletes state keys //! belonging to other invocations. Two atgc processes overlapping can //! spend the same refresh token, and the loser gets `invalid_grant`. //! //! Both end in the same visible symptom. They are distinguishable only from //! *what was actually sent and returned*, which nothing recorded. So: this //! file records the `client_id` on every token request, the token endpoint's //! error code and body on refusal, a fingerprint of every token read and //! written, and enough per-invocation identity and sub-millisecond timing to //! see two processes interleaving. Everything else follows from that goal. //! //! # Format //! //! One JSON object per line (JSON Lines) at `~/.config/atgc/oauth.jsonl`, //! mode 0600, override with `ATGC_OAUTH_LOG`. Chosen over a location //! directly in `~` because what it describes — the session and account files //! under `~/.config/atgc/dids/` — already lives there, and a log that sits //! beside the thing it is about is the one people find. `ATGC_OAUTH_LOG=0` //! turns it off. //! //! Each line is `{"ts", "inv", "seq", "event", ...payload}`. `inv` is the //! invocation id (see [`crate::logging::file::Invocation`]); `seq` counts events within one //! invocation, so a gap is visible even if two clocks disagree. //! //! # Secrets //! //! Nothing secret is ever written here. Not access tokens, refresh tokens, //! DPoP private keys, PKCE verifiers, authorization codes or client secrets. //! Where identifying a particular token matters — proving that a rotation //! happened, or that two processes spent the same refresh token — the value //! goes through [`Fp`], which stores only the first 8 hex characters of its //! SHA-256. That is 32 bits of a preimage-resistant hash: enough to match two //! sightings of the same token against each other, useless for recovering it, //! and far too short to brute-force a match against a token you do not //! already hold. Every field in [`Event`] that could carry a secret is typed //! `Fp`, so putting a raw secret there does not compile. //! //! A fingerprint is no use for the fields that record what a *server* said, //! because the whole value of an error message is being readable. Those are //! typed [`Scrubbed`] instead, which cannot be built without going through //! [`scrub_text`] — the same guarantee moved from the type into its //! constructor. That scrubber is now also what `--debug` and the sentences //! atgc prints when a login or a refresh fails run their errors through, so //! the promise this file makes about the log covers the terminal beside it. use crate::logging::file::{Log, MAX_FIELD}; use serde::{Deserialize, Serialize}; use std::borrow::Cow; /// The fingerprint type and the clipper both live in [`crate::logging::file`] now, /// because the PDS log needs the same two. Re-exported rather than repointed /// at every call site: `oauthlog::clip` is what a hundred lines in `auth.rs` /// and `account.rs` already say, and the indirection costs nothing. pub use crate::logging::file::{Fp, clip}; /// This log: `~/.config/atgc/oauth.jsonl`, `ATGC_OAUTH_LOG` to move or /// disable it. /// /// Beside the per-identity files it is about, under `~/.config/atgc`, rather /// than directly in `~`: a log that sits next to the thing it describes is /// the one people find. pub static LOG: Log = Log::new("oauth.jsonl", "ATGC_OAUTH_LOG"); /// A `client_id` as recorded: a readable prefix plus an exact digest. /// /// atgc's loopback `client_id` is a `http://localhost/` URL with the redirect /// URI *and* the entire scope list folded into its query string, which in /// practice runs to about 850 bytes — too long to write out repeatedly in a /// 4096-byte line. Clipping alone would be a bad trade for the one comparison /// this log has to support, so both are kept: `id` is the leading 512 bytes, /// which is where the redirect URI and its ephemeral port live and so is the /// part that actually varies between a login and a refresh, and `fp` digests /// the *whole* value so two client_ids can be compared for equality by eye or /// by `jq` regardless of clipping. /// /// `fp` reuses [`Fp`] for its digest but is not concealing anything: a /// `client_id` is public by construction — it goes to the authorization /// server in the clear, and for a non-loopback client it is a URL anyone can /// fetch. #[derive(Debug, Clone, Serialize, Deserialize)] pub struct ClientId { pub id: String, pub fp: Fp, } impl ClientId { pub fn new(raw: &str) -> Self { ClientId { id: clip(raw, MAX_FIELD), fp: Fp::of(raw), } } } /// Text written by somebody else's server, with any credential in it blanked /// and the rest clipped to the field budget. /// /// [`Fp`] keeps a token out of this file by refusing to compile, but it cannot /// stand in for an error message: a fingerprint of "what the token endpoint /// said" is worthless, and the whole value of the field is being readable. So /// the guarantee is moved into the constructor instead — there is no way to /// build one of these that does not go through [`scrub_text`], and every field /// that records a foreign error is typed as one. /// /// It exists because the alternative failed. Three events record an error a /// server wrote — `authorize_failed`, `restore_failed` and /// `session_establish_failed` — and the only thing keeping their treatment /// consistent was that two of them had been written by copying the first. /// `authorize_failed` was clipped and never scrubbed. /// /// `Deserialize` takes the string as it finds it. `atgc logs oauth` is reading /// a line that was scrubbed when it was written, and scrubbing it again on the /// way out would only chew on a `` that is already there. #[derive(Debug, Clone, Serialize, Deserialize)] #[serde(transparent)] pub struct Scrubbed(String); impl Scrubbed { /// From an error's full structure. `Debug` rather than `Display` because /// a jacquard refusal lives down the chain and `Display` shows only the /// outermost link of it. pub fn of(e: &impl std::fmt::Debug) -> Self { Self::text(&format!("{e:?}")) } /// From an error on its way to a person. `Display`, because what someone /// reading a failure needs is the sentence rather than the chain — and /// for `session::Error::ServerAgent`, which is `#[error(transparent)]` /// over an error whose own `Display` is the token endpoint's response /// body, that sentence is where the credential was. pub fn shown(e: &impl std::fmt::Display) -> Self { Self::text(&e.to_string()) } /// From text atgc composed itself. Scrubbed anyway: a way in that skips /// the scrubber is the one thing this type exists not to have. pub fn text(s: &str) -> Self { Scrubbed(clip(&scrub_text(s), MAX_FIELD)) } pub fn as_str(&self) -> &str { &self.0 } } impl std::fmt::Display for Scrubbed { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { f.write_str(&self.0) } } /// Everything atgc can observe about an OAuth operation. /// /// A real enum with typed payloads rather than a message string, for two /// reasons that both come up in practice: a reader (`jq`, or a future `atgc /// logs oauth`) can match on `event` and know exactly which fields exist, and /// adding an operation is a compile-time-checked change instead of a new /// spelling nobody greps for. /// /// Serialized with `#[serde(tag = "event")]`, so the tag is a field of the /// same flat object as the payload and `jq 'select(.event=="token_refused")'` /// works without reaching into a nested value. /// /// `Deserialize` is derived alongside `Serialize` so that the reader — /// [`crate::cmd::logs::oauth`], behind `atgc logs oauth` — consumes the same enum this /// module writes rather than a second, drifting description of the format in /// JSON. /// The cost is that a line whose `event` tag this build does not know fails /// to parse; the reader reports that per line and keeps going, which is the /// right answer for a log read by a binary older than the one that wrote it. /// /// # These variants are public /// /// `atgc logs oauth --json` prints the OAuth log's lines verbatim, so /// every variant name below — as `serde` renames it, `snake_case` into the /// `event` field — and every field name in it is part of the CLI's output /// contract. `docs/output.md` says so, and the stability rules there apply: /// a new variant or a new field is a `feat`, a rename or a removal is a /// breaking `!`. Rename one here and somebody's `jq` filter stops matching. #[derive(Debug, Serialize, Deserialize)] #[serde(tag = "event", rename_all = "snake_case")] pub enum Event { /// First line of every invocation. The per-invocation facts live here and /// nowhere else; every later line carries only `inv` and refers back. /// /// Repeating them on every line would be more robust to a lost head, but /// they cost ~120 bytes each against a 4096-byte line budget that the /// token-refusal events actually need, and the head is the *least* likely /// line to be lost: it is written first, and rotation only ever happens /// before it. Cheap redundancy where it is free instead: `pid` is also /// encoded in `inv`, so even an orphaned line names its process. Invocation { pid: u32, /// From `$USER`/`$LOGNAME`. A hint about who ran this, not an /// authenticated identity — but on a shared machine it is the first /// question asked. user: Option, cwd: Option, /// `Cow` rather than `&'static str`: the writer still passes /// `env!("CARGO_PKG_VERSION")` with no allocation, and the reader, /// which has no static string to borrow from, gets an owned one. A /// borrowed `&'static str` cannot be deserialized into at all, and /// this was the only field in the enum that stood in the way of /// reading the log back through the type that writes it. version: Cow<'static, str>, /// The leading positional words of the command line — `auth login`, /// `pr resubmit`. Deliberately stops at the first flag so that no /// flag *value* (a PR body, a title) is ever recorded. subcommand: String, /// Where `sessions.json` was expected, so a log from a different /// `HOME` is obvious. store: Option, /// Set when this invocation rotated the log on startup, giving the /// size that triggered it. Explains a short file. rotated_from_bytes: Option, }, // ---- sessions.json as a whole file ------------------------------------- // atgc reads, edits and rewrites the store wholesale in several places // with no locking. These four events make a destructive rewrite visible // as such, and let two overlapping read-modify-write cycles be lined up // against each other by timestamp. /// The store file was read in full. StoreRead { path: String, present: bool, bytes: u64, keys: usize, /// Keys under `oauth:` — actual sessions. sessions: usize, /// Keys under `oauth-state:` — in-flight authorization requests. states: usize, error: Option, }, /// The store file was rewritten whole. /// /// `keys_before`/`keys_after` are the point of this event: a write that /// drops keys is the shape of the incident, and it should be visible as /// one line without cross-referencing anything. StoreWrite { path: String, /// What the caller said this write was for. A destructive write whose /// reason is `logout` is the tool doing as it was told; the same write /// with reason `unspecified` is a bug. reason: Reason, keys_before: usize, keys_after: usize, /// Which keys went away. Store keys are `oauth:/` /// and `oauth-state:`; the state values are random nonces /// rather than secrets, but they are fingerprinted anyway by /// [`redact_key`] on the principle that a nonce that gates a token /// exchange is not something to write down. removed: Vec, error: Option, }, // ---- individual session records ---------------------------------------- // These come from the wrapping store in `auth::LoggedAuthStore`, so they // fire for jacquard's own accesses too — including the delete on a // permanent refresh failure, which is the event the whole file is for. SessionGet { did: String, session_id: String, found: bool, /// Fingerprints, never values. Two invocations reporting the same /// `refresh_token` fingerprint and then one of them failing is the /// signature of the race hypothesis. access_token: Option, refresh_token: Option, expires_at: Option, error: Option, }, SessionUpsert { did: String, session_id: String, access_token: Option, refresh_token: Option, expires_at: Option, scope: Option, error: Option, }, /// A session record was removed. `reason` is what the caller said it was /// doing; jacquard's own delete arrives as [`Reason::VendorRegistry`], /// which is the permanent-refresh-failure path. SessionDelete { did: String, session_id: String, reason: Reason, error: Option, }, SessionKeysListed { count: usize, error: Option, }, // ---- authorization request state (PKCE) -------------------------------- // The `oauth-state:` keys. `prune_stale_sessions` and `logout` both // delete every one of them, including ones belonging to another // invocation's in-flight login — which is one concrete way two processes // interfere. Logging both sides makes that visible. AuthStateSaved { state: Fp, }, AuthStateGet { state: Fp, found: bool, }, AuthStateDeleted { state: Fp, }, /// `oauth::sessions::prune_stale_sessions`, broken out from [`Event::StoreWrite`] /// because it is the one write with a policy behind it: keep this DID's /// newest session, drop its older ones, drop every state key regardless /// of owner. Prune { did: String, keep_session_id: String, keys_before: usize, keys_after: usize, removed_sessions: Vec, /// State keys removed. Counted rather than named because they may /// belong to another live invocation and the count is the point. removed_states: usize, }, // ---- the browser flow -------------------------------------------------- /// A login is starting. `client_id` here is the one baked with *this* /// invocation's ephemeral redirect port; compare it against the /// `client_id` on a later `token_request` with `grant_type` `refresh_token` /// and hypothesis 1 is settled either way. AuthorizeStart { handle: String, redirect_uri: String, port: u16, client_id: ClientId, scopes: String, }, /// `start_auth` came back with a URL. Emitted for the elapsed time and /// nothing else: everything between it and `authorize_start` is network — /// resolving the handle, then fetching the PDS's protected-resource /// metadata and the authorization server's — against hosts atgc has never /// contacted, any of which can be slow or unreachable. /// /// Without it an `authorize_start` with nothing after it has two readings, /// "the resolve is still going" and "the browser was never used", and the /// log cannot tell them apart. With it, an `authorize_start` alone means /// the first and the pair means the second. AuthorizeReady { handle: String, elapsed_ms: u64, }, AuthorizeFailed { handle: String, error: Scrubbed, /// How long the attempt ran before failing. `#[serde(default)]` so /// that lines written before this field existed still parse; a zero /// there means "not recorded", which no real attempt reaches. #[serde(default)] elapsed_ms: u64, }, /// What happened when the authorization URL was handed to a browser. /// /// An `authorize_ready` with no `callback` after it has two readings — /// the consent page was shown and abandoned, or nothing ever showed it /// — and they call for opposite fixes. This event separates them: it /// says whether a browser was launched at all, and which of the two /// ways it was not. `opened` is only the launcher's exit status, so it /// still allows "a browser started and put the page somewhere the user /// could not see". BrowserOpen { /// `opened`, `failed` or `skipped` — `noinput::BrowserOpen` /// spelled out, one field rather than a bool and a reason that /// could disagree with each other. outcome: String, }, /// A request arrived on the loopback listener. Callback { port: u16, path: String, has_code: bool, has_state: bool, iss: Option, /// The authorization code is a single-use credential, so only its /// fingerprint is kept — enough to prove the same code was replayed. code: Option, /// The request did not carry this login's `state`, so it was answered /// and the listener went back to waiting. Anything that can reach an /// ephemeral port on 127.0.0.1 can produce one of these, which is /// exactly why they are recorded rather than dropped: a login that /// timed out with a dozen of these in the log was scanned, and that /// is a different diagnosis from a browser that never arrived. /// /// `default` because logs written before this field existed have no /// opinion about it, and every one of those was a callback that was /// acted on. #[serde(default)] ignored: bool, }, CallbackFailed { reason: String, }, /// The code-for-token exchange came back and a session exists. SessionEstablished { did: String, session_id: String, }, SessionEstablishFailed { error: Scrubbed, }, // ---- the token endpoint ------------------------------------------------ // Sourced from [`LoggedHttpClient`], which sits under jacquard as the // HTTP transport. That is deliberately the lowest layer available: it // reads `client_id` and `grant_type` out of the form body that is about // to go on the wire, so these events record what was *sent*, not what // atgc believed it had configured. A patch to the vendored crate would // have recorded the latter. /// About to POST to the token endpoint. Emitted *before* the request, so /// a request that never returns still leaves a trace. TokenRequest { /// From the request body: `authorization_code`, `refresh_token`, or /// absent for PAR and revocation, which carry no grant type. grant_type: Option, endpoint: String, /// **The field this log was built for.** The `client_id` actually /// serialized into the request body, not the one we meant to send. client_id: ClientId, }, TokenGranted { grant_type: Option, endpoint: String, client_id: ClientId, http_status: u16, /// What the grant actually covers, as the authorization server /// worded it — see [`granted_scope`] for why this one field of a /// success body is recorded when none of the others is. scope: Option, elapsed_ms: u64, }, /// The token endpoint refused. Carries everything needed to tell /// `invalid_grant` ("that refresh token is spent or was never yours") /// from `invalid_client` ("that client_id is not who this grant was /// issued to") without guessing. TokenRefused { grant_type: Option, endpoint: String, client_id: ClientId, http_status: u16, /// OAuth `error` code from the response body, when it parsed as JSON. oauth_error: Option, error_description: Option, /// A bounded, key-redacted excerpt of the body. Token endpoints /// sometimes echo request parameters back in an error, so this is /// scrubbed by [`redact_body`] before it is stored, not just clipped. body: String, elapsed_ms: u64, }, /// The request never reached a status code. TokenTransportError { grant_type: Option, endpoint: String, client_id: ClientId, error: Scrubbed, elapsed_ms: u64, }, // ---- atgc-side session use --------------------------------------------- /// `cmd::auth::agent_for_did` is about to resume a session, which is what /// triggers a refresh. `client_id` is the one this resume will present at /// the token endpoint, and it should be identical to the one on the /// `authorize_start` that created the grant — that equality is the fix /// for the session-destruction incident, and this pair of lines is how /// you check it still holds. Restore { did: String, session_id: String, client_id: ClientId, /// Whether the `client_id` above is the one the grant was actually /// issued to or a guess. A `unrecorded` here on a session that then /// fails to refresh is not a regression: it is a grant from before /// atgc recorded this, and it needs one more login. /// /// Defaulted on read: every `restore` line written before this field /// existed was, by definition, a guess. #[serde(default)] client_id_source: ClientIdSource, /// Which of the account's grants this invocation resumed — `human` or /// `agent`. /// /// One account can hold both, and every visible thing they produce is /// identical: same DID, same records, same author. So when somebody /// asks afterwards whether an agent published as them, this field is /// the only place the answer exists. That is the same reason the rest /// of this file exists — see the module header on the incident that /// produced it. /// /// Defaulted on read: a `restore` written before planes was, by /// definition, a person's. #[serde(default = "human_plane")] plane: String, }, /// A resume refused because the account holds no grant on this plane. /// /// Distinct from [`Event::RestoreFailed`], which is a session that exists /// and would not come back. This one never got that far: the credential /// asked for is not there, and the one that *is* there belongs to /// somebody else — which is a refusal worth telling apart from a broken /// session when reading a log after the fact. PlaneRefused { did: String, /// The plane this process is on, and therefore the grant it wanted. wanted: String, /// The plane whose grant the account does hold, when it holds one. held: Option, }, RestoreFailed { did: String, session_id: String, error: Scrubbed, }, Logout { all: bool, targets: Vec, keys_before: usize, keys_after: usize, }, // ---- the account registry ---------------------------------------------- RegistryRead { path: String, present: bool, accounts: usize, /// The registry's default-account pointer. `alias` because the field /// was `active` until the pointer was renamed, and a log is read long /// after it is written — an incident from last month must not lose a /// column because the spelling moved. #[serde(alias = "active")] default: Option, error: Option, }, RegistryWrite { path: String, accounts: usize, #[serde(alias = "active")] default: Option, error: Option, }, /// Which rule picked the account to act as. A session destroyed while the /// "wrong" account was selected is a different bug from one destroyed /// under the right account. AccountSelected { did: String, handle: Option, /// `--account`, `ATGC_ACCOUNT`, this repo's .git/config, and so on — /// `account::Source::describe`. source: String, }, AccountSelectFailed { error: String, }, /// A record was too long to write atomically and was dropped. Named so /// that a hole in the log is never mistaken for silence. Oversize { of: String, bytes: usize, }, // ---- the config-directory lock ------------------------------------------ // `crate::config::lock` serializes the read-modify-write cycles these events // otherwise only let you reconstruct after the fact. These two are the // evidence that it works: a `waited_ms` above zero is one process having // been made to queue behind another, which is the interleaving that used // to happen silently and destructively instead. /// The lock was taken, or waited for and given up on. Lock { purpose: Purpose, /// Time spent waiting. Zero is the ordinary case — nobody else held /// it. Anything else is a real overlap, and pairs with the /// [`Event::LockReleased`] of whoever was ahead. waited_ms: u64, /// False when the wait ran out, or `flock` refused outright. The /// caller does **not** go on to touch the store in that case — it /// fails — so this line is the end of that invocation's dealings /// with account state rather than a warning attached to a write that /// happened anyway. acquired: bool, }, /// A held lock was released. /// /// `held_ms` is what makes a wait on the other side explicable: a /// [`Purpose::Refresh`] hold covers a network round trip and is /// legitimately the long one, while a hold of that length for /// [`Purpose::Store`] would mean something is wrong. LockReleased { purpose: Purpose, held_ms: u64, }, } /// The plane a `restore` line written before planes was made on. fn human_plane() -> String { "human".to_string() } /// What a caller took the config-directory lock for. /// /// Typed for the same reason [`Reason`] is: the interesting question about a /// wait is what the process ahead was doing, and "a refresh was in flight" and /// "someone was rewriting the store" call for different conclusions. #[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)] #[serde(rename_all = "snake_case")] pub enum Purpose { /// A token refresh: read the session, spend the refresh token on the /// network, write the rotated one back. The only hold that spans I/O, /// and the only one whose absence can destroy a grant rather than lose /// an edit. Refresh, /// A whole-file read-modify-write of `sessions.json`. Store, /// A whole-file read-modify-write of `accounts.json`. Registry, } /// Where the `client_id` on a resume came from. /// /// A loopback `client_id` embeds the login's ephemeral redirect port, so it /// cannot be derived — it is either the string recorded at login or a /// different client wearing the same name. Recording which of the two went on /// the wire is what makes a future refusal readable: `granted` plus a refusal /// is a new bug, `unrecorded` plus a refusal is the old one, already /// diagnosed, on a session that predates the fix. /// /// `Default` is `Unrecorded` so that `logs oauth` reading a line written before /// this field existed takes it for what it was: a guess. #[derive(Debug, Clone, Copy, Default, PartialEq, Eq, Serialize, Deserialize)] #[serde(rename_all = "snake_case")] pub enum ClientIdSource { /// Read back from the account registry: the one the grant was issued to. Granted, /// Nothing was recorded for this account, so the metadata was built the /// old way and this is very likely the wrong client. #[default] Unrecorded, } /// Why a session record was deleted. /// /// Typed rather than a string because the whole point is telling apart a /// deletion the user asked for from one jacquard performed on its own. #[derive(Debug, Clone, Copy, Serialize, Deserialize)] #[serde(rename_all = "snake_case")] pub enum Reason { /// `atgc auth logout`. Logout, /// A session record inserted or replaced — a fresh login, a rotated /// token set, a moved DPoP nonce. The ordinary write, and the one that /// used to reach disk through jacquard without appearing here at all. Upsert, /// An in-flight authorization request saved before the browser opens, or /// dropped once its callback has been handled or abandoned. AuthState, /// `oauth::sessions::prune_stale_sessions`: superseded by a fresh login of the same /// account. Prune, /// jacquard's `SessionRegistry` deleted it: a refresh failed and /// `is_permanent()` returned true. **This is the deletion that emptied /// the store.** VendorRegistry, /// A path that did not say which it was. Nothing constructs this today; /// it exists so that a future caller of `write_store` that forgets to /// classify itself is visible in the log as unclassified rather than /// mislabelled as one of the deliberate cases. #[allow(dead_code)] Unspecified, } /// Redact a session-store key for logging. /// /// `oauth:/` is kept verbatim — a DID is public and the /// session id is a store-local label, and both are needed to line two /// invocations up. `oauth-state:` is fingerprinted: that value is the /// random nonce a callback is matched against, and while it is not a /// credential on its own it gates one. pub fn redact_key(key: &str) -> String { match key.strip_prefix("oauth-state:") { Some(state) => format!("oauth-state:{}", Fp::of(state).as_str()), None => clip(key, MAX_FIELD), } } /// Fields an error body must never echo back into this file. /// /// A token endpoint's error response is written by someone else's server and /// has been known to include the request parameters that caused it. That is /// the one place a secret could reach this log without any atgc code asking /// for it, so every JSON key is checked against this list before the body is /// recorded. const SECRET_KEYS: &[&str] = &[ "access_token", "refresh_token", "id_token", "code", "code_verifier", "client_assertion", "client_secret", "dpop", "dpop_proof", "authorization", "assertion", "jwk", "key", "password", "token", ]; /// Scrub and bound a token-endpoint error body. /// /// JSON is walked and any value under a suspicious key replaced; anything /// that is not JSON is treated as opaque and only clipped, since a /// non-JSON error page is HTML or a proxy banner rather than an echo of the /// request. Returns the excerpt plus the parsed `error`/`error_description` /// when present. /// /// One residual risk, stated rather than papered over: `error_description` is /// free text written by someone else's server and is recorded verbatim, since /// its whole value is being readable. A server that put a credential in its /// human-readable error message would put it in this log. No ATProto PDS is /// known to do that, the field is bounded, and the alternative — dropping the /// one field that says what went wrong — would defeat the log's purpose. pub fn redact_body(raw: &[u8]) -> (String, Option, Option) { let text = String::from_utf8_lossy(raw); match serde_json::from_str::(&text) { Ok(mut value) => { let oauth_error = value .get("error") .and_then(|v| v.as_str()) .map(|s| clip(s, 128)); let description = value .get("error_description") .and_then(|v| v.as_str()) .map(|s| clip(s, MAX_FIELD)); scrub(&mut value); ( clip(&value.to_string(), MAX_FIELD), oauth_error, description, ) } Err(_) => (clip(text.trim(), MAX_FIELD), None, None), } } /// The `scope` a successful token response granted, and nothing else from it. /// /// The one field of a success body this log records, against the rule that /// [`redact_body`]'s neighbours state: a success body *is* the tokens. `scope` /// is not a credential — it is the list of things those tokens are allowed to /// do, published to the client in the clear, and already recorded on the way /// out as `authorize_start`'s `scopes`. What was missing was the other half: /// what came back. /// /// That gap cost a real diagnosis. bsky.social granted a scope jacquard could /// not parse, atgc aborted inside the callback, and the log held a /// `token_granted` with a status and an elapsed time and no way to tell which /// word had done it — the string existed only in a response body that was /// deliberately never written down. Extracted by name rather than by /// scrubbing the body, so nothing else in it can arrive here by accident. /// /// Clipped well past [`MAX_FIELD`] on purpose. A granular grant runs to the /// better part of a kilobyte and the tokens that sort last are the newest /// ones — exactly what a truncation would take — while the line as a whole /// still lands under [`crate::logging::file::MAX_LINE`]. fn granted_scope(raw: &[u8]) -> Option { let text = std::str::from_utf8(raw).ok()?; let value: serde_json::Value = serde_json::from_str(text).ok()?; value .get("scope") .and_then(|v| v.as_str()) .map(|s| clip(s, 2048)) } /// Redact sensitive values out of arbitrary text. /// /// [`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, on stderr under `--debug`, and in /// the sentence the failure prints for the user. /// /// 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(); // (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; if let Some(span) = value_after(s, after) { spans.push(span); } } } if spans.is_empty() { return s.to_string(); } spans.sort_unstable(); let mut out = String::with_capacity(s.len()); let mut cursor = 0; for (start, end) in spans { if start < cursor { continue; } out.push_str(&s[cursor..start]); out.push_str(""); cursor = end; } out.push_str(&s[cursor..]); 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 let Some(next) = quote_at(bytes, i) { i = next; } // 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 { if let Some(start) = quote_at(bytes, i) { return quoted_value(s, start, bytes[i] == b'\\'); } match bytes.get(i)? { 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 double quote at `i`, plain or backslash-escaped, and the index past it. /// /// The escaped spelling is not decoration. A body that did not parse as JSON /// is kept as an opaque string, and when that string is a JSON document it /// comes back out of a `Debug` formatter with every quote in it escaped — /// `body: String("{\"access_token\": \"…\"}")`. Reading only the plain /// spelling walked straight past that shape. fn quote_at(bytes: &[u8], i: usize) -> Option { match bytes.get(i) { Some(b'"') => Some(i + 1), Some(b'\\') if bytes.get(i + 1) == Some(&b'"') => Some(i + 2), _ => None, } } /// A quoted value, from just past its opening quote to its closing one. fn quoted_value(s: &str, start: usize, escaped: bool) -> Option<(usize, usize)> { let bytes = s.as_bytes(); let mut end = start; while end < bytes.len() { if escaped { // The closing quote is `\"`, and a lone `\` is part of the value. if bytes[end] == b'\\' && bytes.get(end + 1) == Some(&b'"') { break; } end += 1; } else { if bytes[end] == b'"' { break; } // A backslash escapes the next byte, quote included. end += if bytes[end] == b'\\' { 2 } else { 1 }; } // The boundary walk is what keeps a `\` before a multi-byte character // from producing a span that panics when it is sliced. 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) => { for (key, v) in map.iter_mut() { let lower = key.to_ascii_lowercase(); if SECRET_KEYS.iter().any(|k| lower.contains(k)) { *v = serde_json::Value::String("".into()); } else { scrub(v); } } } serde_json::Value::Array(items) => items.iter_mut().for_each(scrub), serde_json::Value::String(s) if s.len() > MAX_FIELD => *s = clip(s, MAX_FIELD), _ => {} } } /// Open the log and record the invocation. Called once, from `main`. /// /// `args` is the raw command line; only its leading positional words are /// kept, which is what keeps a PR body or a title out of the log. pub fn init(args: &[String]) { LOG.open(); let Some(head) = LOG.head(args) else { return }; emit(Event::Invocation { pid: head.pid, user: head.user, cwd: head.cwd, version: Cow::Borrowed(head.version), subcommand: head.subcommand, // The directory the per-identity stores live under. There is no one // store file to name any more, and the directory is what a reader // needs to find them all. store: crate::config::dir::config_dir() .ok() .map(|d| d.join("dids").display().to_string()), rotated_from_bytes: head.rotated_from_bytes, }); } /// Append one event. Never fails, never blocks a command. pub fn emit(event: Event) { LOG.emit(event, |of, bytes| Event::Oversize { of, bytes }); } // =========================================================================== // Instrumentation // =========================================================================== // // Both observers live here rather than in `auth.rs` for one reason: this is // the file that promises no secret is ever written, and that promise is only // auditable if everything that *could* write one is in front of you at once. // Between them they cover every OAuth operation without a single line of // patch to `vendor/jacquard-oauth`, which is worth saying plainly because the // obvious plan was to patch it: // // - [`LoggedHttpClient`] sits under jacquard as the transport, so it sees // every token-endpoint request and response as bytes. That is strictly // better than a patch at `request::oauth_request` would have been: it // records the `client_id` that went on the wire rather than the one the // crate believed it configured, and it sees the two failure shapes // jacquard's own error type throws away — a 5xx (whose body is dropped) // and a 4xx with a non-JSON body (which becomes an opaque "json error"). // - [`LoggedAuthStore`] wraps the session store, so it sees every session // read, write and delete — including the delete jacquard performs on a // permanent refresh failure, which is the event this whole file exists for. use jacquard::common::bos::BosStr; use jacquard::common::http_client::HttpClient; use jacquard::common::session::{SessionKey, SessionStoreError}; use jacquard::oauth::authstore::ClientAuthStore; use jacquard::oauth::session::{AuthRequestData, ClientSessionData}; use jacquard::types::string::Did; /// A `reqwest::Client` that records OAuth token-endpoint traffic on its way /// past. #[derive(Debug, Clone)] pub struct LoggedHttpClient(pub reqwest::Client); /// What a token-endpoint request body tells us about itself. /// /// Deliberately only two fields. The body also holds `code`, /// `code_verifier`, `refresh_token` and `client_assertion`, and the way to /// be sure none of them is ever logged is to never extract them: this struct /// is the complete set of things [`LoggedHttpClient`] can know about a /// request body, so there is nothing else for a later change to leak. #[derive(Debug, PartialEq, Eq)] pub struct FormIdentity { pub client_id: String, pub grant_type: Option, } /// Pick `client_id` and `grant_type` out of a form-encoded request body, if /// it looks like an OAuth client request at all. /// /// `client_id` present is the test for "this is a token-endpoint request". /// It is required on every request atgc's public client makes to the /// authorization server — token, refresh, PAR and revocation — and appears /// on nothing else jacquard sends, so it filters out the XRPC traffic, /// DID-document fetches and metadata lookups that share this transport /// without needing to know any endpoint URLs in advance. pub fn form_identity(body: &[u8]) -> Option { let body = std::str::from_utf8(body).ok()?; let mut client_id = None; let mut grant_type = None; for pair in body.split('&') { let (k, v) = pair.split_once('=')?; match k { "client_id" => { client_id = Some(crate::clients::atproto::oauth::login::percent_decode(v)) } "grant_type" => { grant_type = Some(crate::clients::atproto::oauth::login::percent_decode(v)) } _ => {} } } Some(FormIdentity { // Unclipped on purpose: `ClientId::new` needs the whole value to // digest it, and does the clipping itself. client_id: client_id?, grant_type: grant_type.map(|g| clip(&g, 64)), }) } impl HttpClient for LoggedHttpClient { type Error = reqwest::Error; async fn send_http( &self, request: http::Request>, ) -> Result>, Self::Error> { // Note what this does *not* touch: headers. The DPoP proof is a // header, and it is a signed assertion bound to this request. It is // never read here and never will be. let identity = form_identity(request.body()); let endpoint = clip(&request.uri().to_string(), MAX_FIELD); let (grant_type, client_id) = match &identity { Some(id) => (id.grant_type.clone(), ClientId::new(&id.client_id)), None => (None, ClientId::new("")), }; if identity.is_some() { emit(Event::TokenRequest { grant_type: grant_type.clone(), endpoint: endpoint.clone(), client_id: client_id.clone(), }); } let started = std::time::Instant::now(); let result = self.0.send_http(request).await; if identity.is_none() { return result; } let elapsed_ms = started.elapsed().as_millis().min(u64::MAX as u128) as u64; match &result { Ok(response) if response.status().is_success() => emit(Event::TokenGranted { grant_type, endpoint, client_id, http_status: response.status().as_u16(), scope: granted_scope(response.body()), elapsed_ms, }), Ok(response) => { // A refusal is the one place a response body is recorded, and // a successful one never is — the success body *is* the // tokens. `redact_body` scrubs the failure body as well, // because a token endpoint may echo the parameters that // caused the error. let (body, oauth_error, error_description) = redact_body(response.body()); emit(Event::TokenRefused { grant_type, endpoint, client_id, http_status: response.status().as_u16(), oauth_error, error_description, body, elapsed_ms, }); } Err(e) => emit(Event::TokenTransportError { grant_type, endpoint, client_id, // A `reqwest::Error` names the URL it was calling, which for // the token endpoint is a bare POST target. Typed the same as // the rest anyway, so that "every field holding a foreign // error is `Scrubbed`" is a sentence the compiler checks. error: Scrubbed::shown(&e), elapsed_ms, }), } result } } /// A [`crate::clients::atproto::oauth::store::SessionStore`] that records /// every session-record /// access. /// /// Placed between jacquard and the file rather than at atgc's own call /// sites, so it catches jacquard's accesses too — which are the interesting /// ones. atgc never calls `delete_session` itself: it edits the store file /// wholesale (see [`Event::StoreWrite`]). So a `session_delete` in this log /// can only have come from jacquard's `SessionRegistry`, and jacquard only /// deletes in one place — the `is_permanent()` branch of `get_refreshed`, /// after a refresh failed with `invalid_grant` or `access_denied`. That is /// what makes [`Reason::VendorRegistry`] a statement about the *reason* and /// not just the caller, and it is why no patch to the vendored crate was /// needed to capture the classification: the deletion is the classification. pub struct LoggedAuthStore(pub crate::clients::atproto::oauth::store::SessionStore); impl std::fmt::Debug for LoggedAuthStore { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { f.debug_tuple("LoggedAuthStore").field(&self.0).finish() } } /// Summarize a session record for the log. Tokens become fingerprints here /// and only here. fn session_fields( s: &ClientSessionData, ) -> (Option, Option, Option, Option) { ( Some(Fp::of(s.token_set.access_token.as_ref())), Fp::opt(s.token_set.refresh_token.as_deref()), s.token_set .expires_at .as_ref() .map(|d| d.as_str().to_string()), s.token_set.scope.as_deref().map(|s| clip(s, MAX_FIELD)), ) } impl ClientAuthStore for LoggedAuthStore { async fn get_session( &self, did: &Did, session_id: &str, ) -> Result, SessionStoreError> { let result = self.0.get_session(did, session_id).await; let found = matches!(result, Ok(Some(_))); let (access_token, refresh_token, expires_at, _) = match &result { Ok(Some(s)) => session_fields(s), _ => (None, None, None, None), }; emit(Event::SessionGet { did: did.as_str().to_string(), session_id: clip(session_id, MAX_FIELD), found, access_token, refresh_token, expires_at, error: result .as_ref() .err() .map(|e| clip(&e.to_string(), MAX_FIELD)), }); result } /// An upsert that would change nothing writes nothing. /// /// jacquard's `OAuthClient::restore` ends by handing the session it has /// just read straight back to the store — `create_session` calls /// `SessionRegistry::set` on the value `get_refreshed` returned — so an /// invocation that resumes a session and finds its token nowhere near /// expiry still rewrote the whole credential file with the bytes already /// in it. Measured on this machine's own `oauth.jsonl`: 51 of 55 /// `session_upsert` records carried an access token identical to the /// `session_get` microseconds before them. /// /// Comparing first turns those into no write at all, which is a better /// answer than making them atomic or taking a lock around them: the /// cheapest whole-file rewrite to get right is the one that does not /// happen. What is left is the writes that carry a change — a rotated /// token set, a new login, a moved nonce — and those are worth a file /// rewrite and the exclusion that goes with it. /// /// The comparison itself lives one layer down, in /// [`crate::clients::atproto::oauth::store::SessionStore::put`], which compares the /// *serialized* record against the bytes already at that key. Doing it /// there rather than here is what keeps it to one file read: this wrapper /// would have to read the store a second time to answer the same /// question, on the hot path of every authenticated invocation. /// /// The event is still emitted, and deliberately. [`LoggedAuthStore`] /// records what *jacquard* asked for; [`Event::StoreWrite`] records what /// happened to the file. Keeping both means a `session_upsert` with no /// `store_write` after it is exactly the signature of an elided write, /// which is how this change is checked in the log rather than asserted. async fn upsert_session(&self, session: ClientSessionData) -> Result<(), SessionStoreError> { let did = session.account_did.as_str().to_string(); let session_id = clip(session.session_id.as_ref(), MAX_FIELD); let (access_token, refresh_token, expires_at, scope) = session_fields(&session); let result = self.0.upsert_session(session).await; emit(Event::SessionUpsert { did, session_id, access_token, refresh_token, expires_at, scope, error: result .as_ref() .err() .map(|e| clip(&e.to_string(), MAX_FIELD)), }); result } async fn delete_session( &self, did: &Did, session_id: &str, ) -> Result<(), SessionStoreError> { let result = self.0.delete_session(did, session_id).await; emit(Event::SessionDelete { did: did.as_str().to_string(), session_id: clip(session_id, MAX_FIELD), reason: Reason::VendorRegistry, error: result .as_ref() .err() .map(|e| clip(&e.to_string(), MAX_FIELD)), }); result } async fn get_auth_req_info( &self, state: &str, ) -> Result, SessionStoreError> { let result = self.0.get_auth_req_info(state).await; emit(Event::AuthStateGet { state: Fp::of(state), found: matches!(result, Ok(Some(_))), }); result } async fn save_auth_req_info( &self, auth_req_info: &AuthRequestData, ) -> Result<(), SessionStoreError> { // `auth_req_info` also carries the PKCE verifier and a private DPoP // key. Only the state is touched, and only as a fingerprint. emit(Event::AuthStateSaved { state: Fp::of(auth_req_info.state.as_ref()), }); self.0.save_auth_req_info(auth_req_info).await } async fn delete_auth_req_info(&self, state: &str) -> Result<(), SessionStoreError> { emit(Event::AuthStateDeleted { state: Fp::of(state), }); self.0.delete_auth_req_info(state).await } async fn list_session_keys(&self) -> Result, SessionStoreError> { let result = self.0.list_session_keys().await; emit(Event::SessionKeysListed { count: result.as_ref().map(|k| k.len()).unwrap_or(0), error: result .as_ref() .err() .map(|e| clip(&e.to_string(), MAX_FIELD)), }); result } /// atgc's store is a file in a directory every invocation shares, so /// this is the case the hook exists for: hand the registry the /// config-directory lock and let it hold it across the read, the token /// request and the write. /// /// Nothing is logged here — [`crate::config::lock`] logs both ends itself, with /// the wait and the hold, which is more than this could say. /// /// A failure to take the lock fails the refresh, which is the whole /// point: refreshing unserialized is how two processes spend one /// single-use token and one of them gets a live session deleted. The /// error arrives at jacquard as `Error::Store`, which `is_permanent` /// reports as false, so this cannot be mistaken for the very failure it /// exists to prevent. /// `take_reentrant`, not `take_async`: `get_refreshed` calls /// `upsert_session` and `delete_session` *inside* the guard it is handed, /// and those now take the lock too. Publishing this context as the holder /// is what lets them inherit it instead of waiting out `WAIT` on this /// process's own hold and failing — on the one write that carries freshly /// rotated tokens. async fn lock_for_refresh( &self, did: &str, ) -> Result>, SessionStoreError> { let guard = crate::config::lock::take_reentrant( self.0.root(), Purpose::Refresh, crate::config::lock::Scope::Identity(did.to_string()), ) .await .map_err(|e| SessionStoreError::Other(e.into()))?; Ok(Some(Box::new(guard))) } } #[cfg(test)] mod tests { use super::*; use crate::logging::file::{MAX_LINE, line_for_test}; use std::io::Write; /// The writer and the reader share one description of the format. A /// record written by [`emit`] must come back as the same event, or `atgc /// logs oauth` is reading a file nobody writes. #[test] fn an_event_survives_a_round_trip_through_json() { let event = Event::TokenRefused { grant_type: Some("refresh_token".into()), endpoint: "https://pds.example/oauth/token".into(), client_id: ClientId::new("http://localhost/?redirect_uri=x"), http_status: 400, oauth_error: Some("invalid_grant".into()), error_description: Some("token is spent".into()), body: "{\"error\":\"invalid_grant\"}".into(), elapsed_ms: 12, }; let line = line_for_test(&event); let back: Event = serde_json::from_slice(&line).expect("the writer's own line parses"); match back { Event::TokenRefused { client_id, oauth_error, .. } => { assert_eq!( client_id.fp, ClientId::new("http://localhost/?redirect_uri=x").fp ); assert_eq!(oauth_error.as_deref(), Some("invalid_grant")); } other => panic!("came back as {other:?}"), } } /// The one field of a success body that is recorded, and the proof that /// it is the only one: a token response carries the tokens themselves in /// the same object, and this walks past all of them. #[test] fn a_grant_records_its_scope_and_nothing_else_from_the_body() { let raw = br#"{"access_token":"tok-abc","refresh_token":"ref-abc", "token_type":"DPoP","sub":"did:plc:abc","expires_in":3600, "scope":"atproto repo:sh.tangled.repo repo:"}"#; let scope = granted_scope(raw).expect("a token response says what it granted"); assert_eq!(scope, "atproto repo:sh.tangled.repo repo:"); assert!(!scope.contains("tok-abc") && !scope.contains("ref-abc")); // A body with no scope, and one that is not JSON at all, are both // "nothing to record" rather than something to guess at. assert_eq!(granted_scope(br#"{"access_token":"tok-abc"}"#), None); assert_eq!(granted_scope(b"proxy banner"), None); // Bounded, but far past MAX_FIELD: the tokens that sort last are the // ones a truncation would take, and they are the interesting ones. let long = format!(r#"{{"scope":"{}"}}"#, "repo:sh.tangled.repo ".repeat(200)); let clipped = granted_scope(long.as_bytes()).expect("still a scope"); assert!(clipped.len() > MAX_FIELD && clipped.len() < MAX_LINE); } #[test] fn error_bodies_are_scrubbed_of_echoed_credentials() { let raw = br#"{"error":"invalid_grant","error_description":"token is spent", "refresh_token":"ref-abc123","nested":{"client_secret":"s3cret"}}"#; let (body, err, desc) = redact_body(raw); assert_eq!(err.as_deref(), Some("invalid_grant")); assert_eq!(desc.as_deref(), Some("token is spent")); assert!(!body.contains("ref-abc123"), "{body}"); assert!(!body.contains("s3cret"), "{body}"); assert!(body.contains("invalid_grant"), "{body}"); } /// The shape jacquard's `Debug` actually produces, which is where a /// scrubbed body would otherwise come back unscrubbed. #[test] fn debug_formatted_errors_are_scrubbed_too() { let debug = r#"RequestError { kind: HttpStatusWithBody { status: 400, body: Object {"error": String("invalid_grant"), "refresh_token": String("ref-abc123")} } }"#; let out = scrub_text(debug); assert!(!out.contains("ref-abc123"), "{out}"); assert!(out.contains("invalid_grant"), "{out}"); // The other spellings a formatter can produce. assert!(!scrub_text(r#"{"access_token":"tok-1"}"#).contains("tok-1")); assert!(!scrub_text(r#"code_verifier = "v-1""#).contains("v-1")); assert!(!scrub_text(r#"client_assertion: Some("jwt-1")"#).contains("jwt-1")); // Text with nothing to redact comes back byte-identical. assert_eq!(scrub_text("http status: 502"), "http status: 502"); // A body that did not parse as JSON is carried as an opaque string, // and a `Debug` formatter escapes every quote in it on the way out. let nested = r#"body: String("{\"error\":\"invalid_grant\",\"access_token\":\"tok-2\"}")"#; let out = scrub_text(nested); assert!(!out.contains("tok-2"), "{out}"); assert!(out.contains("invalid_grant"), "{out}"); } /// The constructors are the guarantee: the field type cannot be built /// without going through the scrubber, which is what stops /// `authorize_failed` drifting away from its two siblings a second time. #[test] fn every_way_into_scrubbed_scrubs() { let raw = r#"HttpStatusWithBody { body: Object {"access_token": String("secret123")} }"#; for made in [ Scrubbed::text(raw), Scrubbed::shown(&raw), Scrubbed::of(&format_args!("{raw}")), ] { assert!(!made.as_str().contains("secret123"), "{made}"); assert!(made.as_str().contains("HttpStatusWithBody"), "{made}"); } // And it survives the round trip the reader depends on, as the bare // string it replaced would have. let event = Event::AuthorizeFailed { handle: "someone.example".into(), error: Scrubbed::text(raw), elapsed_ms: 3, }; let line = line_for_test(&event); assert!(!String::from_utf8_lossy(&line).contains("secret123")); match serde_json::from_slice::(&line).expect("the writer's own line parses") { Event::AuthorizeFailed { error, .. } => { assert!(error.as_str().contains("HttpStatusWithBody"), "{error}"); } other => panic!("came back as {other:?}"), } } /// 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); let (body, err, desc) = redact_body(raw.as_bytes()); assert!(body.len() < MAX_LINE); assert!(body.ends_with("B]")); assert!(err.is_none() && desc.is_none()); } /// The filter that decides what counts as a token-endpoint request, and /// the guarantee that only two fields are ever lifted out of a body that /// also contains a refresh token, a PKCE verifier and an auth code. #[test] fn form_identity_takes_only_client_id_and_grant_type() { let body = b"client_id=http%3A%2F%2Flocalhost%2F%3Fredirect_uri%3Dhttp%3A%2F%2F127.0.0.1%3A5321%2Foauth%2Fcallback\ &grant_type=refresh_token&refresh_token=ref-super-secret"; let id = form_identity(body).expect("recognized as a client request"); assert_eq!(id.grant_type.as_deref(), Some("refresh_token")); assert!(id.client_id.contains("127.0.0.1:5321"), "{}", id.client_id); // Nothing else escapes the parser at all. assert!(!format!("{id:?}").contains("ref-super-secret")); // PAR and revocation carry a client_id but no grant type. let par = form_identity(b"client_id=http%3A%2F%2Flocalhost%2F&response_type=code").unwrap(); assert_eq!(par.grant_type, None); // Everything else on this transport — XRPC, DID docs, metadata — has // no client_id and is not logged at all. assert_eq!(form_identity(b"{\"json\":true}"), None); assert_eq!(form_identity(b""), None); assert_eq!(form_identity(b"foo=bar&baz=qux"), None); } /// The two `client_id`s whose disagreement is hypothesis 1. This is a /// characterization test of jacquard's loopback rule, not of atgc: if /// upstream ever makes the two agree, this goes red and the hypothesis /// stops applying. #[test] fn login_and_refresh_derive_different_client_ids() { use jacquard::common::DefaultStr; use jacquard::common::deps::fluent_uri::Uri; use jacquard::oauth::atproto::AtprotoClientMetadata; let redirect = Uri::parse("http://127.0.0.1:5321/oauth/callback".to_string()).unwrap(); let with_port: AtprotoClientMetadata = AtprotoClientMetadata::new_localhost(Some(vec![redirect]), None); let without: AtprotoClientMetadata = AtprotoClientMetadata::new_localhost(None, None); assert_ne!( with_port.client_id.to_string(), without.client_id.to_string(), "if these are equal the client_id-mismatch hypothesis is dead" ); assert!(with_port.client_id.to_string().contains("5321")); } #[test] fn state_keys_are_fingerprinted_but_session_keys_are_not() { assert_eq!( redact_key("oauth:did:plc:abc/session-1"), "oauth:did:plc:abc/session-1" ); let out = redact_key("oauth-state:the-random-nonce"); assert!(out.starts_with("oauth-state:")); assert!(!out.contains("the-random-nonce"), "{out}"); } /// Every event, serialized, must fit in one atomic append. Fields are /// clipped at construction, so this is really a check that the *fixed* /// parts of the biggest variants leave room. #[test] fn the_widest_events_fit_within_one_atomic_write() { let long = "y".repeat(MAX_FIELD); let events = vec![ Event::TokenRefused { grant_type: Some("refresh_token".into()), endpoint: clip(&long, MAX_FIELD), client_id: ClientId::new(&long), http_status: 400, oauth_error: Some("invalid_grant".into()), error_description: Some(clip(&long, MAX_FIELD)), body: clip(&long, MAX_FIELD), elapsed_ms: 42, }, Event::Invocation { pid: 1, user: Some(long.clone()), cwd: Some(clip(&long, MAX_FIELD)), version: Cow::Borrowed("0.1.0"), subcommand: "auth login".into(), store: Some(clip(&long, MAX_FIELD)), rotated_from_bytes: Some(u64::MAX), }, ]; for event in events { let line = line_for_test(&event); assert!(line.len() < MAX_LINE, "{} bytes", line.len()); } } /// The multi-writer claim, checked rather than asserted. /// /// Many writers, each with its own `O_APPEND` handle on one file, each /// emitting a full-width line with a single `write(2)`. Afterwards every /// line must parse as JSON and the count must be exact — a torn or /// interleaved write shows up as both a parse failure and a miscount. /// /// Threads rather than processes: the guarantee is a property of the /// `write(2)` syscall against a shared file description-less `O_APPEND` /// open, and threads issue the same syscalls. Real processes would /// exercise the same kernel path with more setup; if this ever goes red, /// reproduce it with processes before believing it. #[test] fn concurrent_appends_never_tear() { const WRITERS: usize = 16; const PER_WRITER: usize = 200; let dir = tempfile::tempdir().unwrap(); let path = LOG.path_in(dir.path()); std::thread::scope(|scope| { for writer in 0..WRITERS { let path = path.clone(); scope.spawn(move || { let mut options = std::fs::OpenOptions::new(); options.create(true).append(true); #[cfg(unix)] { use std::os::unix::fs::OpenOptionsExt; options.mode(0o600); } let file = options.open(&path).unwrap(); for seq in 0..PER_WRITER { // Pad to near the cap: short lines would pass even // without atomicity, so the test has to push against // the bound it claims is safe. let event = Event::TokenRefused { grant_type: Some("refresh_token".into()), endpoint: "https://example.invalid/token".into(), client_id: ClientId::new(&format!("http://localhost/?w={writer}")), http_status: 400, oauth_error: Some("invalid_grant".into()), error_description: Some("z".repeat(MAX_FIELD)), body: "b".repeat(MAX_FIELD), elapsed_ms: seq as u64, }; let line = line_for_test(&event); assert!(line.len() < MAX_LINE, "{} bytes", line.len()); let written = (&file).write(&line).unwrap(); assert_eq!(written, line.len(), "short write"); } }); } }); let contents = std::fs::read_to_string(&path).unwrap(); let lines: Vec<&str> = contents.lines().collect(); assert_eq!(lines.len(), WRITERS * PER_WRITER, "lines went missing"); for (n, line) in lines.iter().enumerate() { serde_json::from_str::(line) .unwrap_or_else(|e| panic!("line {n} did not parse ({e}): {line}")); } } /// A throwaway store directory, named for the test so two cannot collide. fn store_dir(label: &str) -> tempfile::TempDir { tempfile::Builder::new() .prefix(&format!("atgc-authstore-{label}-")) // 0o700, because these stand in for ~/.config/atgc, which // production creates owner-only. `tempfile` defaults a // directory to 0o777 & ~umask, which would quietly make // every mode assertion below weaker than the real thing. .permissions( ::from_mode(0o700), ) .tempdir() .unwrap() } use crate::testutil::oauth_session as a_session; /// The file's modification time, as the test's evidence of a rewrite. fn mtime(path: &std::path::Path) -> std::time::SystemTime { std::fs::metadata(path) .expect("the store exists") .modified() .expect("this platform records mtime") } /// Hold the mtime still, so that "was it rewritten" is a question with a /// crisp answer rather than one bounded by the clock's resolution. fn backdate(path: &std::path::Path) -> std::time::SystemTime { let when = std::time::SystemTime::UNIX_EPOCH + std::time::Duration::from_secs(1_000_000); let file = std::fs::OpenOptions::new() .write(true) .open(path) .expect("open the store to set its times"); file.set_times(std::fs::FileTimes::new().set_modified(when)) .expect("set the store's mtime"); assert_eq!(mtime(path), when, "the backdate did not take"); when } /// **The property this elision exists for.** An upsert carrying what the /// store already holds must not touch the file. /// /// Asserted on the modification time, because the claim is about the /// credential file and not about a branch being taken: a rewrite with /// identical bytes would be indistinguishable by content, and it is the /// rewrite — the truncate, the lost atomicity, the window — that this is /// meant to stop. /// /// The second half is the half that fails if the elision is too eager. /// Round-tripping a session through JSON and back has to compare equal /// for the first assertion to hold at all, and *unequal* the moment a /// token changes, or this optimization would silently drop live /// credentials. Both directions are checked here for that reason. #[tokio::test] async fn an_unchanged_upsert_does_not_rewrite_the_store() { let dir = store_dir("unchanged-upsert"); let store = LoggedAuthStore(crate::clients::atproto::oauth::store::SessionStore::new( dir.path().to_path_buf(), )); let session = a_session("first-token"); // The shard this session routes to, which is the file whose mtime // says whether the elision held. let path = crate::clients::atproto::oauth::sessions::path_for_key_in( dir.path(), &format!( "oauth:{}/{}", session.account_did.as_str(), AsRef::::as_ref(&session.session_id) ), ) .expect("a shard path"); store .upsert_session(session.clone()) .await .expect("the first upsert lands"); let untouched = backdate(&path); store .upsert_session(session.clone()) .await .expect("the identical upsert succeeds"); assert_eq!( mtime(&path), untouched, "an upsert that changed nothing rewrote the credential file anyway" ); let mut rotated = session; rotated.token_set.access_token = "second-token".into(); store .upsert_session(rotated) .await .expect("the changed upsert lands"); assert_ne!( mtime(&path), untouched, "an upsert carrying a new access token was elided: a live credential was dropped" ); let back = store .get_session( &Did::::new_owned("did:plc:alice").unwrap(), "session", ) .await .expect("the store reads back") .expect("the session is there"); assert_eq!( back.token_set.access_token.as_str(), "second-token", "the changed token did not reach the file" ); std::fs::remove_dir_all(&dir).ok(); } }