From 20b5eeab3a3f96c67dc95b1e01c661938defad71 Mon Sep 17 00:00:00 2001 From: Spencer Ferris <3319370+spencewenski@users.noreply.github.com> Date: Wed, 31 Jul 2024 01:09:12 -0700 Subject: [PATCH] feat: Add middleware to log the request/response payloads (#304) It can be useful when developing an application to be able to see the request/response bodies as they are seen by the server. Add an Axum middleware to do this. Because the middleware buffers the entire request/response, it is disabled by default. If we add a mechanism to provide different defaults per environment, this middleware may be enabled in non-prod environments by default in the future. --- Cargo.toml | 1 + justfile | 5 + src/config/service/http/default.toml | 4 + src/config/service/http/middleware.rs | 3 + ...ster__config__app_config__tests__test.snap | 4 + src/service/http/middleware/default.rs | 2 + .../middleware/{tracing.rs => tracing/mod.rs} | 2 + .../middleware/tracing/req_res_logging.rs | 155 ++++++++++++++++++ 8 files changed, 176 insertions(+) rename src/service/http/middleware/{tracing.rs => tracing/mod.rs} (99%) create mode 100644 src/service/http/middleware/tracing/req_res_logging.rs diff --git a/Cargo.toml b/Cargo.toml index e376dd78..8a7b4f12 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -52,6 +52,7 @@ tower = { version = "0.4.13", optional = true } tower-http = { version = "0.5.0", features = ["trace", "timeout", "request-id", "util", "normalize-path", "sensitive-headers", "catch-panic", "compression-full", "decompression-full", "limit", "cors"], optional = true } aide = { workspace = true, features = ["axum", "redoc", "scalar", "macros"], optional = true } schemars = { workspace = true, optional = true } +http-body-util = "0.1.0" # DB sea-orm = { version = "1.0.0-rc.5", features = ["debug-print", "runtime-tokio-rustls", "sqlx-postgres", "macros"], optional = true } diff --git a/justfile b/justfile index d17c98b3..ebbc4e4c 100644 --- a/justfile +++ b/justfile @@ -35,6 +35,11 @@ coverage: coverage-clean coverage-open: coverage open target/llvm-cov-target/debug/coverage/index.html +alias fmt := format +# Format the project +format: + cargo fmt + # Run a suite of checks. These checks are fairly comprehensive and will catch most issues. However, they are still less than what is run in CI. check: .cargo-husky/hooks/pre-push diff --git a/src/config/service/http/default.toml b/src/config/service/http/default.toml index 08b5be69..7d2dd153 100644 --- a/src/config/service/http/default.toml +++ b/src/config/service/http/default.toml @@ -41,6 +41,10 @@ limit = "5 MB" [service.http.middleware.cors] priority = -9950 +[service.http.middleware.request-response-logging] +enable = false +priority = 0 + # Initializers [service.http.initializer] default-enable = true diff --git a/src/config/service/http/middleware.rs b/src/config/service/http/middleware.rs index 2d7c7c6a..62ad5006 100644 --- a/src/config/service/http/middleware.rs +++ b/src/config/service/http/middleware.rs @@ -11,6 +11,7 @@ use crate::service::http::middleware::sensitive_headers::{ }; use crate::service::http::middleware::size_limit::SizeLimitConfig; use crate::service::http::middleware::timeout::TimeoutConfig; +use crate::service::http::middleware::tracing::req_res_logging::ReqResLoggingConfig; use crate::service::http::middleware::tracing::TracingConfig; use crate::util::serde::default_true; use axum::extract::FromRef; @@ -50,6 +51,8 @@ pub struct Middleware { pub cors: MiddlewareConfig, + pub request_response_logging: MiddlewareConfig, + /// Allows providing configs for custom middleware. Any configs that aren't pre-defined above /// will be collected here. /// diff --git a/src/config/snapshots/roadster__config__app_config__tests__test.snap b/src/config/snapshots/roadster__config__app_config__tests__test.snap index 83032b06..628086e9 100644 --- a/src/config/snapshots/roadster__config__app_config__tests__test.snap +++ b/src/config/snapshots/roadster__config__app_config__tests__test.snap @@ -81,6 +81,10 @@ priority = -9950 preset = 'restrictive' max-age = 3600000 +[service.http.middleware.request-response-logging] +enable = false +priority = 0 + [service.http.initializer] default-enable = true diff --git a/src/service/http/middleware/default.rs b/src/service/http/middleware/default.rs index 8856cb83..4f937a84 100644 --- a/src/service/http/middleware/default.rs +++ b/src/service/http/middleware/default.rs @@ -10,6 +10,7 @@ use crate::service::http::middleware::sensitive_headers::{ }; use crate::service::http::middleware::size_limit::RequestBodyLimitMiddleware; use crate::service::http::middleware::timeout::TimeoutMiddleware; +use crate::service::http::middleware::tracing::req_res_logging::RequestLoggingMiddleware; use crate::service::http::middleware::tracing::TracingMiddleware; use crate::service::http::middleware::Middleware; use axum::extract::FromRef; @@ -31,6 +32,7 @@ where Box::new(TimeoutMiddleware), Box::new(RequestBodyLimitMiddleware), Box::new(CorsMiddleware), + Box::new(RequestLoggingMiddleware), ]; middleware .into_iter() diff --git a/src/service/http/middleware/tracing.rs b/src/service/http/middleware/tracing/mod.rs similarity index 99% rename from src/service/http/middleware/tracing.rs rename to src/service/http/middleware/tracing/mod.rs index 3cd9cb5b..3eba6301 100644 --- a/src/service/http/middleware/tracing.rs +++ b/src/service/http/middleware/tracing/mod.rs @@ -1,3 +1,5 @@ +pub mod req_res_logging; + use crate::app::context::AppContext; use crate::error::RoadsterResult; use crate::service::http::middleware::Middleware; diff --git a/src/service/http/middleware/tracing/req_res_logging.rs b/src/service/http/middleware/tracing/req_res_logging.rs new file mode 100644 index 00000000..2dfcc9e7 --- /dev/null +++ b/src/service/http/middleware/tracing/req_res_logging.rs @@ -0,0 +1,155 @@ +//! Middleware to log the request/response payloads. Logs at the debug level. + +use crate::app::context::AppContext; +use crate::error::RoadsterResult; +use crate::service::http::middleware::Middleware; +use axum::body::{Body, Bytes}; +use axum::extract::{FromRef, Request}; +use axum::http::StatusCode; +use axum::middleware::Next; +use axum::response::{IntoResponse, Response}; +use axum::{middleware, Router}; +use http_body_util::BodyExt; +use serde_derive::{Deserialize, Serialize}; +use tracing::debug; +use validator::Validate; + +#[derive(Debug, Clone, Default, Validate, Serialize, Deserialize)] +#[serde(rename_all = "kebab-case", default)] +#[non_exhaustive] +pub struct ReqResLoggingConfig {} + +pub struct RequestLoggingMiddleware; +impl Middleware for RequestLoggingMiddleware +where + S: Clone + Send + Sync + 'static, + AppContext: FromRef, +{ + fn name(&self) -> String { + "request-response-logging".to_string() + } + + fn enabled(&self, state: &S) -> bool { + AppContext::from_ref(state) + .config() + .service + .http + .custom + .middleware + .request_response_logging + .common + .enabled(state) + } + + fn priority(&self, state: &S) -> i32 { + AppContext::from_ref(state) + .config() + .service + .http + .custom + .middleware + .request_response_logging + .common + .priority + } + + fn install(&self, router: Router, _state: &S) -> RoadsterResult { + let router = router.layer(middleware::from_fn(log_req_res_bodies)); + + Ok(router) + } +} + +// https://github.com/tokio-rs/axum/blob/main/examples/consume-body-in-extractor-or-middleware/src/main.rs +async fn log_req_res_bodies(request: Request, next: Next) -> Result { + // Log the request body + let (parts, body) = request.into_parts(); + let bytes = log_body(body, "request").await?; + let request = Request::from_parts(parts, Body::from(bytes)); + + // Handle the request + let response = next.run(request).await; + + // Log the response body + let (parts, body) = response.into_parts(); + let bytes = log_body(body, "response").await?; + let response = Response::from_parts(parts, Body::from(bytes)); + + // Return the response + Ok(response) +} + +async fn log_body(body: Body, msg: &str) -> Result { + // This only works if the body is not a long-running stream + let bytes = body + .collect() + .await + .map_err(|err| (StatusCode::INTERNAL_SERVER_ERROR, err.to_string()).into_response())? + .to_bytes(); + + debug!(body = ?bytes, msg); + + Ok(bytes) +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::config::app_config::AppConfig; + use rstest::rstest; + + #[rstest] + #[case(false, Some(true), true)] + #[case(false, Some(false), false)] + #[cfg_attr(coverage_nightly, coverage(off))] + fn enabled( + #[case] default_enable: bool, + #[case] enable: Option, + #[case] expected_enabled: bool, + ) { + // Arrange + let mut config = AppConfig::test(None).unwrap(); + config.service.http.custom.middleware.default_enable = default_enable; + config + .service + .http + .custom + .middleware + .request_response_logging + .common + .enable = enable; + + let context = AppContext::test(Some(config), None, None).unwrap(); + + let middleware = RequestLoggingMiddleware; + + // Act/Assert + assert_eq!(middleware.enabled(&context), expected_enabled); + } + + #[rstest] + #[case(None, 0)] + #[case(Some(1234), 1234)] + #[cfg_attr(coverage_nightly, coverage(off))] + fn priority(#[case] override_priority: Option, #[case] expected_priority: i32) { + // Arrange + let mut config = AppConfig::test(None).unwrap(); + if let Some(priority) = override_priority { + config + .service + .http + .custom + .middleware + .request_response_logging + .common + .priority = priority; + } + + let context = AppContext::test(Some(config), None, None).unwrap(); + + let middleware = RequestLoggingMiddleware; + + // Act/Assert + assert_eq!(middleware.priority(&context), expected_priority); + } +}