Log built-in rejections (#1890)

axum-core/Cargo.toml

@@ -9,9 +9,12 @@ license = "MIT"
 name = "axum-core"
 readme = "README.md"
 repository = "https://github.com/tokio-rs/axum"
-version = "0.3.3" # remember to also bump the version that axum and axum-extra depends on
+version = "0.3.3" # remember to also bump the version that axum and axum-extra depend on
 
 [features]
+tracing = ["dep:tracing"]
+
+# Required for intra-doc links to resolve correctly
 __private_docs = ["dep:tower-http"]
 
 [dependencies]
@@ -26,6 +29,7 @@ tower-service = "0.3"
 
 # optional dependencies
 tower-http = { version = "0.4", optional = true, features = ["limit"] }
+tracing = { version = "0.1.37", default-features = false, optional = true }
 
 [build-dependencies]
 rustversion = "1.0.9"

axum-core/src/extract/rejection.rs

@@ -1,5 +1,8 @@
 //! Rejection response types.
 
+use crate::__composite_rejection as composite_rejection;
+use crate::__define_rejection as define_rejection;
+
 use crate::BoxError;
 
 composite_rejection! {

axum-core/src/macros.rs

@@ -1,4 +1,79 @@
-macro_rules! define_rejection {
+/// Private API.
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __log_rejection {
+    (
+        rejection_type = $ty:ident,
+        body_text = $body_text:expr,
+        status = $status:expr,
+    ) => {
+        #[cfg(feature = "tracing")]
+        {
+            tracing::event!(
+                target: "axum::rejection",
+                tracing::Level::TRACE,
+                status = $status.as_u16(),
+                body = $body_text,
+                rejection_type = std::any::type_name::<$ty>(),
+                "rejecting request",
+            );
+        }
+    };
+}
+
+/// Private API.
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __define_rejection {
+    (
+        #[status = $status:ident]
+        #[body = $body:expr]
+        $(#[$m:meta])*
+        pub struct $name:ident;
+    ) => {
+        $(#[$m])*
+        #[derive(Debug)]
+        #[non_exhaustive]
+        pub struct $name;
+
+        impl $crate::response::IntoResponse for $name {
+            fn into_response(self) -> $crate::response::Response {
+                $crate::__log_rejection!(
+                    rejection_type = $name,
+                    body_text = $body,
+                    status = http::StatusCode::$status,
+                );
+                (self.status(), $body).into_response()
+            }
+        }
+
+        impl $name {
+            /// Get the response body text used for this rejection.
+            pub fn body_text(&self) -> String {
+                $body.into()
+            }
+
+            /// Get the status code used for this rejection.
+            pub fn status(&self) -> http::StatusCode {
+                http::StatusCode::$status
+            }
+        }
+
+        impl std::fmt::Display for $name {
+            fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+                write!(f, "{}", $body)
+            }
+        }
+
+        impl std::error::Error for $name {}
+
+        impl Default for $name {
+            fn default() -> Self {
+                Self
+            }
+        }
+    };
+
     (
         #[status = $status:ident]
         #[body = $body:expr]
@@ -7,15 +82,25 @@ macro_rules! define_rejection {
     ) => {
         $(#[$m])*
         #[derive(Debug)]
-        pub struct $name(pub(crate) crate::Error);
+        pub struct $name(pub(crate) $crate::Error);
 
         impl $name {
-            #[allow(dead_code)]
             pub(crate) fn from_err<E>(err: E) -> Self
             where
-                E: Into<crate::BoxError>,
+                E: Into<$crate::BoxError>,
             {
-                Self(crate::Error::new(err))
+                Self($crate::Error::new(err))
+            }
+        }
+
+        impl $crate::response::IntoResponse for $name {
+            fn into_response(self) -> $crate::response::Response {
+                $crate::__log_rejection!(
+                    rejection_type = $name,
+                    body_text = self.body_text(),
+                    status = http::StatusCode::$status,
+                );
+                (self.status(), self.body_text()).into_response()
             }
         }
 
@@ -31,12 +116,6 @@ macro_rules! define_rejection {
             }
         }
 
-        impl crate::response::IntoResponse for $name {
-            fn into_response(self) -> $crate::response::Response {
-                (self.status(), self.body_text()).into_response()
-            }
-        }
-
         impl std::fmt::Display for $name {
             fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
                 write!(f, "{}", $body)
@@ -51,7 +130,10 @@ macro_rules! define_rejection {
     };
 }
 
-macro_rules! composite_rejection {
+/// Private API.
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __composite_rejection {
     (
         $(#[$m:meta])*
         pub enum $name:ident {

axum-extra/src/extract/multipart.rs

@@ -250,6 +250,11 @@ impl MultipartError {
 
     /// Get the response body text used for this rejection.
     pub fn body_text(&self) -> String {
+        axum_core::__log_rejection!(
+            rejection_type = Self,
+            body_text = self.body_text(),
+            status = self.status(),
+        );
         self.source.to_string()
     }
 

axum/CHANGELOG.md

@@ -7,6 +7,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 # Unreleased
 
+- **added:** Log rejections from built-in extractors with the
+  `axum::rejection=trace` target ([#1890])
 - **fixed:** Fixed performance regression with `Router::nest` introduced in
   0.6.0. `nest` now flattens the routes which performs better ([#1711])
 - **fixed:** Extracting `MatchedPath` in nested handlers now gives the full
@@ -14,6 +16,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - **added:** Implement `Deref` and `DerefMut` for built-in extractors ([#1922])
 
 [#1711]: https://github.com/tokio-rs/axum/pull/1711
+[#1890]: https://github.com/tokio-rs/axum/pull/1890
 [#1922]: https://github.com/tokio-rs/axum/pull/1922
 
 # 0.6.12 (22. March, 2023)

axum/Cargo.toml

@@ -24,6 +24,7 @@ original-uri = []
 query = ["dep:serde_urlencoded"]
 tokio = ["dep:tokio", "hyper/server", "hyper/tcp", "hyper/runtime", "tower/make"]
 tower-log = ["tower/log"]
+tracing = ["dep:tracing", "axum-core/tracing"]
 ws = ["tokio", "dep:tokio-tungstenite", "dep:sha1", "dep:base64"]
 
 # Required for intra-doc links to resolve correctly
@@ -61,6 +62,7 @@ serde_urlencoded = { version = "0.7", optional = true }
 sha1 = { version = "0.10", optional = true }
 tokio = { package = "tokio", version = "1.25.0", features = ["time"], optional = true }
 tokio-tungstenite = { version = "0.18.0", optional = true }
+tracing = { version = "0.1", default-features = false, optional = true }
 
 [dependencies.tower-http]
 version = "0.4"
@@ -113,6 +115,7 @@ time = { version = "0.3", features = ["serde-human-readable"] }
 tokio = { package = "tokio", version = "1.25.0", features = ["macros", "rt", "rt-multi-thread", "net", "test-util"] }
 tokio-stream = "0.1"
 tracing = "0.1"
+tracing-subscriber = { version = "0.3", features = ["json"] }
 uuid = { version = "1.0", features = ["serde", "v4"] }
 
 [package.metadata.docs.rs]

axum/src/docs/extract.md

@@ -15,6 +15,7 @@ Types and traits for extracting data from requests.
 - [Request body extractors](#request-body-extractors)
 - [Running extractors from middleware](#running-extractors-from-middleware)
 - [Wrapping extractors](#wrapping-extractors)
+- [Logging rejections](#logging-rejections)
 
 # Intro
 
@@ -833,6 +834,13 @@ async fn handler(
 # let _: axum::routing::MethodRouter = axum::routing::get(handler);
 ```
 
+# Logging rejections
+
+All built-in extractors will log rejections for easier debugging. To see the
+logs, enable the `tracing` feature for axum and the `axum::rejection=trace`
+tracing target, for example with `RUST_LOG=info,axum::rejection=trace cargo
+run`.
+
 [`body::Body`]: crate::body::Body
 [`Bytes`]: crate::body::Bytes
 [customize-extractor-error]: https://github.com/tokio-rs/axum/blob/main/examples/customize-extractor-error/src/main.rs

axum/src/extract/multipart.rs

@@ -6,6 +6,8 @@ use super::{BodyStream, FromRequest};
 use crate::body::{Bytes, HttpBody};
 use crate::BoxError;
 use async_trait::async_trait;
+use axum_core::__composite_rejection as composite_rejection;
+use axum_core::__define_rejection as define_rejection;
 use axum_core::response::{IntoResponse, Response};
 use axum_core::RequestExt;
 use futures_util::stream::Stream;
@@ -272,6 +274,11 @@ impl std::error::Error for MultipartError {
 
 impl IntoResponse for MultipartError {
     fn into_response(self) -> Response {
+        axum_core::__log_rejection!(
+            rejection_type = Self,
+            body_text = self.body_text(),
+            status = self.status(),
+        );
         (self.status(), self.body_text()).into_response()
     }
 }

axum/src/extract/path/mod.rs

@@ -404,6 +404,11 @@ impl FailedToDeserializePathParams {
 
 impl IntoResponse for FailedToDeserializePathParams {
     fn into_response(self) -> Response {
+        axum_core::__log_rejection!(
+            rejection_type = Self,
+            body_text = self.body_text(),
+            status = self.status(),
+        );
         (self.status(), self.body_text()).into_response()
     }
 }

axum/src/extract/rejection.rs

@@ -1,5 +1,8 @@
 //! Rejection response types.
 
+use axum_core::__composite_rejection as composite_rejection;
+use axum_core::__define_rejection as define_rejection;
+
 pub use crate::extract::path::{FailedToDeserializePathParams, InvalidUtf8InPathParam};
 pub use axum_core::extract::rejection::*;
 

axum/src/extract/ws.rs

@@ -681,6 +681,9 @@ fn sign(key: &[u8]) -> HeaderValue {
 pub mod rejection {
     //! WebSocket specific rejections.
 
+    use axum_core::__composite_rejection as composite_rejection;
+    use axum_core::__define_rejection as define_rejection;
+
     define_rejection! {
         #[status = METHOD_NOT_ALLOWED]
         #[body = "Request method must be `GET`"]

axum/src/lib.rs

@@ -358,6 +358,7 @@
 //! `original-uri` | Enables capturing of every request's original URI and the [`OriginalUri`] extractor | Yes
 //! `tokio` | Enables `tokio` as a dependency and `axum::Server`, `SSE` and `extract::connect_info` types. | Yes
 //! `tower-log` | Enables `tower`'s `log` feature | Yes
+//! `tracing` | Log rejections from built-in extractors | No
 //! `ws` | Enables WebSockets support via [`extract::ws`] | No
 //! `form` | Enables the `Form` extractor | Yes
 //! `query` | Enables the `Query` extractor | Yes

axum/src/macros.rs

@@ -45,180 +45,6 @@ macro_rules! opaque_future {
     };
 }
 
-macro_rules! define_rejection {
-    (
-        #[status = $status:ident]
-        #[body = $body:expr]
-        $(#[$m:meta])*
-        pub struct $name:ident;
-    ) => {
-        $(#[$m])*
-        #[derive(Debug)]
-        #[non_exhaustive]
-        pub struct $name;
-
-        impl $crate::response::IntoResponse for $name {
-            fn into_response(self) -> $crate::response::Response {
-                (self.status(), $body).into_response()
-            }
-        }
-
-        impl $name {
-            /// Get the response body text used for this rejection.
-            pub fn body_text(&self) -> String {
-                $body.into()
-            }
-
-            /// Get the status code used for this rejection.
-            pub fn status(&self) -> http::StatusCode {
-                http::StatusCode::$status
-            }
-        }
-
-        impl std::fmt::Display for $name {
-            fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
-                write!(f, "{}", $body)
-            }
-        }
-
-        impl std::error::Error for $name {}
-
-        impl Default for $name {
-            fn default() -> Self {
-                Self
-            }
-        }
-    };
-
-    (
-        #[status = $status:ident]
-        #[body = $body:expr]
-        $(#[$m:meta])*
-        pub struct $name:ident (Error);
-    ) => {
-        $(#[$m])*
-        #[derive(Debug)]
-        pub struct $name(pub(crate) crate::Error);
-
-        impl $name {
-            pub(crate) fn from_err<E>(err: E) -> Self
-            where
-                E: Into<crate::BoxError>,
-            {
-                Self(crate::Error::new(err))
-            }
-        }
-
-        impl crate::response::IntoResponse for $name {
-            fn into_response(self) -> $crate::response::Response {
-                (self.status(), self.body_text()).into_response()
-            }
-        }
-
-        impl $name {
-            /// Get the response body text used for this rejection.
-            pub fn body_text(&self) -> String {
-                format!(concat!($body, ": {}"), self.0).into()
-            }
-
-            /// Get the status code used for this rejection.
-            pub fn status(&self) -> http::StatusCode {
-                http::StatusCode::$status
-            }
-        }
-
-        impl std::fmt::Display for $name {
-            fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
-                write!(f, "{}", $body)
-            }
-        }
-
-        impl std::error::Error for $name {
-            fn source(&self) -> Option<&(dyn std::error::Error + 'static)> {
-                Some(&self.0)
-            }
-        }
-    };
-}
-
-macro_rules! composite_rejection {
-    (
-        $(#[$m:meta])*
-        pub enum $name:ident {
-            $($variant:ident),+
-            $(,)?
-        }
-    ) => {
-        $(#[$m])*
-        #[derive(Debug)]
-        #[non_exhaustive]
-        pub enum $name {
-            $(
-                #[allow(missing_docs)]
-                $variant($variant)
-            ),+
-        }
-
-        impl $crate::response::IntoResponse for $name {
-            fn into_response(self) -> $crate::response::Response {
-                match self {
-                    $(
-                        Self::$variant(inner) => inner.into_response(),
-                    )+
-                }
-            }
-        }
-
-        impl $name {
-            /// Get the response body text used for this rejection.
-            pub fn body_text(&self) -> String {
-                match self {
-                    $(
-                        Self::$variant(inner) => inner.body_text(),
-                    )+
-                }
-            }
-
-            /// Get the status code used for this rejection.
-            pub fn status(&self) -> http::StatusCode {
-                match self {
-                    $(
-                        Self::$variant(inner) => inner.status(),
-                    )+
-                }
-            }
-        }
-
-        $(
-            impl From<$variant> for $name {
-                fn from(inner: $variant) -> Self {
-                    Self::$variant(inner)
-                }
-            }
-        )+
-
-        impl std::fmt::Display for $name {
-            fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
-                match self {
-                    $(
-                        Self::$variant(inner) => write!(f, "{}", inner),
-                    )+
-                }
-            }
-        }
-
-        impl std::error::Error for $name {
-            fn source(&self) -> Option<&(dyn std::error::Error + 'static)> {
-                match self {
-                    $(
-                        Self::$variant(inner) => Some(inner),
-                    )+
-                }
-            }
-        }
-    };
-}
-
 #[rustfmt::skip]
 macro_rules! all_the_tuples {
     ($name:ident) => {

axum/src/routing/tests/mod.rs

@@ -8,12 +8,16 @@ use crate::{
         delete, get, get_service, on, on_service, patch, patch_service,
         path_router::path_for_nested_route, post, MethodFilter,
     },
-    test_helpers::*,
-    BoxError, Json, Router,
+    test_helpers::{
+        tracing_helpers::{capture_tracing, TracingEvent},
+        *,
+    },
+    BoxError, Extension, Json, Router,
 };
 use futures_util::stream::StreamExt;
 use http::{header::ALLOW, header::CONTENT_LENGTH, HeaderMap, Request, Response, StatusCode, Uri};
 use hyper::Body;
+use serde::Deserialize;
 use serde_json::json;
 use std::{
     convert::Infallible,
@@ -913,3 +917,70 @@ async fn state_isnt_cloned_too_much() {
 
     assert_eq!(COUNT.load(Ordering::SeqCst), 4);
 }
+
+#[crate::test]
+async fn logging_rejections() {
+    #[derive(Deserialize, Eq, PartialEq, Debug)]
+    #[serde(deny_unknown_fields)]
+    struct RejectionEvent {
+        message: String,
+        status: u16,
+        body: String,
+        rejection_type: String,
+    }
+
+    let events = capture_tracing::<RejectionEvent, _, _>(|| async {
+        let app = Router::new()
+            .route("/extension", get(|_: Extension<Infallible>| async {}))
+            .route("/string", post(|_: String| async {}));
+
+        let client = TestClient::new(app);
+
+        assert_eq!(
+            client.get("/extension").send().await.status(),
+            StatusCode::INTERNAL_SERVER_ERROR
+        );
+
+        assert_eq!(
+            client
+                .post("/string")
+                .body(Vec::from([0, 159, 146, 150]))
+                .send()
+                .await
+                .status(),
+            StatusCode::BAD_REQUEST,
+        );
+    })
+    .await;
+
+    assert_eq!(
+        dbg!(events),
+        Vec::from([
+            TracingEvent {
+                fields: RejectionEvent {
+                    message: "rejecting request".to_owned(),
+                    status: 500,
+                    body: "Missing request extension: Extension of \
+                        type `core::convert::Infallible` was not found. \
+                        Perhaps you forgot to add it? See `axum::Extension`."
+                        .to_owned(),
+                    rejection_type: "axum::extract::rejection::MissingExtension".to_owned(),
+                },
+                target: "axum::rejection".to_owned(),
+                level: "TRACE".to_owned(),
+            },
+            TracingEvent {
+                fields: RejectionEvent {
+                    message: "rejecting request".to_owned(),
+                    status: 400,
+                    body: "Request body didn't contain valid UTF-8: \
+                        invalid utf-8 sequence of 1 bytes from index 1"
+                        .to_owned(),
+                    rejection_type: "axum_core::extract::rejection::InvalidUtf8".to_owned(),
+                },
+                target: "axum::rejection".to_owned(),
+                level: "TRACE".to_owned(),
+            },
+        ])
+    )
+}

axum/src/test_helpers/mod.rs

@@ -5,6 +5,8 @@ use crate::{body::HttpBody, BoxError};
 mod test_client;
 pub(crate) use self::test_client::*;
 
+pub(crate) mod tracing_helpers;
+
 pub(crate) fn assert_send<T: Send>() {}
 pub(crate) fn assert_sync<T: Sync>() {}
 pub(crate) fn assert_unpin<T: Unpin>() {}

axum/src/test_helpers/tracing_helpers.rs

@@ -0,0 +1,108 @@
+use std::{
+    future::Future,
+    io,
+    sync::{Arc, Mutex},
+};
+
+use serde::{de::DeserializeOwned, Deserialize};
+use tracing_subscriber::prelude::*;
+use tracing_subscriber::{filter::Targets, fmt::MakeWriter};
+
+#[derive(Deserialize, Eq, PartialEq, Debug)]
+#[serde(deny_unknown_fields)]
+pub(crate) struct TracingEvent<T> {
+    pub(crate) fields: T,
+    pub(crate) target: String,
+    pub(crate) level: String,
+}
+
+/// Run an async closure and capture the tracing output it produces.
+pub(crate) async fn capture_tracing<T, F, Fut>(f: F) -> Vec<TracingEvent<T>>
+where
+    F: Fn() -> Fut,
+    Fut: Future,
+    T: DeserializeOwned,
+{
+    let (make_writer, handle) = TestMakeWriter::new();
+
+    let subscriber = tracing_subscriber::registry().with(
+        tracing_subscriber::fmt::layer()
+            .with_writer(make_writer)
+            .with_target(true)
+            .without_time()
+            .with_ansi(false)
+            .json()
+            .flatten_event(false)
+            .with_filter("axum=trace".parse::<Targets>().unwrap()),
+    );
+
+    let guard = tracing::subscriber::set_default(subscriber);
+
+    f().await;
+
+    drop(guard);
+
+    handle
+        .take()
+        .lines()
+        .map(|line| serde_json::from_str(line).unwrap())
+        .collect()
+}
+
+struct TestMakeWriter {
+    write: Arc<Mutex<Option<Vec<u8>>>>,
+}
+
+impl TestMakeWriter {
+    fn new() -> (Self, Handle) {
+        let write = Arc::new(Mutex::new(Some(Vec::<u8>::new())));
+
+        (
+            Self {
+                write: write.clone(),
+            },
+            Handle { write },
+        )
+    }
+}
+
+impl<'a> MakeWriter<'a> for TestMakeWriter {
+    type Writer = Writer<'a>;
+
+    fn make_writer(&'a self) -> Self::Writer {
+        Writer(self)
+    }
+}
+
+struct Writer<'a>(&'a TestMakeWriter);
+
+impl<'a> io::Write for Writer<'a> {
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        match &mut *self.0.write.lock().unwrap() {
+            Some(vec) => {
+                let len = buf.len();
+                vec.extend(buf);
+                Ok(len)
+            }
+            None => Err(io::Error::new(
+                io::ErrorKind::Other,
+                "inner writer has been taken",
+            )),
+        }
+    }
+
+    fn flush(&mut self) -> io::Result<()> {
+        Ok(())
+    }
+}
+
+struct Handle {
+    write: Arc<Mutex<Option<Vec<u8>>>>,
+}
+
+impl Handle {
+    fn take(self) -> String {
+        let vec = self.write.lock().unwrap().take().unwrap();
+        String::from_utf8(vec).unwrap()
+    }
+}

examples/tracing-aka-logging/Cargo.toml

@@ -5,7 +5,7 @@ edition = "2021"
 publish = false
 
 [dependencies]
-axum = { path = "../../axum" }
+axum = { path = "../../axum", features = ["tracing"] }
 tokio = { version = "1.0", features = ["full"] }
 tower-http = { version = "0.4.0", features = ["trace"] }
 tracing = "0.1"

examples/tracing-aka-logging/src/main.rs

@@ -21,8 +21,11 @@ use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
 async fn main() {
     tracing_subscriber::registry()
         .with(
-            tracing_subscriber::EnvFilter::try_from_default_env()
-                .unwrap_or_else(|_| "example_tracing_aka_logging=debug,tower_http=debug".into()),
+            tracing_subscriber::EnvFilter::try_from_default_env().unwrap_or_else(|_| {
+                // axum logs rejections from built-in extractors with the `axum::rejection`
+                // target, at `TRACE` level. `axum::rejection=trace` enables showing those events
+                "example_tracing_aka_logging=debug,tower_http=debug,axum::rejection=trace".into()
+            }),
         )
         .with(tracing_subscriber::fmt::layer())
         .init();