use axum::extract::Request;
use axum::middleware::Next;
use axum::response::Response;
use std::sync::atomic::{AtomicU64, Ordering};
use std::time::Instant;
use crate::log::LogLevel;
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
pub struct RequestId {
timestamp_secs: u64,
counter: u64,
}
impl RequestId {
pub fn to_hex(&self) -> String {
format!("{:08x}{:08x}", self.timestamp_secs, self.counter)
}
pub fn timestamp_secs(&self) -> u64 {
self.timestamp_secs
}
pub fn counter(&self) -> u64 {
self.counter
}
}
impl std::fmt::Display for RequestId {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
f.write_str(&self.to_hex())
}
}
static REQUEST_ID_COUNTER: AtomicU64 = AtomicU64::new(0);
pub fn generate_request_id() -> RequestId {
let counter = REQUEST_ID_COUNTER.fetch_add(1, Ordering::Relaxed);
let timestamp_secs = std::time::SystemTime::now()
.duration_since(std::time::UNIX_EPOCH)
.map(|d| d.as_secs())
.unwrap_or(0);
RequestId {
timestamp_secs,
counter,
}
}
#[derive(Debug, Clone, Default)]
pub struct LogConfig {
pub exclude_paths: Vec<String>,
}
impl LogConfig {
pub fn with_exclude_paths(mut self, paths: Vec<String>) -> Self {
self.exclude_paths = paths;
self
}
pub fn is_excluded(&self, path: &str) -> bool {
crate::middleware::auth::is_route_allowed(path, &self.exclude_paths)
}
}
pub fn log_level_for_status(status: u16) -> LogLevel {
match status {
400..=499 => LogLevel::Warn,
500..=599 => LogLevel::Error,
_ => LogLevel::Info,
}
}
pub fn format_request_log(
method: &str,
uri: &str,
status: u16,
duration_ms: u64,
request_id: &RequestId,
) -> String {
format!(
"request_id={} method={} uri={} status={} duration_ms={}",
request_id.to_hex(),
method,
uri,
status,
duration_ms
)
}
pub async fn log_middleware(req: Request, next: Next) -> Response {
log_middleware_inner(req, next, &LogConfig::default()).await
}
pub async fn log_middleware_with_config(
axum::extract::State(config): axum::extract::State<LogConfig>,
req: Request,
next: Next,
) -> Response {
log_middleware_inner(req, next, &config).await
}
async fn log_middleware_inner(req: Request, next: Next, config: &LogConfig) -> Response {
let method = req.method().clone();
let uri = req.uri().path().to_string();
let request_id = req
.extensions()
.get::<RequestId>()
.copied()
.unwrap_or_else(generate_request_id);
let start = Instant::now();
let mut req = req;
req.extensions_mut().insert(request_id);
let response = next.run(req).await;
let duration_ms = start.elapsed().as_millis() as u64;
if !config.is_excluded(&uri) {
let status = response.status().as_u16();
let level = log_level_for_status(status);
let request_id_hex = request_id.to_hex();
match level {
LogLevel::Debug => tracing::debug!(
request_id = %request_id_hex,
method = %method,
uri = %uri,
status = status,
duration_ms = duration_ms,
"request completed"
),
LogLevel::Info => tracing::info!(
request_id = %request_id_hex,
method = %method,
uri = %uri,
status = status,
duration_ms = duration_ms,
"request completed"
),
LogLevel::Warn => tracing::warn!(
request_id = %request_id_hex,
method = %method,
uri = %uri,
status = status,
duration_ms = duration_ms,
"request completed"
),
LogLevel::Error => tracing::error!(
request_id = %request_id_hex,
method = %method,
uri = %uri,
status = status,
duration_ms = duration_ms,
"request completed"
),
}
}
response
}
#[cfg(test)]
mod tests {
use super::*;
use axum::body::Body;
use axum::http::StatusCode;
use axum::Router;
use http_body_util::BodyExt;
use tower::ServiceExt;
async fn read_body(resp: Response) -> String {
let bytes = resp.into_body().collect().await.unwrap().to_bytes();
String::from_utf8(bytes.to_vec()).unwrap()
}
fn make_request(method: &str, uri: &str) -> Request {
Request::builder()
.method(method)
.uri(uri)
.body(Body::empty())
.unwrap()
}
fn build_app() -> Router {
Router::new()
.route(
"/ok",
axum::routing::get(|| async { axum::http::StatusCode::OK }),
)
.route(
"/notfound",
axum::routing::get(|| async { axum::http::StatusCode::NOT_FOUND }),
)
.route(
"/error",
axum::routing::get(|| async { axum::http::StatusCode::INTERNAL_SERVER_ERROR }),
)
.route("/body", axum::routing::get(|| async { "hello" }))
.layer(axum::middleware::from_fn(log_middleware))
}
#[test]
fn test_request_id_to_hex_is_16_chars() {
let id = RequestId {
timestamp_secs: 0x12345678,
counter: 0x9ABCDEF0,
};
let hex = id.to_hex();
assert_eq!(hex.len(), 16);
assert_eq!(hex, "123456789abcdef0");
}
#[test]
fn test_request_id_to_hex_zero() {
let id = RequestId {
timestamp_secs: 0,
counter: 0,
};
assert_eq!(id.to_hex(), "0000000000000000");
}
#[test]
fn test_request_id_to_hex_max() {
let id = RequestId {
timestamp_secs: u64::MAX,
counter: u64::MAX,
};
let hex = id.to_hex();
assert_eq!(hex.len(), 32); }
#[test]
fn test_request_id_display_matches_to_hex() {
let id = RequestId {
timestamp_secs: 0x12345678,
counter: 0x9ABCDEF0,
};
assert_eq!(format!("{}", id), id.to_hex());
}
#[test]
fn test_request_id_accessors() {
let id = RequestId {
timestamp_secs: 100,
counter: 200,
};
assert_eq!(id.timestamp_secs(), 100);
assert_eq!(id.counter(), 200);
}
#[test]
fn test_request_id_equality() {
let id1 = RequestId {
timestamp_secs: 1,
counter: 2,
};
let id2 = RequestId {
timestamp_secs: 1,
counter: 2,
};
let id3 = RequestId {
timestamp_secs: 1,
counter: 3,
};
assert_eq!(id1, id2);
assert_ne!(id1, id3);
}
#[test]
fn test_generate_request_id_returns_unique() {
let id1 = generate_request_id();
let id2 = generate_request_id();
assert_ne!(id1.counter(), id2.counter());
assert_eq!(id2.counter(), id1.counter() + 1);
}
#[test]
fn test_generate_request_id_hex_is_16_chars() {
let id = generate_request_id();
let hex = id.to_hex();
assert!(hex.len() >= 16);
}
#[test]
fn test_log_level_for_2xx_returns_info() {
assert_eq!(log_level_for_status(200), LogLevel::Info);
assert_eq!(log_level_for_status(201), LogLevel::Info);
assert_eq!(log_level_for_status(204), LogLevel::Info);
}
#[test]
fn test_log_level_for_3xx_returns_info() {
assert_eq!(log_level_for_status(301), LogLevel::Info);
assert_eq!(log_level_for_status(302), LogLevel::Info);
assert_eq!(log_level_for_status(304), LogLevel::Info);
}
#[test]
fn test_log_level_for_4xx_returns_warn() {
assert_eq!(log_level_for_status(400), LogLevel::Warn);
assert_eq!(log_level_for_status(401), LogLevel::Warn);
assert_eq!(log_level_for_status(403), LogLevel::Warn);
assert_eq!(log_level_for_status(404), LogLevel::Warn);
assert_eq!(log_level_for_status(422), LogLevel::Warn);
assert_eq!(log_level_for_status(499), LogLevel::Warn);
}
#[test]
fn test_log_level_for_5xx_returns_error() {
assert_eq!(log_level_for_status(500), LogLevel::Error);
assert_eq!(log_level_for_status(501), LogLevel::Error);
assert_eq!(log_level_for_status(502), LogLevel::Error);
assert_eq!(log_level_for_status(503), LogLevel::Error);
assert_eq!(log_level_for_status(599), LogLevel::Error);
}
#[test]
fn test_log_level_for_1xx_returns_info() {
assert_eq!(log_level_for_status(100), LogLevel::Info);
assert_eq!(log_level_for_status(101), LogLevel::Info);
}
#[test]
fn test_log_level_for_boundary() {
assert_eq!(log_level_for_status(399), LogLevel::Info);
assert_eq!(log_level_for_status(400), LogLevel::Warn);
assert_eq!(log_level_for_status(499), LogLevel::Warn);
assert_eq!(log_level_for_status(500), LogLevel::Error);
assert_eq!(log_level_for_status(599), LogLevel::Error);
assert_eq!(log_level_for_status(600), LogLevel::Info);
}
#[test]
fn test_format_request_log_basic() {
let request_id = RequestId {
timestamp_secs: 0x12345678,
counter: 0x9ABCDEF0,
};
let msg = format_request_log("GET", "/api/users", 200, 15, &request_id);
assert_eq!(
msg,
"request_id=123456789abcdef0 method=GET uri=/api/users status=200 duration_ms=15"
);
}
#[test]
fn test_format_request_log_post_method() {
let request_id = RequestId {
timestamp_secs: 0,
counter: 1,
};
let msg = format_request_log("POST", "/api/orders", 201, 42, &request_id);
assert_eq!(
msg,
"request_id=0000000000000001 method=POST uri=/api/orders status=201 duration_ms=42"
);
}
#[test]
fn test_format_request_log_error_status() {
let request_id = RequestId {
timestamp_secs: 0,
counter: 0,
};
let msg = format_request_log("GET", "/missing", 404, 5, &request_id);
assert_eq!(
msg,
"request_id=0000000000000000 method=GET uri=/missing status=404 duration_ms=5"
);
}
#[test]
fn test_format_request_log_with_query_string_in_uri() {
let request_id = RequestId {
timestamp_secs: 0,
counter: 0,
};
let msg = format_request_log("GET", "/api?foo=bar", 200, 1, &request_id);
assert!(msg.contains("uri=/api?foo=bar"));
}
#[test]
fn test_log_config_default_empty_exclude_paths() {
let config = LogConfig::default();
assert!(config.exclude_paths.is_empty());
}
#[test]
fn test_log_config_with_exclude_paths() {
let config = LogConfig::default().with_exclude_paths(vec!["/health".to_string()]);
assert_eq!(config.exclude_paths, vec!["/health".to_string()]);
}
#[test]
fn test_log_config_is_excluded_exact_match() {
let config = LogConfig::default().with_exclude_paths(vec!["/health".to_string()]);
assert!(config.is_excluded("/health"));
assert!(!config.is_excluded("/health/detail"));
assert!(!config.is_excluded("/api"));
}
#[test]
fn test_log_config_is_excluded_wildcard_match() {
let config = LogConfig::default().with_exclude_paths(vec!["/health/*".to_string()]);
assert!(config.is_excluded("/health/check"));
assert!(config.is_excluded("/health/deep/nested"));
assert!(!config.is_excluded("/health"));
assert!(!config.is_excluded("/api"));
}
#[test]
fn test_log_config_is_excluded_empty_list() {
let config = LogConfig::default();
assert!(!config.is_excluded("/any"));
}
#[test]
fn test_log_config_is_excluded_multiple_entries() {
let config = LogConfig::default()
.with_exclude_paths(vec!["/health".to_string(), "/metrics/*".to_string()]);
assert!(config.is_excluded("/health"));
assert!(config.is_excluded("/metrics/prometheus"));
assert!(!config.is_excluded("/api"));
}
#[tokio::test]
async fn test_log_middleware_returns_response_unchanged() {
let app = build_app();
let resp = app.oneshot(make_request("GET", "/body")).await.unwrap();
let body = read_body(resp).await;
assert_eq!(body, "hello");
}
#[tokio::test]
async fn test_log_middleware_returns_correct_status() {
let app = build_app();
let resp = app.oneshot(make_request("GET", "/ok")).await.unwrap();
assert_eq!(resp.status(), StatusCode::OK);
}
#[tokio::test]
async fn test_log_middleware_injects_request_id() {
let app = Router::new()
.route(
"/",
axum::routing::get(|req: Request| async move {
let request_id = req.extensions().get::<RequestId>().unwrap();
format!("request_id:{}", request_id.to_hex())
}),
)
.layer(axum::middleware::from_fn(log_middleware));
let resp = app.oneshot(make_request("GET", "/")).await.unwrap();
assert_eq!(resp.status(), StatusCode::OK);
let body = read_body(resp).await;
assert!(body.starts_with("request_id:"));
let hex = body.strip_prefix("request_id:").unwrap();
assert!(hex.len() >= 16);
}
#[tokio::test]
async fn test_log_middleware_generates_unique_request_ids() {
let app = Router::new()
.route(
"/",
axum::routing::get(|req: Request| async move {
let request_id = req.extensions().get::<RequestId>().unwrap();
request_id.to_hex()
}),
)
.layer(axum::middleware::from_fn(log_middleware));
let resp1 = app.clone().oneshot(make_request("GET", "/")).await.unwrap();
let hex1 = read_body(resp1).await;
let resp2 = app.oneshot(make_request("GET", "/")).await.unwrap();
let hex2 = read_body(resp2).await;
assert_ne!(hex1, hex2);
}
#[tokio::test]
async fn test_log_middleware_preserves_existing_request_id() {
let existing_id = RequestId {
timestamp_secs: 0xDEADBEEF,
counter: 0x12345678,
};
let app = Router::new()
.route(
"/",
axum::routing::get(|req: Request| async move {
let request_id = req.extensions().get::<RequestId>().unwrap();
request_id.to_hex()
}),
)
.layer(axum::middleware::from_fn(log_middleware))
.layer(
tower::ServiceBuilder::new().layer(tower::layer::layer_fn(move |service| {
tower::util::MapRequest::new(service, move |mut req: Request| {
req.extensions_mut().insert(existing_id);
req
})
})),
);
let resp = app.oneshot(make_request("GET", "/")).await.unwrap();
let body = read_body(resp).await;
assert_eq!(body, "deadbeef12345678");
}
#[tokio::test]
async fn test_log_middleware_records_2xx_status() {
let app = build_app();
let resp = app.oneshot(make_request("GET", "/ok")).await.unwrap();
assert_eq!(resp.status(), StatusCode::OK);
}
#[tokio::test]
async fn test_log_middleware_records_4xx_status() {
let app = build_app();
let resp = app.oneshot(make_request("GET", "/notfound")).await.unwrap();
assert_eq!(resp.status(), StatusCode::NOT_FOUND);
}
#[tokio::test]
async fn test_log_middleware_records_5xx_status() {
let app = build_app();
let resp = app.oneshot(make_request("GET", "/error")).await.unwrap();
assert_eq!(resp.status(), StatusCode::INTERNAL_SERVER_ERROR);
}
#[tokio::test]
async fn test_log_middleware_with_config_excludes_path() {
let config = LogConfig::default().with_exclude_paths(vec!["/health".to_string()]);
let app = Router::new()
.route("/health", axum::routing::get(|| async { "healthy" }))
.layer(axum::middleware::from_fn_with_state(
config,
log_middleware_with_config,
));
let resp = app.oneshot(make_request("GET", "/health")).await.unwrap();
assert_eq!(resp.status(), StatusCode::OK);
let body = read_body(resp).await;
assert_eq!(body, "healthy");
}
#[tokio::test]
async fn test_log_middleware_with_config_wildcard_exclude() {
let config = LogConfig::default().with_exclude_paths(vec!["/metrics/*".to_string()]);
let app = Router::new()
.route(
"/metrics/prometheus",
axum::routing::get(|| async { "metrics" }),
)
.layer(axum::middleware::from_fn_with_state(
config,
log_middleware_with_config,
));
let resp = app
.oneshot(make_request("GET", "/metrics/prometheus"))
.await
.unwrap();
assert_eq!(resp.status(), StatusCode::OK);
}
#[tokio::test]
async fn test_log_middleware_preserves_method_and_uri() {
let app = build_app();
let resp = app.oneshot(make_request("GET", "/ok")).await.unwrap();
assert_eq!(resp.status(), StatusCode::OK);
}
#[tokio::test]
async fn test_log_middleware_duration_is_non_negative() {
let app = build_app();
let start = std::time::Instant::now();
let resp = app.oneshot(make_request("GET", "/ok")).await.unwrap();
let elapsed = start.elapsed();
assert!(resp.status().is_success());
assert!(elapsed.as_millis() < 5000); }
#[tokio::test]
async fn test_log_middleware_handles_post_request() {
let app = Router::new()
.route(
"/submit",
axum::routing::post(|| async { axum::http::StatusCode::CREATED }),
)
.layer(axum::middleware::from_fn(log_middleware));
let req = Request::builder()
.method("POST")
.uri("/submit")
.body(Body::empty())
.unwrap();
let resp = app.oneshot(req).await.unwrap();
assert_eq!(resp.status(), StatusCode::CREATED);
}
#[tokio::test]
async fn test_log_middleware_chains_with_other_middleware() {
async fn add_header_middleware(req: Request, next: Next) -> Response {
let mut resp = next.run(req).await;
resp.headers_mut()
.insert("X-Custom", "value".parse().unwrap());
resp
}
let app = Router::new()
.route("/", axum::routing::get(|| async { "ok" }))
.layer(axum::middleware::from_fn(add_header_middleware))
.layer(axum::middleware::from_fn(log_middleware));
let resp = app.oneshot(make_request("GET", "/")).await.unwrap();
assert_eq!(resp.status(), StatusCode::OK);
assert_eq!(resp.headers().get("X-Custom").unwrap(), "value");
}
#[test]
fn test_php_apart_level_alignment() {
assert_eq!(log_level_for_status(200), LogLevel::Info);
assert_eq!(log_level_for_status(404), LogLevel::Warn);
assert_eq!(log_level_for_status(500), LogLevel::Error);
}
#[test]
fn test_php_think_logger_level_alignment() {
let levels = [
LogLevel::Debug,
LogLevel::Info,
LogLevel::Warn,
LogLevel::Error,
];
assert_eq!(levels.len(), 4);
}
#[test]
fn test_request_id_format_aligns_with_w3c_span_id_length() {
let id = RequestId {
timestamp_secs: 0x12345678,
counter: 0x9ABCDEF0,
};
assert_eq!(id.to_hex().len(), 16);
}
}