warpdrive_proxy/middleware/
logging.rs

1//! Request/response logging middleware
2//!
3//! Logs detailed information about each HTTP request and response.
4//! Uses structured logging via tracing for machine-readable output.
5//!
6//! # Logged Information
7//!
8//! - Request: method, path, query, content-type, content-length, user-agent, remote IP
9//! - Response: status, content-type, content-length, duration, cache status
10//! - Additional: X-Forwarded-For (if present), X-Cache header
11//!
12//! # Performance
13//!
14//! Logging is designed to be low-overhead:
15//! - No blocking I/O in the hot path
16//! - Structured logging for efficient serialization
17//! - Minimal string allocations
18
19use async_trait::async_trait;
20use pingora::http::ResponseHeader;
21use pingora::prelude::*;
22use std::time::Instant;
23use tracing::info;
24
25use super::{Middleware, MiddlewareContext};
26use crate::metrics::{HTTP_REQUEST_DURATION_SECONDS, HTTP_REQUESTS_TOTAL};
27
28/// Logging middleware
29///
30/// Captures request/response metrics and logs them with structured data.
31pub struct LoggingMiddleware;
32
33impl LoggingMiddleware {
34    /// Create new logging middleware
35    pub fn new() -> Self {
36        Self
37    }
38
39    /// Get header value as string, returning empty string if not present
40    fn get_header_str<'a>(headers: &'a http::HeaderMap, name: &str) -> &'a str {
41        headers
42            .get(name)
43            .and_then(|v| v.to_str().ok())
44            .unwrap_or("")
45    }
46}
47
48impl Default for LoggingMiddleware {
49    fn default() -> Self {
50        Self::new()
51    }
52}
53
54#[async_trait]
55impl Middleware for LoggingMiddleware {
56    /// Record request start time
57    ///
58    /// This captures the request start timestamp in the context for
59    /// duration calculation in the response phase.
60    async fn request_filter(
61        &self,
62        _session: &mut Session,
63        ctx: &mut MiddlewareContext,
64    ) -> Result<()> {
65        // Record request start time (already done in MiddlewareContext::default)
66        ctx.request_start = Instant::now();
67        Ok(())
68    }
69
70    /// Log request and response details
71    ///
72    /// This is called after the response is received from upstream,
73    /// capturing all relevant metrics for the access log.
74    async fn response_filter(
75        &self,
76        session: &mut Session,
77        upstream_response: &mut ResponseHeader,
78        ctx: &mut MiddlewareContext,
79    ) -> Result<()> {
80        let elapsed = ctx.request_start.elapsed();
81        let req_header = session.req_header();
82        let resp_header = upstream_response;
83
84        // Extract request metadata
85        let method = req_header.method.as_str();
86        let path = req_header.uri.path();
87        let query = req_header.uri.query().unwrap_or("");
88        // Use real client IP from context (normalized by trusted_ranges middleware)
89        let remote_addr = ctx.real_client_ip.to_string();
90
91        let req_content_type = Self::get_header_str(&req_header.headers, "content-type");
92        let req_content_length = req_header
93            .headers
94            .get("content-length")
95            .and_then(|v| v.to_str().ok())
96            .and_then(|s| s.parse::<i64>().ok())
97            .unwrap_or(-1);
98
99        let user_agent = Self::get_header_str(&req_header.headers, "user-agent");
100
101        // Extract response metadata
102        let status = resp_header.status.as_u16();
103        ctx.status_code = status;
104
105        let resp_content_type = Self::get_header_str(&resp_header.headers, "content-type");
106        let resp_content_length = resp_header
107            .headers
108            .get("content-length")
109            .and_then(|v| v.to_str().ok())
110            .and_then(|s| s.parse::<i64>().ok())
111            .unwrap_or(-1);
112
113        let cache_status = Self::get_header_str(&resp_header.headers, "x-cache");
114
115        // Record Prometheus metrics
116        let status_str = status.to_string();
117        let method_str = method.to_string();
118
119        HTTP_REQUESTS_TOTAL
120            .with_label_values(&[&status_str, &method_str])
121            .inc();
122
123        HTTP_REQUEST_DURATION_SECONDS
124            .with_label_values(&[&method_str, &status_str])
125            .observe(elapsed.as_secs_f64());
126
127        // Log with structured data
128        info!(
129            path = %path,
130            status = status,
131            dur = elapsed.as_millis() as u64,
132            method = %method,
133            req_content_length = req_content_length,
134            req_content_type = %req_content_type,
135            resp_content_length = resp_content_length,
136            resp_content_type = %resp_content_type,
137            remote_addr = %remote_addr,
138            user_agent = %user_agent,
139            cache = %cache_status,
140            query = %query,
141            "Request"
142        );
143
144        Ok(())
145    }
146}
147
148#[cfg(test)]
149mod tests {
150    use super::*;
151
152    #[test]
153    fn test_logging_middleware_creation() {
154        let middleware = LoggingMiddleware::new();
155        // Just verify it can be created
156        drop(middleware);
157
158        let middleware_default = LoggingMiddleware::default();
159        drop(middleware_default);
160    }
161
162    #[test]
163    fn test_get_header_str() {
164        let mut headers = http::HeaderMap::new();
165        headers.insert("content-type", "text/html".parse().unwrap());
166
167        assert_eq!(
168            LoggingMiddleware::get_header_str(&headers, "content-type"),
169            "text/html"
170        );
171        assert_eq!(LoggingMiddleware::get_header_str(&headers, "missing"), "");
172    }
173}
warpdrive_proxy/middleware/logging.rs

warpdrive_proxy/middleware/
logging.rs
