From 40687ab4a5d213335ca89ac8da3780df5bfa4b84 Mon Sep 17 00:00:00 2001 From: atlas Date: Tue, 6 Oct 2026 16:01:53 +0200 Subject: [PATCH] swarm-nats-auth: a failed re-read no longer logs that the stored secret was refused When the store re-read failed or timed out, introspect fell through to the unchanged-secret branch and logged "the stored OIDC client secret is the one the IdP refused" after the re-read's own failure line. The re-read now says whether it read the store, and a failed one denies without the second line. The verdict is unchanged. --- swarm-nats-auth/src/oidc_secret.rs | 116 +++++++++++++++++++++++------ 1 file changed, 95 insertions(+), 21 deletions(-) diff --git a/swarm-nats-auth/src/oidc_secret.rs b/swarm-nats-auth/src/oidc_secret.rs index f62b4ed3..63425f1b 100644 --- a/swarm-nats-auth/src/oidc_secret.rs +++ b/swarm-nats-auth/src/oidc_secret.rs @@ -98,8 +98,9 @@ impl Source for Store { /// starting another. const REREAD_TIMEOUT: Duration = Duration::from_secs(10); -/// A re-read in progress, shared by every request waiting on it. -type Reread = Shared>; +/// A re-read in progress, shared by every request waiting on it. It yields +/// whether the store was read; a failed or timed-out read logs for itself. +type Reread = Shared>; /// The secret in use, and the re-read that replaces it. No `Debug`: it holds /// the secret. @@ -139,15 +140,16 @@ impl OidcSecret { if let Answer::Caller(caller) = attempt(used.clone()).await? { return Ok(caller); } - if tokio::time::timeout_at(deadline, self.reread()) - .await - .is_err() - { - tracing::warn!( - "re-reading the OIDC client secret did not finish inside the introspection budget; \ - denying, and the next request introspects with what it reads" - ); - return Ok(None); + match tokio::time::timeout_at(deadline, self.reread()).await { + Err(_) => { + tracing::warn!( + "re-reading the OIDC client secret did not finish inside the introspection budget; \ + denying, and the next request introspects with what it reads" + ); + return Ok(None); + } + Ok(false) => return Ok(None), + Ok(true) => {} } let fresh = self.current(); if fresh == used { @@ -174,19 +176,28 @@ impl OidcSecret { let current = Arc::clone(&self.current); let task = tokio::spawn(async move { match tokio::time::timeout(REREAD_TIMEOUT, source.read()).await { - Ok(Ok(secret)) => *current.write().expect("unpoisoned") = secret, - Ok(Err(e)) => tracing::warn!( - error = format!("{e:#}"), - "could not re-read the OIDC client secret; keeping the one in use" - ), - Err(_) => tracing::warn!( - timeout = ?REREAD_TIMEOUT, - "re-reading the OIDC client secret timed out; keeping the one in use" - ), + Ok(Ok(secret)) => { + *current.write().expect("unpoisoned") = secret; + true + } + Ok(Err(e)) => { + tracing::warn!( + error = format!("{e:#}"), + "could not re-read the OIDC client secret; keeping the one in use" + ); + false + } + Err(_) => { + tracing::warn!( + timeout = ?REREAD_TIMEOUT, + "re-reading the OIDC client secret timed out; keeping the one in use" + ); + false + } } }); let handle = task.abort_handle(); - let shared = task.map(|_| ()).boxed().shared(); + let shared = task.map(|read| read.unwrap_or(false)).boxed().shared(); *slot = Some((handle, shared.clone())); shared } @@ -325,8 +336,48 @@ mod tests { assert_eq!(calls.load(Ordering::SeqCst), 1); } + thread_local! { + static LOG: std::cell::RefCell> = const { std::cell::RefCell::new(Vec::new()) }; + } + + /// What `tracing` records on the calling thread. The subscriber is + /// process-wide, because a scoped one loses to the callsite cache when + /// another test reaches the same event first; the buffer is per thread, + /// which is where a current-thread test runtime runs the spawned re-read. + struct Logs; + + impl std::io::Write for Logs { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + LOG.with(|log| log.borrow_mut().extend_from_slice(buf)); + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } + } + + impl Logs { + /// Starts this thread's capture empty. + fn capture() { + static INSTALLED: std::sync::Once = std::sync::Once::new(); + INSTALLED.call_once(|| { + tracing_subscriber::fmt() + .with_writer(|| Logs) + .with_ansi(false) + .init(); + }); + LOG.with(|log| log.borrow_mut().clear()); + } + + fn text() -> String { + LOG.with(|log| String::from_utf8(log.borrow().clone()).expect("utf-8")) + } + } + #[tokio::test] async fn a_failed_re_read_denies_and_keeps_the_secret_in_use() { + Logs::capture(); let store = Fake { secret: None, delay: Duration::ZERO, @@ -341,6 +392,29 @@ mod tests { assert_eq!(caller, None); assert_eq!(calls.load(Ordering::SeqCst), 1); assert_eq!(secret.current(), "old"); + + let text = Logs::text(); + assert!(text.contains("could not re-read the OIDC client secret")); + assert!(!text.contains("is the one the IdP refused"), "{text}"); + assert!(!text.contains("old"), "no secret in the log: {text}"); + } + + /// The store was read and holds what the `IdP` already refused: the one + /// case that says so. + #[tokio::test] + async fn the_unchanged_secret_is_logged_as_the_one_the_idp_refused() { + Logs::capture(); + let secret = OidcSecret::new(Fake::holding("old"), "old".to_owned()); + let calls = AtomicUsize::new(0); + let caller = secret + .introspect(budget(), idp("new", &calls)) + .await + .expect("answered"); + assert_eq!(caller, None); + + let text = Logs::text(); + assert!(text.contains("is the one the IdP refused"), "{text}"); + assert!(!text.contains("could not re-read"), "{text}"); } /// A store slower than the budget: the request is denied at its