trace: Simplify dynamic tracing level application (#380)

tower-rs · Jul 19, 2023 · 1cd1505 · 1cd1505
1 parent 21aa172
commit 1cd1505
Show file tree

Hide file tree

Showing 6 changed files with 103 additions and 328 deletions.
diff --git a/tower-http/src/trace/make_span.rs b/tower-http/src/trace/make_span.rs
@@ -103,21 +103,11 @@ impl<B> MakeSpan<B> 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
@@ -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
@@ -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
@@ -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<FailureClass> OnFailure<FailureClass> 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
@@ -77,22 +77,6 @@ impl DefaultOnRequest {
 
 impl<B> OnRequest<B> for DefaultOnRequest {
     fn on_request(&mut self, _: &Request<B>, _: &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");
     }
 }