From 99a230f3736043363599e7f0aa7eed0b1e5aa448 Mon Sep 17 00:00:00 2001 From: Edouard Vanbelle Date: Sat, 5 Sep 2026 00:54:47 +0200 Subject: [PATCH] fix(dpop): log the nonce-bootstrap challenge instead of returning a bare 401 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The `None` arm of the nonce match returns a challenge — the client sent a valid proof but carried no nonce, so it gets 401 + `DPoP-Nonce` and retries. It was the only one of the three challenge paths that logged nothing. The result was an unexplainable line in the access log: WARN http::api: client_error status=401 latency_ms=0 … with no audit line saying why, and no sign of the successful retry — `main.rs` defaults the access log to `http=warn`, so the 200 that follows is never printed. It came up as "any clue why I have 401?" while reading an e2e run, which is the cost of a silent rejection. AGENTS.md is explicit that every rejection emits a structured audit line before returning the error; this path simply missed it. The line pays off immediately: it names `htu`, and the first run with it showed the caller was `GET /api/admin/plugins/{id}/logs/stream` — the admin log tail, an `EventSource`, whose proof is minted by the service worker rather than by `apiFetch`. `service-worker.ts` documents exactly this: the nonce cache is per-scope, so the page module and the SW EACH pay one round-trip challenge and then catch up from `DPoP-Nonce` response headers. The SW absorbs the 401 and retries, so `EventSource` never sees it. Hence "once per client SCOPE" rather than per session — and again whenever the browser terminates and restarts the worker, which is normal and is why one run shows several. Deliberately NOT `dpop.verify_failed`. The proof verified cleanly — nothing failed — and folding a routine bootstrap into the event operators watch for attacks would bury real signal. `nonce_stale` above keeps that event name because it is long-standing and aggregators key off it; this path is new, so it gets the accurate one: `dpop.nonce_challenged` / `reason = "nonce_missing"`. No new counter — `nonce_challenge_response` already counts every challenge centrally, so adding one here would double-count. Co-Authored-By: Claude Opus 5 (1M context) --- src/interfaces/middleware/dpop.rs | 28 ++++++++++++++++++++++++++++ 1 file changed, 28 insertions(+) diff --git a/src/interfaces/middleware/dpop.rs b/src/interfaces/middleware/dpop.rs index e6e7cbe2..b5d39dc8 100644 --- a/src/interfaces/middleware/dpop.rs +++ b/src/interfaces/middleware/dpop.rs @@ -237,6 +237,34 @@ pub async fn require_dpop_layer( // window at the verifier means this one still // succeeded, but we still want the client onto // the nonce path immediately. + // + // Logged because this returns a 401, and every + // rejection owes the operator a line saying why — + // otherwise the access log shows a bare + // `client_error status=401` with nothing to + // explain it, while the client's successful retry + // stays invisible under the default `http=warn` + // access-log filter. That combination reads like a + // real auth failure and is not one. + // + // NOT `dpop.verify_failed`: the proof verified + // cleanly, and counting a routine bootstrap as a + // verification failure would put a per-session + // event into the metric operators watch for + // attacks. `nonce_stale` above keeps that event + // name — it is long-standing and log aggregators + // key off it — but this path is new, so it gets + // the accurate one. The challenge itself is + // already counted centrally by + // `nonce_challenge_response`. + tracing::info!( + target: "audit", + event = "dpop.nonce_challenged", + reason = "nonce_missing", + method = %method, + htu = %htu, + "👮🏻‍♂️ DPoP proof carried no nonce — issuing challenge (expected once per client scope; the client harvests the nonce and retries)", + ); return nonce_challenge_response(&nonce_service); } Some(n) => n,