doido_controller/
logging.rs

1//! Request/response logging middleware.
2//!
3//! [`log_requests`] logs each incoming request and its response through the
4//! framework's centralized logger (`doido_core::logger`), so every HTTP exchange
5//! flows through the same `tracing` subscriber as jobs, mail and ORM queries. It
6//! is wired into the always-on [`MiddlewareStack`] (`crate::stack`).
7//!
8//! A per-request UUID (`request_id`) ties the `request` and `response` log lines
9//! together; it is taken from an inbound `x-request-id` header when present (so
10//! an upstream proxy's id is preserved) or generated otherwise, and echoed back
11//! on the response so clients can correlate too. The `request` line carries the
12//! method, path, query and request headers; the `response` line carries the
13//! status, latency and response headers.
14
15use crate::axum::{extract::Request, middleware::Next, response::Response};
16use doido_core::tracing::Instrument;
17use http::{HeaderMap, HeaderName, HeaderValue};
18use std::time::Instant;
19use uuid::Uuid;
20
21/// Header carrying the request correlation id, in/out.
22const REQUEST_ID_HEADER: &str = "x-request-id";
23
24/// Logs an incoming request and its response through the doido logger.
25///
26/// Two events flow through the global `tracing` subscriber per exchange, sharing
27/// a `request_id`: a `request` line when it arrives (method, path, query, request
28/// headers), and a `response` line once the response is ready (status, latency,
29/// response headers). Both run inside a `request` span so nested events (e.g. SQL
30/// queries) correlate back to the originating request.
31pub async fn log_requests(request: Request, next: Next) -> Response {
32    let request_id = resolve_request_id(request.headers());
33    let method = request.method().clone();
34    let path = request.uri().path().to_owned();
35    let query = request.uri().query().map(str::to_owned);
36    let request_headers = format_headers(request.headers());
37
38    // Span carrying the request identity; nested events inherit it.
39    let span = doido_core::tracing::info_span!(
40        "request",
41        request_id = %request_id,
42        method = %method,
43        path = %path,
44    );
45    doido_core::tracing::info!(
46        target: doido_core::logger::REQUEST_TARGET,
47        parent: &span,
48        request_id = %request_id,
49        method = %method,
50        path = %path,
51        query = query.as_deref().unwrap_or(""),
52        headers = %request_headers,
53        "request"
54    );
55
56    let start = Instant::now();
57    // `instrument` enters the span for the whole handler, across `.await`s.
58    let mut response = next.run(request).instrument(span.clone()).await;
59    let latency_ms = start.elapsed().as_millis() as u64;
60
61    // Echo the correlation id back so clients/proxies can trace it; do this
62    // before logging so the logged response headers reflect what's sent.
63    if let Ok(value) = HeaderValue::from_str(&request_id) {
64        response
65            .headers_mut()
66            .insert(HeaderName::from_static(REQUEST_ID_HEADER), value);
67    }
68
69    let status = response.status().as_u16();
70    let response_headers = format_headers(response.headers());
71    {
72        // Emit the response event inside the span; no `.await` follows.
73        let _guard = span.enter();
74        doido_core::tracing::info!(
75            target: doido_core::logger::RESPONSE_TARGET,
76            request_id = %request_id,
77            method = %method,
78            path = %path,
79            status = status,
80            latency_ms = latency_ms,
81            headers = %response_headers,
82            "response"
83        );
84    }
85
86    response
87}
88
89/// Returns the inbound `x-request-id` when present and non-empty, otherwise a
90/// freshly generated UUID v4.
91fn resolve_request_id(headers: &HeaderMap) -> String {
92    headers
93        .get(REQUEST_ID_HEADER)
94        .and_then(|value| value.to_str().ok())
95        .map(str::trim)
96        .filter(|id| !id.is_empty())
97        .map(str::to_owned)
98        .unwrap_or_else(|| Uuid::new_v4().to_string())
99}
100
101/// Renders request headers as `name: value` pairs for a single log field.
102/// Sensitive headers (auth, cookies) are redacted so secrets never reach logs.
103fn format_headers(headers: &HeaderMap) -> String {
104    headers
105        .iter()
106        .map(|(name, value)| {
107            let rendered = if is_sensitive(name.as_str()) {
108                "[redacted]"
109            } else {
110                value.to_str().unwrap_or("[non-utf8]")
111            };
112            format!("{}: {}", name.as_str(), rendered)
113        })
114        .collect::<Vec<_>>()
115        .join(", ")
116}
117
118/// Whether a header's value must be redacted from logs. Header names compare
119/// lowercase (the `http` crate normalizes them).
120fn is_sensitive(name: &str) -> bool {
121    matches!(
122        name,
123        "authorization" | "proxy-authorization" | "cookie" | "set-cookie"
124    )
125}
doido_controller/logging.rs

doido_controller/
logging.rs
