Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

trace: Simplify dynamic tracing level application #380

Merged
merged 1 commit into from
Jul 19, 2023
Merged

trace: Simplify dynamic tracing level application #380

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
20 changes: 5 additions & 15 deletions tower-http/src/trace/make_span.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
}
}
}
66 changes: 66 additions & 0 deletions tower-http/src/trace/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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::{
Expand All @@ -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;
Expand All @@ -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::*;
Expand Down
93 changes: 6 additions & 87 deletions tower-http/src/trace/on_eos.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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;
Expand Down Expand Up @@ -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,
Expand All @@ -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");
}
}
64 changes: 10 additions & 54 deletions tower-http/src/trace/on_failure.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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};
Expand Down Expand Up @@ -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"
);
}
}
18 changes: 1 addition & 17 deletions tower-http/src/trace/on_request.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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");
}
}
Loading