Log on every HTTP response

Cargo.lock

@@ -3159,6 +3159,7 @@ dependencies = [
  "dotenvy",
  "figment",
  "futures-util",
+ "headers",
  "http-body-util",
  "hyper",
  "ipnetwork",

crates/cli/Cargo.toml

@@ -27,6 +27,7 @@ dialoguer = { version = "0.11.0", default-features = false, features = [
 dotenvy = "0.15.7"
 figment.workspace = true
 futures-util.workspace = true
+headers.workspace = true
 http-body-util.workspace = true
 hyper.workspace = true
 ipnetwork = "0.20.0"

crates/cli/src/server.rs

@@ -16,12 +16,14 @@ use axum::{
     error_handling::HandleErrorLayer,
     extract::{FromRef, MatchedPath},
 };
+use headers::{HeaderMapExt as _, UserAgent};
 use hyper::{
     Method, Request, Response, StatusCode, Version,
     header::{CACHE_CONTROL, HeaderValue, USER_AGENT},
 };
 use listenfd::ListenFd;
 use mas_config::{HttpBindConfig, HttpResource, HttpTlsConfig, UnixOrTcp};
+use mas_context::LogContext;
 use mas_listener::{ConnectionInfo, unix_or_tcp::UnixOrTcpListener};
 use mas_router::Route;
 use mas_templates::Templates;
@@ -170,6 +172,45 @@ fn on_http_response_labels<B>(res: &Response<B>) -> Vec<KeyValue> {
     )]
 }
 
+async fn log_response_middleware(
+    request: axum::extract::Request,
+    next: axum::middleware::Next,
+) -> axum::response::Response {
+    let user_agent: Option<UserAgent> = request.headers().typed_get();
+    let user_agent = user_agent.as_ref().map_or("-", |u| u.as_str());
+    let method = otel_http_method(&request);
+    let path = request.uri().path().to_owned();
+    let version = otel_net_protocol_version(&request);
+
+    let response = next.run(request).await;
+
+    let Some(log_context) = LogContext::current() else {
+        tracing::error!("Missing log context for request, this is a bug!");
+        return response;
+    };
+
+    let stats = log_context.stats();
+
+    let status_code = response.status();
+    match status_code.as_u16() {
+        100..=399 => tracing::info!(
+            name: "http.server.response",
+            "\"{method} {path} HTTP/{version}\" {status_code} {user_agent:?} [{stats}]",
+        ),
+        400..=499 => tracing::warn!(
+            name: "http.server.response",
+            "\"{method} {path} HTTP/{version}\" {status_code} {user_agent:?} [{stats}]",
+        ),
+        500..=599 => tracing::error!(
+            name: "http.server.response",
+            "\"{method} {path} HTTP/{version}\" {status_code} {user_agent:?} [{stats}]",
+        ),
+        _ => { /* This shouldn't happen */ }
+    }
+
+    response
+}
+
 pub fn build_router(
     state: AppState,
     resources: &[HttpResource],
@@ -277,6 +318,7 @@ pub fn build_router(
                 span.record("otel.status_code", "OK");
             }),
         )
+        .layer(axum::middleware::from_fn(log_response_middleware))
         .layer(mas_context::LogContextLayer::new(|req| {
             otel_http_method(req).into()
         }))

crates/context/src/fmt.rs

@@ -100,11 +100,18 @@ where
         SystemTime.format_time(&mut writer)?;
 
         let level = FmtLevel::new(metadata.level(), ansi);
-        let target = Style::new()
-            .dim()
-            .force_styling(ansi)
-            .apply_to(TargetFmt::new(metadata));
-        write!(&mut writer, " {level} {target} ")?;
+        write!(&mut writer, " {level} ")?;
+
+        // If there is no explicit 'name' set in the event macro, it will have the
+        // 'event {filename}:{line}' value. In this case, we want to display the target:
+        // the module from where it was emitted. In other cases, we want to
+        // display the explit name of the event we have set.
+        let style = Style::new().dim().force_styling(ansi);
+        if metadata.name().starts_with("event ") {
+            write!(&mut writer, "{} ", style.apply_to(TargetFmt::new(metadata)))?;
+        } else {
+            write!(&mut writer, "{} ", style.apply_to(metadata.name()))?;
+        }
 
         if let Some(log_context) = LogContext::current() {
             let log_context = Style::new()