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

@@ -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 }

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

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

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<CorsConfig>,
 
+    pub request_response_logging: MiddlewareConfig<ReqResLoggingConfig>,
+
     /// Allows providing configs for custom middleware. Any configs that aren't pre-defined above
     /// will be collected here.
     ///

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
 

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()

src/service/http/middleware/tracing.rs → 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;

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<S> Middleware<S> for RequestLoggingMiddleware
+where
+    S: Clone + Send + Sync + 'static,
+    AppContext: FromRef<S>,
+{
+    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<Router> {
+        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<impl IntoResponse, Response> {
+    // 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<Bytes, Response> {
+    // 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<bool>,
+        #[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<i32>, #[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);
+    }
+}