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,13 +7,16 @@ 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
   matched path, including the nested path ([#1711])
 - **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