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

@@ -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.
+/// A re-read in progress, shared by every request waiting on it. It yields
-type Reread = Shared<BoxFuture<'static, ()>>;
+/// whether the store was read; a failed or timed-out read logs for itself.
+type Reread = Shared<BoxFuture<'static, bool>>;
 
 /// The secret in use, and the re-read that replaces it. No `Debug`: it holds
 /// the secret.
@@ -139,15 +140,16 @@ impl<S: Source> OidcSecret<S> {
         if let Answer::Caller(caller) = attempt(used.clone()).await? {
             return Ok(caller);
         }
-        if tokio::time::timeout_at(deadline, self.reread())
+        match tokio::time::timeout_at(deadline, self.reread()).await {
-            .await
+            Err(_) => {
-            .is_err()
+                tracing::warn!(
-        {
+                    "re-reading the OIDC client secret did not finish inside the introspection budget; \
-            tracing::warn!(
+                     denying, and the next request introspects with what it reads"
-                "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);
-            );
+            }
-            return Ok(None);
+            Ok(false) => return Ok(None),
+            Ok(true) => {}
         }
         let fresh = self.current();
         if fresh == used {
@@ -174,19 +176,28 @@ impl<S: Source> OidcSecret<S> {
         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(Ok(secret)) => {
-                Ok(Err(e)) => tracing::warn!(
+                    *current.write().expect("unpoisoned") = secret;
-                    error = format!("{e:#}"),
+                    true
-                    "could not re-read the OIDC client secret; keeping the one in use"
+                }
-                ),
+                Ok(Err(e)) => {
-                Err(_) => tracing::warn!(
+                    tracing::warn!(
-                    timeout = ?REREAD_TIMEOUT,
+                        error = format!("{e:#}"),
-                    "re-reading the OIDC client secret timed out; keeping the one in use"
+                        "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<Vec<u8>> = 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<usize> {
+            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