From 1e2fde244a86755d7afae1e4e89fe7760fc6b974 Mon Sep 17 00:00:00 2001 From: Jonas Platte Date: Sat, 24 Jun 2023 21:29:06 +0200 Subject: [PATCH] trace: Simplify dynamic tracing level application --- tower-http/src/trace/make_span.rs | 20 +--- tower-http/src/trace/mod.rs | 66 +++++++++++ tower-http/src/trace/on_eos.rs | 93 +-------------- tower-http/src/trace/on_failure.rs | 64 ++--------- tower-http/src/trace/on_request.rs | 18 +-- tower-http/src/trace/on_response.rs | 170 +++------------------------- 6 files changed, 103 insertions(+), 328 deletions(-) diff --git a/tower-http/src/trace/make_span.rs b/tower-http/src/trace/make_span.rs index 904d941f..bf558d3b 100644 --- a/tower-http/src/trace/make_span.rs +++ b/tower-http/src/trace/make_span.rs @@ -103,21 +103,11 @@ impl MakeSpan for DefaultMakeSpan { } match self.level { - Level::ERROR => { - make_span!(Level::ERROR) - } - Level::WARN => { - make_span!(Level::WARN) - } - Level::INFO => { - make_span!(Level::INFO) - } - Level::DEBUG => { - make_span!(Level::DEBUG) - } - Level::TRACE => { - make_span!(Level::TRACE) - } + Level::ERROR => make_span!(Level::ERROR), + Level::WARN => make_span!(Level::WARN), + Level::INFO => make_span!(Level::INFO), + Level::DEBUG => make_span!(Level::DEBUG), + Level::TRACE => make_span!(Level::TRACE), } } } diff --git a/tower-http/src/trace/mod.rs b/tower-http/src/trace/mod.rs index cc635ee1..e08da3e3 100644 --- a/tower-http/src/trace/mod.rs +++ b/tower-http/src/trace/mod.rs @@ -383,6 +383,8 @@ //! [`Body::poll_trailers`]: http_body::Body::poll_trailers //! [`Body::poll_data`]: http_body::Body::poll_data +use std::{fmt, time::Duration}; + use tracing::Level; pub use self::{ @@ -397,6 +399,54 @@ pub use self::{ on_response::{DefaultOnResponse, OnResponse}, service::Trace, }; +use crate::LatencyUnit; + +macro_rules! event_dynamic_lvl { + ( $(target: $target:expr,)? $(parent: $parent:expr,)? $lvl:expr, $($tt:tt)* ) => { + match $lvl { + tracing::Level::ERROR => { + tracing::event!( + $(target: $target,)? + $(parent: $parent,)? + tracing::Level::ERROR, + $($tt)* + ); + } + tracing::Level::WARN => { + tracing::event!( + $(target: $target,)? + $(parent: $parent,)? + tracing::Level::WARN, + $($tt)* + ); + } + tracing::Level::INFO => { + tracing::event!( + $(target: $target,)? + $(parent: $parent,)? + tracing::Level::INFO, + $($tt)* + ); + } + tracing::Level::DEBUG => { + tracing::event!( + $(target: $target,)? + $(parent: $parent,)? + tracing::Level::DEBUG, + $($tt)* + ); + } + tracing::Level::TRACE => { + tracing::event!( + $(target: $target,)? + $(parent: $parent,)? + tracing::Level::TRACE, + $($tt)* + ); + } + } + }; +} mod body; mod future; @@ -412,6 +462,22 @@ mod service; const DEFAULT_MESSAGE_LEVEL: Level = Level::DEBUG; const DEFAULT_ERROR_LEVEL: Level = Level::ERROR; +struct Latency { + unit: LatencyUnit, + duration: Duration, +} + +impl fmt::Display for Latency { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self.unit { + LatencyUnit::Seconds => write!(f, "{} s", self.duration.as_secs_f64()), + LatencyUnit::Millis => write!(f, "{} ms", self.duration.as_millis()), + LatencyUnit::Micros => write!(f, "{} μs", self.duration.as_micros()), + LatencyUnit::Nanos => write!(f, "{} ns", self.duration.as_nanos()), + } + } +} + #[cfg(test)] mod tests { use super::*; diff --git a/tower-http/src/trace/on_eos.rs b/tower-http/src/trace/on_eos.rs index bebe6db1..ab90fc9c 100644 --- a/tower-http/src/trace/on_eos.rs +++ b/tower-http/src/trace/on_eos.rs @@ -1,4 +1,4 @@ -use super::DEFAULT_MESSAGE_LEVEL; +use super::{Latency, DEFAULT_MESSAGE_LEVEL}; use crate::{classify::grpc_errors_as_failures::ParsedGrpcStatus, LatencyUnit}; use http::header::HeaderMap; use std::time::Duration; @@ -83,88 +83,12 @@ impl DefaultOnEos { } } -// Repeating this pattern match for each case is tedious. So we do it with a quick and -// dirty macro. -// -// Tracing requires all these parts to be declared statically. You cannot easily build -// events dynamically. -#[allow(unused_macros)] -macro_rules! log_pattern_match { - ( - $this:expr, $stream_duration:expr, $status:expr, [$($level:ident),*] - ) => { - match ($this.level, $this.latency_unit, $status) { - $( - (Level::$level, LatencyUnit::Seconds, None) => { - tracing::event!( - Level::$level, - stream_duration = format_args!("{} s", $stream_duration.as_secs_f64()), - "end of stream" - ); - } - (Level::$level, LatencyUnit::Seconds, Some(status)) => { - tracing::event!( - Level::$level, - stream_duration = format_args!("{} s", $stream_duration.as_secs_f64()), - status = status, - "end of stream" - ); - } - - (Level::$level, LatencyUnit::Millis, None) => { - tracing::event!( - Level::$level, - stream_duration = format_args!("{} ms", $stream_duration.as_millis()), - "end of stream" - ); - } - (Level::$level, LatencyUnit::Millis, Some(status)) => { - tracing::event!( - Level::$level, - stream_duration = format_args!("{} ms", $stream_duration.as_millis()), - status = status, - "end of stream" - ); - } - - (Level::$level, LatencyUnit::Micros, None) => { - tracing::event!( - Level::$level, - stream_duration = format_args!("{} μs", $stream_duration.as_micros()), - "end of stream" - ); - } - (Level::$level, LatencyUnit::Micros, Some(status)) => { - tracing::event!( - Level::$level, - stream_duration = format_args!("{} μs", $stream_duration.as_micros()), - status = status, - "end of stream" - ); - } - - (Level::$level, LatencyUnit::Nanos, None) => { - tracing::event!( - Level::$level, - stream_duration = format_args!("{} ns", $stream_duration.as_nanos()), - "end of stream" - ); - } - (Level::$level, LatencyUnit::Nanos, Some(status)) => { - tracing::event!( - Level::$level, - stream_duration = format_args!("{} ns", $stream_duration.as_nanos()), - status = status, - "end of stream" - ); - } - )* - } - }; -} - impl OnEos for DefaultOnEos { fn on_eos(self, trailers: Option<&HeaderMap>, stream_duration: Duration, _span: &Span) { + let stream_duration = Latency { + unit: self.latency_unit, + duration: stream_duration, + }; let status = trailers.and_then(|trailers| { match crate::classify::grpc_errors_as_failures::classify_grpc_metadata( trailers, @@ -178,11 +102,6 @@ impl OnEos for DefaultOnEos { } }); - log_pattern_match!( - self, - stream_duration, - status, - [ERROR, WARN, INFO, DEBUG, TRACE] - ); + event_dynamic_lvl!(self.level, %stream_duration, status, "end of stream"); } } diff --git a/tower-http/src/trace/on_failure.rs b/tower-http/src/trace/on_failure.rs index 42fb1006..7dfa186d 100644 --- a/tower-http/src/trace/on_failure.rs +++ b/tower-http/src/trace/on_failure.rs @@ -1,4 +1,4 @@ -use super::DEFAULT_ERROR_LEVEL; +use super::{Latency, DEFAULT_ERROR_LEVEL}; use crate::LatencyUnit; use std::{fmt, time::Duration}; use tracing::{Level, Span}; @@ -81,64 +81,20 @@ impl DefaultOnFailure { } } -// Repeating this pattern match for each case is tedious. So we do it with a quick and -// dirty macro. -// -// Tracing requires all these parts to be declared statically. You cannot easily build -// events dynamically. -macro_rules! log_pattern_match { - ( - $this:expr, $failure_classification:expr, $latency:expr, [$($level:ident),*] - ) => { - match ($this.level, $this.latency_unit) { - $( - (Level::$level, LatencyUnit::Seconds) => { - tracing::event!( - Level::$level, - classification = tracing::field::display($failure_classification), - latency = format_args!("{} s", $latency.as_secs_f64()), - "response failed" - ); - } - (Level::$level, LatencyUnit::Millis) => { - tracing::event!( - Level::$level, - classification = tracing::field::display($failure_classification), - latency = format_args!("{} ms", $latency.as_millis()), - "response failed" - ); - } - (Level::$level, LatencyUnit::Micros) => { - tracing::event!( - Level::$level, - classification = tracing::field::display($failure_classification), - latency = format_args!("{} μs", $latency.as_micros()), - "response failed" - ); - } - (Level::$level, LatencyUnit::Nanos) => { - tracing::event!( - Level::$level, - classification = tracing::field::display($failure_classification), - latency = format_args!("{} ns", $latency.as_nanos()), - "response failed" - ); - } - )* - } - }; -} - impl OnFailure for DefaultOnFailure where FailureClass: fmt::Display, { fn on_failure(&mut self, failure_classification: FailureClass, latency: Duration, _: &Span) { - log_pattern_match!( - self, - &failure_classification, - latency, - [ERROR, WARN, INFO, DEBUG, TRACE] + let latency = Latency { + unit: self.latency_unit, + duration: latency, + }; + event_dynamic_lvl!( + self.level, + classification = %failure_classification, + %latency, + "response failed" ); } } diff --git a/tower-http/src/trace/on_request.rs b/tower-http/src/trace/on_request.rs index 0e343ae5..07de1893 100644 --- a/tower-http/src/trace/on_request.rs +++ b/tower-http/src/trace/on_request.rs @@ -77,22 +77,6 @@ impl DefaultOnRequest { impl OnRequest for DefaultOnRequest { fn on_request(&mut self, _: &Request, _: &Span) { - match self.level { - Level::ERROR => { - tracing::event!(Level::ERROR, "started processing request"); - } - Level::WARN => { - tracing::event!(Level::WARN, "started processing request"); - } - Level::INFO => { - tracing::event!(Level::INFO, "started processing request"); - } - Level::DEBUG => { - tracing::event!(Level::DEBUG, "started processing request"); - } - Level::TRACE => { - tracing::event!(Level::TRACE, "started processing request"); - } - } + event_dynamic_lvl!(self.level, "started processing request"); } } diff --git a/tower-http/src/trace/on_response.rs b/tower-http/src/trace/on_response.rs index 573de2e4..c6ece840 100644 --- a/tower-http/src/trace/on_response.rs +++ b/tower-http/src/trace/on_response.rs @@ -1,4 +1,4 @@ -use super::DEFAULT_MESSAGE_LEVEL; +use super::{Latency, DEFAULT_MESSAGE_LEVEL}; use crate::LatencyUnit; use http::Response; use std::time::Duration; @@ -101,162 +101,22 @@ impl DefaultOnResponse { } } -// Repeating this pattern match for each case is tedious. So we do it with a quick and -// dirty macro. -// -// Tracing requires all these parts to be declared statically. You cannot easily build -// events dynamically. -#[allow(unused_macros)] -macro_rules! log_pattern_match { - ( - $this:expr, $res:expr, $latency:expr, $include_headers:expr, [$($level:ident),*] - ) => { - match ($this.level, $include_headers, $this.latency_unit, status($res)) { - $( - (Level::$level, true, LatencyUnit::Seconds, None) => { - tracing::event!( - Level::$level, - latency = format_args!("{} s", $latency.as_secs_f64()), - response_headers = ?$res.headers(), - "finished processing request" - ); - } - (Level::$level, false, LatencyUnit::Seconds, None) => { - tracing::event!( - Level::$level, - latency = format_args!("{} s", $latency.as_secs_f64()), - "finished processing request" - ); - } - (Level::$level, true, LatencyUnit::Seconds, Some(status)) => { - tracing::event!( - Level::$level, - latency = format_args!("{} s", $latency.as_secs_f64()), - status = status, - response_headers = ?$res.headers(), - "finished processing request" - ); - } - (Level::$level, false, LatencyUnit::Seconds, Some(status)) => { - tracing::event!( - Level::$level, - latency = format_args!("{} s", $latency.as_secs_f64()), - status = status, - "finished processing request" - ); - } - - (Level::$level, true, LatencyUnit::Millis, None) => { - tracing::event!( - Level::$level, - latency = format_args!("{} ms", $latency.as_millis()), - response_headers = ?$res.headers(), - "finished processing request" - ); - } - (Level::$level, false, LatencyUnit::Millis, None) => { - tracing::event!( - Level::$level, - latency = format_args!("{} ms", $latency.as_millis()), - "finished processing request" - ); - } - (Level::$level, true, LatencyUnit::Millis, Some(status)) => { - tracing::event!( - Level::$level, - latency = format_args!("{} ms", $latency.as_millis()), - status = status, - response_headers = ?$res.headers(), - "finished processing request" - ); - } - (Level::$level, false, LatencyUnit::Millis, Some(status)) => { - tracing::event!( - Level::$level, - latency = format_args!("{} ms", $latency.as_millis()), - status = status, - "finished processing request" - ); - } - - (Level::$level, true, LatencyUnit::Micros, None) => { - tracing::event!( - Level::$level, - latency = format_args!("{} μs", $latency.as_micros()), - response_headers = ?$res.headers(), - "finished processing request" - ); - } - (Level::$level, false, LatencyUnit::Micros, None) => { - tracing::event!( - Level::$level, - latency = format_args!("{} μs", $latency.as_micros()), - "finished processing request" - ); - } - (Level::$level, true, LatencyUnit::Micros, Some(status)) => { - tracing::event!( - Level::$level, - latency = format_args!("{} μs", $latency.as_micros()), - status = status, - response_headers = ?$res.headers(), - "finished processing request" - ); - } - (Level::$level, false, LatencyUnit::Micros, Some(status)) => { - tracing::event!( - Level::$level, - latency = format_args!("{} μs", $latency.as_micros()), - status = status, - "finished processing request" - ); - } - - (Level::$level, true, LatencyUnit::Nanos, None) => { - tracing::event!( - Level::$level, - latency = format_args!("{} ns", $latency.as_nanos()), - response_headers = ?$res.headers(), - "finished processing request" - ); - } - (Level::$level, false, LatencyUnit::Nanos, None) => { - tracing::event!( - Level::$level, - latency = format_args!("{} ns", $latency.as_nanos()), - "finished processing request" - ); - } - (Level::$level, true, LatencyUnit::Nanos, Some(status)) => { - tracing::event!( - Level::$level, - latency = format_args!("{} ns", $latency.as_nanos()), - status = status, - response_headers = ?$res.headers(), - "finished processing request" - ); - } - (Level::$level, false, LatencyUnit::Nanos, Some(status)) => { - tracing::event!( - Level::$level, - latency = format_args!("{} ns", $latency.as_nanos()), - status = status, - "finished processing request" - ); - } - )* - } - }; -} - impl OnResponse for DefaultOnResponse { fn on_response(self, response: &Response, latency: Duration, _: &Span) { - log_pattern_match!( - self, - response, - latency, - self.include_headers, - [ERROR, WARN, INFO, DEBUG, TRACE] + let latency = Latency { + unit: self.latency_unit, + duration: latency, + }; + let response_headers = self + .include_headers + .then(|| tracing::field::debug(response.headers())); + + event_dynamic_lvl!( + self.level, + %latency, + status = status(response), + response_headers, + "finished processing request" ); } }