From 6b106f4babfa0417952134040cc0618f2fd60c7c Mon Sep 17 00:00:00 2001 From: David Pedersen Date: Tue, 11 Apr 2023 16:57:49 +0200 Subject: [PATCH] Log built-in rejections (#1890) --- axum-core/Cargo.toml | 6 +- axum-core/src/extract/rejection.rs | 3 + axum-core/src/macros.rs | 106 ++++++++++++-- axum-extra/src/extract/multipart.rs | 5 + axum/CHANGELOG.md | 3 + axum/Cargo.toml | 3 + axum/src/docs/extract.md | 8 ++ axum/src/extract/multipart.rs | 7 + axum/src/extract/path/mod.rs | 5 + axum/src/extract/rejection.rs | 3 + axum/src/extract/ws.rs | 3 + axum/src/lib.rs | 1 + axum/src/macros.rs | 174 ----------------------- axum/src/routing/tests/mod.rs | 75 +++++++++- axum/src/test_helpers/mod.rs | 2 + axum/src/test_helpers/tracing_helpers.rs | 108 ++++++++++++++ examples/tracing-aka-logging/Cargo.toml | 2 +- examples/tracing-aka-logging/src/main.rs | 7 +- 18 files changed, 329 insertions(+), 192 deletions(-) create mode 100644 axum/src/test_helpers/tracing_helpers.rs diff --git a/axum-core/Cargo.toml b/axum-core/Cargo.toml index cafa46d1..ef263564 100644 --- a/axum-core/Cargo.toml +++ b/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" diff --git a/axum-core/src/extract/rejection.rs b/axum-core/src/extract/rejection.rs index 09d70191..958f3b21 100644 --- a/axum-core/src/extract/rejection.rs +++ b/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! { diff --git a/axum-core/src/macros.rs b/axum-core/src/macros.rs index 58a74625..10365e15 100644 --- a/axum-core/src/macros.rs +++ b/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(err: E) -> Self where - E: Into, + 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 { diff --git a/axum-extra/src/extract/multipart.rs b/axum-extra/src/extract/multipart.rs index 03f7fc54..83c4934f 100644 --- a/axum-extra/src/extract/multipart.rs +++ b/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() } diff --git a/axum/CHANGELOG.md b/axum/CHANGELOG.md index 0f661904..2da21583 100644 --- a/axum/CHANGELOG.md +++ b/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) diff --git a/axum/Cargo.toml b/axum/Cargo.toml index 616f7e3b..4f3bf4fd 100644 --- a/axum/Cargo.toml +++ b/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] diff --git a/axum/src/docs/extract.md b/axum/src/docs/extract.md index 7e9b59f1..ed350e5b 100644 --- a/axum/src/docs/extract.md +++ b/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 diff --git a/axum/src/extract/multipart.rs b/axum/src/extract/multipart.rs index 3923600a..b7f2c103 100644 --- a/axum/src/extract/multipart.rs +++ b/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() } } diff --git a/axum/src/extract/path/mod.rs b/axum/src/extract/path/mod.rs index 65f5c092..0932d9ce 100644 --- a/axum/src/extract/path/mod.rs +++ b/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() } } diff --git a/axum/src/extract/rejection.rs b/axum/src/extract/rejection.rs index 7285d49e..caaab06d 100644 --- a/axum/src/extract/rejection.rs +++ b/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::*; diff --git a/axum/src/extract/ws.rs b/axum/src/extract/ws.rs index 482e6916..d785a800 100644 --- a/axum/src/extract/ws.rs +++ b/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`"] diff --git a/axum/src/lib.rs b/axum/src/lib.rs index f40dc71a..b10a8d6b 100644 --- a/axum/src/lib.rs +++ b/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 diff --git a/axum/src/macros.rs b/axum/src/macros.rs index abff1dd7..180c3c05 100644 --- a/axum/src/macros.rs +++ b/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(err: E) -> Self - where - E: Into, - { - 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) => { diff --git a/axum/src/routing/tests/mod.rs b/axum/src/routing/tests/mod.rs index b69dbc8f..950d601a 100644 --- a/axum/src/routing/tests/mod.rs +++ b/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::(|| async { + let app = Router::new() + .route("/extension", get(|_: Extension| 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(), + }, + ]) + ) +} diff --git a/axum/src/test_helpers/mod.rs b/axum/src/test_helpers/mod.rs index 0b60ee90..de455490 100644 --- a/axum/src/test_helpers/mod.rs +++ b/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() {} pub(crate) fn assert_sync() {} pub(crate) fn assert_unpin() {} diff --git a/axum/src/test_helpers/tracing_helpers.rs b/axum/src/test_helpers/tracing_helpers.rs new file mode 100644 index 00000000..3d5cf181 --- /dev/null +++ b/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 { + 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(f: F) -> Vec> +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::().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>>>, +} + +impl TestMakeWriter { + fn new() -> (Self, Handle) { + let write = Arc::new(Mutex::new(Some(Vec::::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 { + 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>>>, +} + +impl Handle { + fn take(self) -> String { + let vec = self.write.lock().unwrap().take().unwrap(); + String::from_utf8(vec).unwrap() + } +} diff --git a/examples/tracing-aka-logging/Cargo.toml b/examples/tracing-aka-logging/Cargo.toml index 5f161d39..db5e2517 100644 --- a/examples/tracing-aka-logging/Cargo.toml +++ b/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" diff --git a/examples/tracing-aka-logging/src/main.rs b/examples/tracing-aka-logging/src/main.rs index 58ece2b5..6b4524ac 100644 --- a/examples/tracing-aka-logging/src/main.rs +++ b/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();