Skip to content

Commit 1cd1505

Browse files
jplattejplatte
authored
trace: Simplify dynamic tracing level application (#380)
1 parent 21aa172 commit 1cd1505

File tree

6 files changed

+103
-328
lines changed

6 files changed

+103
-328
lines changed

‎tower-http/src/trace/make_span.rs

+5-15
Original file line numberDiff line numberDiff line change
@@ -103,21 +103,11 @@ impl<B> MakeSpan<B> for DefaultMakeSpan {
103103
}
104104

105105
match self.level {
106-
Level::ERROR => {
107-
make_span!(Level::ERROR)
108-
}
109-
Level::WARN => {
110-
make_span!(Level::WARN)
111-
}
112-
Level::INFO => {
113-
make_span!(Level::INFO)
114-
}
115-
Level::DEBUG => {
116-
make_span!(Level::DEBUG)
117-
}
118-
Level::TRACE => {
119-
make_span!(Level::TRACE)
120-
}
106+
Level::ERROR => make_span!(Level::ERROR),
107+
Level::WARN => make_span!(Level::WARN),
108+
Level::INFO => make_span!(Level::INFO),
109+
Level::DEBUG => make_span!(Level::DEBUG),
110+
Level::TRACE => make_span!(Level::TRACE),
121111
}
122112
}
123113
}

‎tower-http/src/trace/mod.rs

+66
Original file line numberDiff line numberDiff line change
@@ -383,6 +383,8 @@
383383
//! [`Body::poll_trailers`]: http_body::Body::poll_trailers
384384
//! [`Body::poll_data`]: http_body::Body::poll_data
385385
386+
use std::{fmt, time::Duration};
387+
386388
use tracing::Level;
387389

388390
pub use self::{
@@ -397,6 +399,54 @@ pub use self::{
397399
on_response::{DefaultOnResponse, OnResponse},
398400
service::Trace,
399401
};
402+
use crate::LatencyUnit;
403+
404+
macro_rules! event_dynamic_lvl {
405+
( $(target: $target:expr,)? $(parent: $parent:expr,)? $lvl:expr, $($tt:tt)* ) => {
406+
match $lvl {
407+
tracing::Level::ERROR => {
408+
tracing::event!(
409+
$(target: $target,)?
410+
$(parent: $parent,)?
411+
tracing::Level::ERROR,
412+
$($tt)*
413+
);
414+
}
415+
tracing::Level::WARN => {
416+
tracing::event!(
417+
$(target: $target,)?
418+
$(parent: $parent,)?
419+
tracing::Level::WARN,
420+
$($tt)*
421+
);
422+
}
423+
tracing::Level::INFO => {
424+
tracing::event!(
425+
$(target: $target,)?
426+
$(parent: $parent,)?
427+
tracing::Level::INFO,
428+
$($tt)*
429+
);
430+
}
431+
tracing::Level::DEBUG => {
432+
tracing::event!(
433+
$(target: $target,)?
434+
$(parent: $parent,)?
435+
tracing::Level::DEBUG,
436+
$($tt)*
437+
);
438+
}
439+
tracing::Level::TRACE => {
440+
tracing::event!(
441+
$(target: $target,)?
442+
$(parent: $parent,)?
443+
tracing::Level::TRACE,
444+
$($tt)*
445+
);
446+
}
447+
}
448+
};
449+
}
400450

401451
mod body;
402452
mod future;
@@ -412,6 +462,22 @@ mod service;
412462
const DEFAULT_MESSAGE_LEVEL: Level = Level::DEBUG;
413463
const DEFAULT_ERROR_LEVEL: Level = Level::ERROR;
414464

465+
struct Latency {
466+
unit: LatencyUnit,
467+
duration: Duration,
468+
}
469+
470+
impl fmt::Display for Latency {
471+
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
472+
match self.unit {
473+
LatencyUnit::Seconds => write!(f, "{} s", self.duration.as_secs_f64()),
474+
LatencyUnit::Millis => write!(f, "{} ms", self.duration.as_millis()),
475+
LatencyUnit::Micros => write!(f, "{} μs", self.duration.as_micros()),
476+
LatencyUnit::Nanos => write!(f, "{} ns", self.duration.as_nanos()),
477+
}
478+
}
479+
}
480+
415481
#[cfg(test)]
416482
mod tests {
417483
use super::*;

‎tower-http/src/trace/on_eos.rs

+6-87
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
use super::DEFAULT_MESSAGE_LEVEL;
1+
use super::{Latency, DEFAULT_MESSAGE_LEVEL};
22
use crate::{classify::grpc_errors_as_failures::ParsedGrpcStatus, LatencyUnit};
33
use http::header::HeaderMap;
44
use std::time::Duration;
@@ -83,88 +83,12 @@ impl DefaultOnEos {
8383
}
8484
}
8585

86-
// Repeating this pattern match for each case is tedious. So we do it with a quick and
87-
// dirty macro.
88-
//
89-
// Tracing requires all these parts to be declared statically. You cannot easily build
90-
// events dynamically.
91-
#[allow(unused_macros)]
92-
macro_rules! log_pattern_match {
93-
(
94-
$this:expr, $stream_duration:expr, $status:expr, [$($level:ident),*]
95-
) => {
96-
match ($this.level, $this.latency_unit, $status) {
97-
$(
98-
(Level::$level, LatencyUnit::Seconds, None) => {
99-
tracing::event!(
100-
Level::$level,
101-
stream_duration = format_args!("{} s", $stream_duration.as_secs_f64()),
102-
"end of stream"
103-
);
104-
}
105-
(Level::$level, LatencyUnit::Seconds, Some(status)) => {
106-
tracing::event!(
107-
Level::$level,
108-
stream_duration = format_args!("{} s", $stream_duration.as_secs_f64()),
109-
status = status,
110-
"end of stream"
111-
);
112-
}
113-
114-
(Level::$level, LatencyUnit::Millis, None) => {
115-
tracing::event!(
116-
Level::$level,
117-
stream_duration = format_args!("{} ms", $stream_duration.as_millis()),
118-
"end of stream"
119-
);
120-
}
121-
(Level::$level, LatencyUnit::Millis, Some(status)) => {
122-
tracing::event!(
123-
Level::$level,
124-
stream_duration = format_args!("{} ms", $stream_duration.as_millis()),
125-
status = status,
126-
"end of stream"
127-
);
128-
}
129-
130-
(Level::$level, LatencyUnit::Micros, None) => {
131-
tracing::event!(
132-
Level::$level,
133-
stream_duration = format_args!("{} μs", $stream_duration.as_micros()),
134-
"end of stream"
135-
);
136-
}
137-
(Level::$level, LatencyUnit::Micros, Some(status)) => {
138-
tracing::event!(
139-
Level::$level,
140-
stream_duration = format_args!("{} μs", $stream_duration.as_micros()),
141-
status = status,
142-
"end of stream"
143-
);
144-
}
145-
146-
(Level::$level, LatencyUnit::Nanos, None) => {
147-
tracing::event!(
148-
Level::$level,
149-
stream_duration = format_args!("{} ns", $stream_duration.as_nanos()),
150-
"end of stream"
151-
);
152-
}
153-
(Level::$level, LatencyUnit::Nanos, Some(status)) => {
154-
tracing::event!(
155-
Level::$level,
156-
stream_duration = format_args!("{} ns", $stream_duration.as_nanos()),
157-
status = status,
158-
"end of stream"
159-
);
160-
}
161-
)*
162-
}
163-
};
164-
}
165-
16686
impl OnEos for DefaultOnEos {
16787
fn on_eos(self, trailers: Option<&HeaderMap>, stream_duration: Duration, _span: &Span) {
88+
let stream_duration = Latency {
89+
unit: self.latency_unit,
90+
duration: stream_duration,
91+
};
16892
let status = trailers.and_then(|trailers| {
16993
match crate::classify::grpc_errors_as_failures::classify_grpc_metadata(
17094
trailers,
@@ -178,11 +102,6 @@ impl OnEos for DefaultOnEos {
178102
}
179103
});
180104

181-
log_pattern_match!(
182-
self,
183-
stream_duration,
184-
status,
185-
[ERROR, WARN, INFO, DEBUG, TRACE]
186-
);
105+
event_dynamic_lvl!(self.level, %stream_duration, status, "end of stream");
187106
}
188107
}

‎tower-http/src/trace/on_failure.rs

+10-54
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
use super::DEFAULT_ERROR_LEVEL;
1+
use super::{Latency, DEFAULT_ERROR_LEVEL};
22
use crate::LatencyUnit;
33
use std::{fmt, time::Duration};
44
use tracing::{Level, Span};
@@ -81,64 +81,20 @@ impl DefaultOnFailure {
8181
}
8282
}
8383

84-
// Repeating this pattern match for each case is tedious. So we do it with a quick and
85-
// dirty macro.
86-
//
87-
// Tracing requires all these parts to be declared statically. You cannot easily build
88-
// events dynamically.
89-
macro_rules! log_pattern_match {
90-
(
91-
$this:expr, $failure_classification:expr, $latency:expr, [$($level:ident),*]
92-
) => {
93-
match ($this.level, $this.latency_unit) {
94-
$(
95-
(Level::$level, LatencyUnit::Seconds) => {
96-
tracing::event!(
97-
Level::$level,
98-
classification = tracing::field::display($failure_classification),
99-
latency = format_args!("{} s", $latency.as_secs_f64()),
100-
"response failed"
101-
);
102-
}
103-
(Level::$level, LatencyUnit::Millis) => {
104-
tracing::event!(
105-
Level::$level,
106-
classification = tracing::field::display($failure_classification),
107-
latency = format_args!("{} ms", $latency.as_millis()),
108-
"response failed"
109-
);
110-
}
111-
(Level::$level, LatencyUnit::Micros) => {
112-
tracing::event!(
113-
Level::$level,
114-
classification = tracing::field::display($failure_classification),
115-
latency = format_args!("{} μs", $latency.as_micros()),
116-
"response failed"
117-
);
118-
}
119-
(Level::$level, LatencyUnit::Nanos) => {
120-
tracing::event!(
121-
Level::$level,
122-
classification = tracing::field::display($failure_classification),
123-
latency = format_args!("{} ns", $latency.as_nanos()),
124-
"response failed"
125-
);
126-
}
127-
)*
128-
}
129-
};
130-
}
131-
13284
impl<FailureClass> OnFailure<FailureClass> for DefaultOnFailure
13385
where
13486
FailureClass: fmt::Display,
13587
{
13688
fn on_failure(&mut self, failure_classification: FailureClass, latency: Duration, _: &Span) {
137-
log_pattern_match!(
138-
self,
139-
&failure_classification,
140-
latency,
141-
[ERROR, WARN, INFO, DEBUG, TRACE]
89+
let latency = Latency {
90+
unit: self.latency_unit,
91+
duration: latency,
92+
};
93+
event_dynamic_lvl!(
94+
self.level,
95+
classification = %failure_classification,
96+
%latency,
97+
"response failed"
14298
);
14399
}
144100
}

‎tower-http/src/trace/on_request.rs

+1-17
Original file line numberDiff line numberDiff line change
@@ -77,22 +77,6 @@ impl DefaultOnRequest {
7777

7878
impl<B> OnRequest<B> for DefaultOnRequest {
7979
fn on_request(&mut self, _: &Request<B>, _: &Span) {
80-
match self.level {
81-
Level::ERROR => {
82-
tracing::event!(Level::ERROR, "started processing request");
83-
}
84-
Level::WARN => {
85-
tracing::event!(Level::WARN, "started processing request");
86-
}
87-
Level::INFO => {
88-
tracing::event!(Level::INFO, "started processing request");
89-
}
90-
Level::DEBUG => {
91-
tracing::event!(Level::DEBUG, "started processing request");
92-
}
93-
Level::TRACE => {
94-
tracing::event!(Level::TRACE, "started processing request");
95-
}
96-
}
80+
event_dynamic_lvl!(self.level, "started processing request");
9781
}
9882
}

0 commit comments

Comments
 (0)