api: log ingress request ids

apps/admin-api/src/request_context.rs

@@ -4,6 +4,7 @@ use axum::{
     middleware::Next,
     response::Response,
 };
+use tracing::info;
 use uuid::Uuid;
 
 pub const REQUEST_ID_HEADER: HeaderName = HeaderName::from_static("x-request-id");
@@ -18,9 +19,18 @@ pub async fn apply_request_context(mut request: Request, next: Next) -> Response
     let context = RequestContext {
         request_id: resolve_request_id(request.headers()),
     };
+    let method = request.method().clone();
+    let path = request.uri().path().to_owned();
     request.extensions_mut().insert(context.clone());
 
     let mut response = next.run(request).await;
+    info!(
+        request_id = %context.request_id,
+        method = %method,
+        path,
+        status = response.status().as_u16(),
+        "admin request completed"
+    );
     if let Ok(value) = HeaderValue::from_str(&context.request_id) {
         response.headers_mut().insert(REQUEST_ID_HEADER, value);
     }
@@ -47,7 +57,15 @@ fn is_valid_request_id(value: &str) -> bool {
 
 #[cfg(test)]
 mod tests {
-    use super::is_valid_request_id;
+    use std::io;
+    use std::sync::{Arc, Mutex};
+
+    use axum::{Router, routing::get};
+    use reqwest::Client;
+    use tokio::net::TcpListener;
+    use tracing_subscriber::{filter::LevelFilter, fmt::MakeWriter, prelude::*};
+
+    use super::{REQUEST_ID_HEADER, apply_request_context, is_valid_request_id};
 
     #[test]
     fn accepts_visible_ascii_request_ids() {
@@ -61,4 +79,87 @@ mod tests {
         assert!(!is_valid_request_id("bad value"));
         assert!(!is_valid_request_id("bad\nvalue"));
     }
+
+    #[derive(Clone, Default)]
+    struct SharedLogWriter {
+        buffer: Arc<Mutex<Vec<u8>>>,
+    }
+
+    impl SharedLogWriter {
+        fn output(&self) -> String {
+            String::from_utf8(self.buffer.lock().unwrap().clone()).unwrap()
+        }
+    }
+
+    impl<'a> MakeWriter<'a> for SharedLogWriter {
+        type Writer = SharedLogGuard;
+
+        fn make_writer(&'a self) -> Self::Writer {
+            SharedLogGuard {
+                buffer: Arc::clone(&self.buffer),
+            }
+        }
+    }
+
+    struct SharedLogGuard {
+        buffer: Arc<Mutex<Vec<u8>>>,
+    }
+
+    impl io::Write for SharedLogGuard {
+        fn write(&mut self, bytes: &[u8]) -> io::Result<usize> {
+            self.buffer.lock().unwrap().extend_from_slice(bytes);
+            Ok(bytes.len())
+        }
+
+        fn flush(&mut self) -> io::Result<()> {
+            Ok(())
+        }
+    }
+
+    #[tokio::test]
+    async fn logs_request_completion_with_request_id() {
+        let writer = SharedLogWriter::default();
+        let subscriber = tracing_subscriber::registry().with(
+            tracing_subscriber::fmt::layer()
+                .with_writer(writer.clone())
+                .without_time()
+                .with_ansi(false)
+                .with_target(false)
+                .compact()
+                .with_filter(LevelFilter::INFO),
+        );
+        let dispatch = tracing::Dispatch::new(subscriber);
+        let app = Router::new()
+            .route("/probe", get(|| async { "ok" }))
+            .layer(axum::middleware::from_fn(apply_request_context));
+        let listener = TcpListener::bind("127.0.0.1:0").await.unwrap();
+        let address = listener.local_addr().unwrap();
+
+        let _guard = tracing::dispatcher::set_default(&dispatch);
+        tokio::spawn(async move {
+            axum::serve(listener, app).await.unwrap();
+        });
+
+        let response = Client::new()
+            .get(format!("http://{address}/probe"))
+            .header(REQUEST_ID_HEADER.as_str(), "req_admin_trace_123")
+            .send()
+            .await
+            .unwrap();
+
+        assert_eq!(response.status(), reqwest::StatusCode::OK);
+        assert_eq!(
+            response.headers()[REQUEST_ID_HEADER.as_str()]
+                .to_str()
+                .unwrap(),
+            "req_admin_trace_123"
+        );
+
+        let logs = writer.output();
+        assert!(logs.contains("admin request completed"));
+        assert!(logs.contains("req_admin_trace_123"));
+        assert!(logs.contains("GET"));
+        assert!(logs.contains("/probe"));
+        assert!(logs.contains("status=200"));
+    }
 }