log refused agent-permission changes on the controller api

swarm-controller/src/agent_permissions.rs

@@ -13,6 +13,7 @@ use std::sync::Arc;
 use std::time::Duration;
 
 use axum::Json;
+use axum::extract::rejection::JsonRejection;
 use axum::extract::{Path, State};
 use axum::http::StatusCode;
 use backon::{ConstantBuilder, Retryable as _};
@@ -70,6 +71,19 @@ fn agent_name(name: &str) -> Result<String, (StatusCode, String)> {
         .map_err(|reason| (StatusCode::BAD_REQUEST, reason.to_owned()))
 }
 
+/// Log a refused `op` on `agent` at `warn` and pass the problem on. The
+/// handlers have no caller identity; `detail` is the response's.
+fn logged(op: &'static str, agent: &str, problem: ProblemDetails) -> ProblemDetails {
+    tracing::warn!(
+        op,
+        agent,
+        status = problem.status.map(|s| s.as_u16()),
+        detail = problem.detail.as_deref(),
+        "agent permissions: request refused"
+    );
+    problem
+}
+
 fn queue_problem(e: &anyhow::Error) -> ProblemDetails {
     tracing::warn!(error = %format!("{e:#}"), "agent permissions: queue failure");
     error_problem(wanted_error_status(e), &format!("{e:#}"))
@@ -136,16 +150,20 @@ pub(crate) async fn get_agent_permissions(
 pub(crate) async fn put_agent_permissions(
     State(state): State<AppState>,
     Path(name): Path<String>,
-    Json(req): Json<Permissions>,
+    req: Result<Json<Permissions>, JsonRejection>,
 ) -> Result<Json<Permissions>, ProblemDetails> {
-    let agent = agent_name(&name).map_err(refused)?;
-    let value = into_stored(req).map_err(|why| error_problem(StatusCode::BAD_REQUEST, &why))?;
-    let client = queue(&state).map_err(refused)?;
-    if !live(&state).await?.contains(&agent) {
-        return Err(error_problem(
+    let refuse = |p| logged("put", &name, p);
+    let Json(req) =
+        req.map_err(|rejection| refuse(error_problem(rejection.status(), &rejection.body_text())))?;
+    let agent = agent_name(&name).map_err(|r| refuse(refused(r)))?;
+    let value =
+        into_stored(req).map_err(|why| refuse(error_problem(StatusCode::BAD_REQUEST, &why)))?;
+    let client = queue(&state).map_err(|r| refuse(refused(r)))?;
+    if !live(&state).await.map_err(refuse)?.contains(&agent) {
+        return Err(refuse(error_problem(
             StatusCode::BAD_REQUEST,
             &format!("no hive's wanted state declares an agent {agent:?} that is not destroyed"),
-        ));
+        )));
     }
     let store = open_or_create(&client).await?;
     for _ in 0..MAX_ATTEMPTS {
@@ -184,8 +202,9 @@ pub(crate) async fn delete_agent_permissions(
     State(state): State<AppState>,
     Path(name): Path<String>,
 ) -> Result<StatusCode, ProblemDetails> {
-    let agent = agent_name(&name).map_err(refused)?;
-    let client = queue(&state).map_err(refused)?;
+    let refuse = |p| logged("delete", &name, p);
+    let agent = agent_name(&name).map_err(|r| refuse(refused(r)))?;
+    let client = queue(&state).map_err(|r| refuse(refused(r)))?;
     let store = open_or_create(&client).await?;
     store
         .delete(&agent)
@@ -543,7 +562,7 @@ mod tests {
         put_agent_permissions(
             State(state.clone()),
             Path(agent.to_owned()),
-            axum::Json(value),
+            Ok(axum::Json(value)),
         )
         .await
     }
@@ -605,6 +624,101 @@ mod tests {
         assert_eq!(published(&client, "iris").await, None);
     }
 
+    type Fields = std::collections::BTreeMap<String, String>;
+
+    /// Every event, by field name. Installed once as the global subscriber:
+    /// a per-thread one loses to a callsite another test already cached as
+    /// disabled.
+    struct Events(std::sync::Mutex<Vec<Fields>>);
+
+    impl<S: tracing::Subscriber> tracing_subscriber::Layer<S> for &'static Events {
+        fn on_event(
+            &self,
+            event: &tracing::Event<'_>,
+            _: tracing_subscriber::layer::Context<'_, S>,
+        ) {
+            let mut fields = Fields::new();
+            event.record(
+                &mut |field: &tracing::field::Field, value: &dyn std::fmt::Debug| {
+                    fields.insert(field.name().to_owned(), format!("{value:?}"));
+                },
+            );
+            self.0.lock().expect("unpoisoned").push(fields);
+        }
+    }
+
+    fn events() -> &'static Events {
+        use tracing_subscriber::layer::SubscriberExt as _;
+        static EVENTS: Events = Events(std::sync::Mutex::new(Vec::new()));
+        static INSTALL: std::sync::Once = std::sync::Once::new();
+        INSTALL.call_once(|| {
+            tracing::subscriber::set_global_default(tracing_subscriber::registry().with(&EVENTS))
+                .expect("no other global subscriber in this test binary");
+        });
+        &EVENTS
+    }
+
+    /// The refusals logged for `agent`.
+    fn refusals(agent: &str) -> Vec<Fields> {
+        let want = format!("{agent:?}");
+        events()
+            .0
+            .lock()
+            .expect("unpoisoned")
+            .iter()
+            .filter(|f| {
+                f.get("message")
+                    .is_some_and(|m| m.contains("request refused"))
+                    && f.get("agent") == Some(&want)
+            })
+            .cloned()
+            .collect()
+    }
+
+    /// Every refused PUT or DELETE logs one `warn` naming the operation, the
+    /// agent, the status and the response's detail.
+    #[tokio::test]
+    async fn a_refused_change_is_logged_with_the_agent_and_status() {
+        use tower::ServiceExt as _;
+        let nats = TestNats::start();
+        let client = nats.client().await;
+        let state = crate::agent_limits::tests::declared(&client).await;
+        let app = crate::startup::build_app(state.clone());
+        let _ = events();
+
+        // Control: the lookup finds nothing for an agent nobody refused.
+        assert_eq!(refusals("ghost"), []);
+
+        let _ = put(&state, "ghost", granted())
+            .await
+            .expect_err("undeclared");
+        let got = refusals("ghost");
+        let [one] = got.as_slice() else {
+            panic!("one event, got {got:?}");
+        };
+        assert_eq!(one["op"], "\"put\"");
+        assert_eq!(one["status"], "400");
+        assert!(one["detail"].contains("declares an agent"), "{one:?}");
+
+        let malformed = axum::http::Request::put("/api/agents/ghost2/permissions")
+            .header(axum::http::header::CONTENT_TYPE, "application/json")
+            .body(axum::body::Body::from(r#"{"permisions":[]}"#))
+            .expect("request");
+        let status = app.oneshot(malformed).await.expect("answers").status();
+        assert_eq!(status, StatusCode::UNPROCESSABLE_ENTITY);
+        let got = refusals("ghost2");
+        assert_eq!(got.len(), 1, "{got:?}");
+        assert_eq!(got[0]["status"], "422");
+
+        let _ = delete_agent_permissions(State(state), Path("Bad_Ghost".to_owned()))
+            .await
+            .expect_err("not an identifier");
+        let got = refusals("Bad_Ghost");
+        assert_eq!(got.len(), 1, "{got:?}");
+        assert_eq!(got[0]["op"], "\"delete\"");
+        assert_eq!(got[0]["status"], "400");
+    }
+
     async fn put_raw(app: &axum::Router, body: &'static str) -> StatusCode {
         use tower::ServiceExt as _;
         app.clone()