siderite_core/middleware/
observe.rs

1//! Request ids and structured request logging.
2
3use super::adapt::{BoxService, Next, from_fn, impl_layer};
4use crate::error::ApiError;
5use crate::extract::{FromRequestParts, Request};
6use crate::response::Response;
7use http::request::Parts;
8use http::{HeaderName, HeaderValue};
9use std::fmt;
10use std::sync::{Arc, Mutex, PoisonError};
11use std::time::Instant;
12use tower::Layer;
13use tracing::Instrument;
14
15const DEFAULT_HEADER: &str = "x-request-id";
16const MAX_ID_LEN: usize = 128;
17
18/// The id of the current request, set by the [`RequestIdLayer`] middleware.
19///
20/// Usable as a handler argument.
21#[derive(Debug, Clone, PartialEq, Eq)]
22pub struct RequestId(pub String);
23
24impl fmt::Display for RequestId {
25    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
26        f.write_str(&self.0)
27    }
28}
29
30impl FromRequestParts for RequestId {
31    async fn from_request_parts(parts: &mut Parts) -> Result<Self, ApiError> {
32        parts
33            .extensions
34            .get::<RequestId>()
35            .cloned()
36            .ok_or_else(|| ApiError::internal("RequestId used without the request_id middleware"))
37    }
38}
39
40/// Assigns every request an id: an incoming `x-request-id` is propagated when
41/// it is 1..=128 visible ASCII characters, otherwise a UUID v4 is generated.
42/// The id is exposed as [`RequestId`], forwarded to the handler as a request
43/// header and echoed on the response.
44#[derive(Debug, Clone)]
45pub struct RequestIdLayer {
46    header: HeaderName,
47}
48
49impl Default for RequestIdLayer {
50    fn default() -> Self {
51        Self {
52            header: HeaderName::from_static(DEFAULT_HEADER),
53        }
54    }
55}
56
57impl RequestIdLayer {
58    /// Use the default `x-request-id` header.
59    pub fn new() -> Self {
60        Self::default()
61    }
62
63    /// Use another header name.
64    #[must_use]
65    pub fn header(mut self, name: HeaderName) -> Self {
66        self.header = name;
67        self
68    }
69
70    fn wrap(&self, inner: BoxService) -> BoxService {
71        let header = self.header.clone();
72        from_fn(move |mut req: Request, next: Next| {
73            let header = header.clone();
74            async move {
75                let id = req
76                    .headers()
77                    .get(&header)
78                    .and_then(|v| v.to_str().ok())
79                    .filter(|v| valid_id(v))
80                    .map_or_else(|| uuid::Uuid::new_v4().to_string(), str::to_owned);
81                let value = HeaderValue::from_str(&id).ok();
82                if let Some(value) = &value {
83                    req.headers_mut().insert(header.clone(), value.clone());
84                }
85                req.extensions_mut().insert(RequestId(id));
86                let mut response = next.run(req).await;
87                if let Some(value) = value {
88                    response.headers_mut().insert(header, value);
89                }
90                response
91            }
92        })
93        .layer(inner)
94    }
95}
96
97fn valid_id(id: &str) -> bool {
98    !id.is_empty() && id.len() <= MAX_ID_LEN && id.bytes().all(|b| b.is_ascii_graphic())
99}
100
101/// Filled with the matched route template by the DI layer (which runs after
102/// routing) so outer middleware can read it once the response is ready.
103#[derive(Clone, Default)]
104pub(crate) struct RouteSlot(Arc<Mutex<Option<String>>>);
105
106impl RouteSlot {
107    fn set(&self, route: String) {
108        *self.0.lock().unwrap_or_else(PoisonError::into_inner) = Some(route);
109    }
110
111    fn get(&self) -> Option<String> {
112        self.0
113            .lock()
114            .unwrap_or_else(PoisonError::into_inner)
115            .clone()
116    }
117}
118
119/// Record the matched route in the request's [`RouteSlot`], if any.
120pub(crate) fn note_matched_path(parts: &Parts) {
121    if let (Some(slot), Some(path)) = (
122        parts.extensions.get::<RouteSlot>(),
123        parts.extensions.get::<axum::extract::MatchedPath>(),
124    ) {
125        slot.set(path.as_str().to_owned());
126    }
127}
128
129/// Emits an `http.request` tracing span per request with `request_id`,
130/// `method`, `route` (matched path template via axum `MatchedPath`, or
131/// `"<unmatched>"`), `status` and `latency_ms`.
132///
133/// **Privacy:** only those fields are recorded. Headers (Authorization,
134/// Cookie, API keys, ...), the query string and bodies are never logged.
135/// Register [`RequestIdLayer`] first so the id is available.
136#[derive(Debug, Clone, Default)]
137pub struct RequestLogging;
138
139impl RequestLogging {
140    /// Create the middleware.
141    pub fn new() -> Self {
142        Self
143    }
144
145    fn wrap(&self, inner: BoxService) -> BoxService {
146        from_fn(|mut req: Request, next: Next| async move {
147            let start = Instant::now();
148            let slot = RouteSlot::default();
149            req.extensions_mut().insert(slot.clone());
150            let request_id = req
151                .extensions()
152                .get::<RequestId>()
153                .map_or_else(|| "-".to_owned(), |id| id.0.clone());
154            let method = req.method().clone();
155            let span = tracing::info_span!(
156                "http.request",
157                request_id = %request_id,
158                method = %method,
159                route = tracing::field::Empty,
160                status = tracing::field::Empty,
161                latency_ms = tracing::field::Empty,
162            );
163            let response: Response = next.run(req).instrument(span.clone()).await;
164            let status = response.status().as_u16();
165            let latency_ms = u64::try_from(start.elapsed().as_millis()).unwrap_or(u64::MAX);
166            let route = slot.get().unwrap_or_else(|| "<unmatched>".to_owned());
167            span.record("route", tracing::field::display(&route));
168            span.record("status", status);
169            span.record("latency_ms", latency_ms);
170            tracing::info!(parent: &span, %route, status, latency_ms, "request completed");
171            response
172        })
173        .layer(inner)
174    }
175}
176
177impl_layer!(RequestIdLayer, RequestLogging);
178
179#[cfg(test)]
180#[allow(clippy::unwrap_used)]
181mod tests {
182    use crate::app::App;
183    use crate::body::Body;
184    use crate::routing::get;
185    use http::Request;
186    use std::sync::atomic::{AtomicUsize, Ordering};
187    use std::sync::{Arc, Mutex};
188    use tower::ServiceExt;
189
190    #[derive(Clone, Default)]
191    struct Capture {
192        lines: Arc<Mutex<Vec<String>>>,
193        next_id: Arc<AtomicUsize>,
194    }
195
196    struct Fields(String);
197
198    impl tracing::field::Visit for Fields {
199        fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
200            use std::fmt::Write as _;
201            let _ = write!(self.0, "{}={value:?} ", field.name());
202        }
203
204        fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
205            use std::fmt::Write as _;
206            let _ = write!(self.0, "{}={value} ", field.name());
207        }
208
209        fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
210            use std::fmt::Write as _;
211            let _ = write!(self.0, "{}={value} ", field.name());
212        }
213
214        fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
215            use std::fmt::Write as _;
216            let _ = write!(self.0, "{}={value} ", field.name());
217        }
218
219        fn record_u128(&mut self, field: &tracing::field::Field, value: u128) {
220            use std::fmt::Write as _;
221            let _ = write!(self.0, "{}={value} ", field.name());
222        }
223    }
224
225    impl tracing::Subscriber for Capture {
226        fn enabled(&self, _: &tracing::Metadata<'_>) -> bool {
227            true
228        }
229
230        fn new_span(&self, attrs: &tracing::span::Attributes<'_>) -> tracing::span::Id {
231            let mut fields = Fields(format!("span {} ", attrs.metadata().name()));
232            attrs.record(&mut fields);
233            self.lines.lock().unwrap().push(fields.0);
234            let id = self.next_id.fetch_add(1, Ordering::SeqCst) as u64 + 1;
235            tracing::span::Id::from_u64(id)
236        }
237
238        fn record(&self, _: &tracing::span::Id, values: &tracing::span::Record<'_>) {
239            let mut fields = Fields("record ".to_owned());
240            values.record(&mut fields);
241            self.lines.lock().unwrap().push(fields.0);
242        }
243
244        fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {}
245
246        fn event(&self, event: &tracing::Event<'_>) {
247            let mut fields = Fields("event ".to_owned());
248            event.record(&mut fields);
249            self.lines.lock().unwrap().push(fields.0);
250        }
251
252        fn enter(&self, _: &tracing::span::Id) {}
253
254        fn exit(&self, _: &tracing::span::Id) {}
255    }
256
257    async fn send(app: App, path: &str, headers: &[(&str, &str)]) -> crate::http::StatusCode {
258        let mut req = Request::builder().method("GET").uri(path);
259        for (k, v) in headers {
260            req = req.header(*k, *v);
261        }
262        let service = app.into_router_service().unwrap();
263        service
264            .oneshot(req.body(Body::from("")).unwrap())
265            .await
266            .unwrap()
267            .status()
268    }
269
270    #[tokio::test]
271    async fn http_request_span_records_fields_and_never_secrets() {
272        let capture = Capture::default();
273        let _guard = tracing::subscriber::set_default(capture.clone());
274        let app = App::new()
275            .route("/users/{id}", get(|| async { "u" }))
276            .request_id()
277            .request_logging();
278        let status = send(
279            app,
280            "/users/42?api_key=QUERYSECRET",
281            &[
282                ("authorization", "Bearer TOPSECRET"),
283                ("cookie", "session=COOKIESECRET"),
284                ("x-api-key", "KEYSECRET"),
285                ("x-request-id", "req-1"),
286            ],
287        )
288        .await;
289        assert_eq!(status, crate::http::StatusCode::OK);
290        let logged = capture.lines.lock().unwrap().join("\n");
291        assert!(logged.contains("span http.request"), "span name:\n{logged}");
292        for secret in [
293            "TOPSECRET",
294            "COOKIESECRET",
295            "KEYSECRET",
296            "QUERYSECRET",
297            "api_key=",
298        ] {
299            assert!(
300                !logged.contains(secret),
301                "{secret} leaked into logs:\n{logged}"
302            );
303        }
304        assert!(
305            logged.contains("request_id=req-1") || logged.contains("request_id=\"req-1\""),
306            "{logged}"
307        );
308        assert!(logged.contains("/users/{id}"), "matched route:\n{logged}");
309        assert!(logged.contains("status=200"), "{logged}");
310        assert!(logged.contains("latency_ms="), "{logged}");
311        assert!(
312            logged.contains("method=GET") || logged.contains("method=\"GET\""),
313            "{logged}"
314        );
315        assert!(!logged.contains("/users/42?"), "{logged}");
316        assert!(
317            !logged.contains("Authorization") && !logged.contains("Bearer "),
318            "{logged}"
319        );
320    }
321
322    #[tokio::test]
323    async fn unmatched_route_is_recorded() {
324        let capture = Capture::default();
325        let _guard = tracing::subscriber::set_default(capture.clone());
326        let app = App::new()
327            .route("/hello", get(|| async { "h" }))
328            .request_id()
329            .request_logging();
330        let status = send(
331            app,
332            "/missing?token=QUERYSECRET",
333            &[("authorization", "Bearer TOPSECRET")],
334        )
335        .await;
336        assert_eq!(status, crate::http::StatusCode::NOT_FOUND);
337        let logged = capture.lines.lock().unwrap().join("\n");
338        assert!(logged.contains("<unmatched>"), "{logged}");
339        assert!(logged.contains("status=404"), "{logged}");
340        assert!(!logged.contains("QUERYSECRET"), "{logged}");
341        assert!(!logged.contains("TOPSECRET"), "{logged}");
342    }
343}
siderite_core/middleware/observe.rs

siderite_core/middleware/
observe.rs
