From 2304525ce76cba5f929a0b59628377746d63f55f Mon Sep 17 00:00:00 2001 From: Zicklag Date: Wed, 3 Mar 2021 14:03:09 -0600 Subject: [PATCH] Switch FmtSpan To a Combinable Bitflag Fixes #1136. Allows arbitrarily combining different FmtSpan events to listen to. --- tracing-subscriber/src/fmt/fmt_subscriber.rs | 27 +++- tracing-subscriber/src/fmt/format/mod.rs | 135 +++++++++++++++---- tracing-subscriber/src/fmt/mod.rs | 19 ++- 3 files changed, 145 insertions(+), 36 deletions(-) diff --git a/tracing-subscriber/src/fmt/fmt_subscriber.rs b/tracing-subscriber/src/fmt/fmt_subscriber.rs index ec140e0ec5..598e7d7def 100644 --- a/tracing-subscriber/src/fmt/fmt_subscriber.rs +++ b/tracing-subscriber/src/fmt/fmt_subscriber.rs @@ -229,18 +229,33 @@ where /// - `FmtSpan::NONE`: No events will be synthesized when spans are /// created, entered, exited, or closed. Data from spans will still be /// included as the context for formatted events. This is the default. - /// - `FmtSpan::ACTIVE`: Events will be synthesized when spans are entered - /// or exited. + /// - `FmtSpan::NEW`: An event will be synthesized when spans are created. + /// - `FmtSpan::ENTER`: An event will be synthesized when spans are entered. + /// - `FmtSpan::EXIT`: An event will be synthesized when spans are exited. /// - `FmtSpan::CLOSE`: An event will be synthesized when a span closes. If /// [timestamps are enabled][time] for this formatter, the generated /// event will contain fields with the span's _busy time_ (the total /// time for which it was entered) and _idle time_ (the total time that /// the span existed but was not entered). + /// - `FmtSpan::ACTIVE`: Events will be synthesized when spans are entered + /// or exited. /// - `FmtSpan::FULL`: Events will be synthesized whenever a span is /// created, entered, exited, or closed. If timestamps are enabled, the /// close event will contain the span's busy and idle time, as /// described above. /// + /// The options can be enabled in any combination. For instance, the following + /// will synthesize events whenever spans are created and closed: + /// + /// ```rust + /// use tracing_subscriber::fmt; + /// use tracing_subscriber::fmt::format::FmtSpan; + /// + /// let subscriber = fmt() + /// .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) + /// .finish(); + /// ``` + /// /// Note that the generated events will only be part of the log output by /// this formatter; they will not be recorded by other `Collector`s or by /// `Subscriber`s added to this subscriber. @@ -603,7 +618,7 @@ where } fn on_enter(&self, id: &Id, ctx: Context<'_, S>) { - if self.fmt_span.trace_active() || self.fmt_span.trace_close() && self.fmt_span.fmt_timing { + if self.fmt_span.trace_enter() || self.fmt_span.trace_close() && self.fmt_span.fmt_timing { let span = ctx.span(id).expect("Span not found, this is a bug"); let mut extensions = span.extensions_mut(); if let Some(timings) = extensions.get_mut::() { @@ -612,7 +627,7 @@ where timings.last = now; } - if self.fmt_span.trace_active() { + if self.fmt_span.trace_enter() { with_event_from_span!(id, span, "message" = "enter", |event| { drop(extensions); drop(span); @@ -623,7 +638,7 @@ where } fn on_exit(&self, id: &Id, ctx: Context<'_, S>) { - if self.fmt_span.trace_active() || self.fmt_span.trace_close() && self.fmt_span.fmt_timing { + if self.fmt_span.trace_exit() || self.fmt_span.trace_close() && self.fmt_span.fmt_timing { let span = ctx.span(id).expect("Span not found, this is a bug"); let mut extensions = span.extensions_mut(); if let Some(timings) = extensions.get_mut::() { @@ -632,7 +647,7 @@ where timings.last = now; } - if self.fmt_span.trace_active() { + if self.fmt_span.trace_exit() { with_event_from_span!(id, span, "message" = "exit", |event| { drop(extensions); drop(span); diff --git a/tracing-subscriber/src/fmt/format/mod.rs b/tracing-subscriber/src/fmt/format/mod.rs index 9c06c26ce2..cf50d03508 100644 --- a/tracing-subscriber/src/fmt/format/mod.rs +++ b/tracing-subscriber/src/fmt/format/mod.rs @@ -1041,40 +1041,89 @@ impl<'a, F> fmt::Debug for FieldFnVisitor<'a, F> { /// /// See also [`with_span_events`](super::CollectorBuilder::with_span_events()). #[derive(Clone, Eq, PartialEq, Ord, PartialOrd)] -pub struct FmtSpan(FmtSpanInner); +pub struct FmtSpan(u8); impl FmtSpan { + /// one event when span is created + pub const NEW: FmtSpan = FmtSpan(1 << 0); + /// one event per enter of a span + pub const ENTER: FmtSpan = FmtSpan(1 << 1); + /// one event per exit of a span + pub const EXIT: FmtSpan = FmtSpan(1 << 2); + /// one event when the span is dropped + pub const CLOSE: FmtSpan = FmtSpan(1 << 3); + /// spans are ignored (this is the default) - pub const NONE: FmtSpan = FmtSpan(FmtSpanInner::None); + pub const NONE: FmtSpan = FmtSpan(0); /// one event per enter/exit of a span - pub const ACTIVE: FmtSpan = FmtSpan(FmtSpanInner::Active); - /// one event when the span is dropped - pub const CLOSE: FmtSpan = FmtSpan(FmtSpanInner::Close); + pub const ACTIVE: FmtSpan = FmtSpan(FmtSpan::ENTER.0 | FmtSpan::EXIT.0); /// events at all points (new, enter, exit, drop) - pub const FULL: FmtSpan = FmtSpan(FmtSpanInner::Full); + pub const FULL: FmtSpan = + FmtSpan(FmtSpan::NEW.0 | FmtSpan::ENTER.0 | FmtSpan::EXIT.0 | FmtSpan::CLOSE.0); + + /// Check whether or not a certain flag is set for this [`FmtSpan`] + fn contains(&self, other: FmtSpan) -> bool { + self.clone() & other.clone() == other + } } +macro_rules! impl_fmt_span_bit_op { + ($trait:ident, $func:ident, $op:tt) => { + impl std::ops::$trait for FmtSpan { + type Output = FmtSpan; + + fn $func(self, rhs: Self) -> Self::Output { + FmtSpan(self.0 $op rhs.0) + } + } + }; +} + +macro_rules! impl_fmt_span_bit_assign_op { + ($trait:ident, $func:ident, $op:tt) => { + impl std::ops::$trait for FmtSpan { + fn $func(&mut self, rhs: Self) { + *self = FmtSpan(self.0 $op rhs.0) + } + } + }; +} + +impl_fmt_span_bit_op!(BitAnd, bitand, &); +impl_fmt_span_bit_op!(BitOr, bitor, |); +impl_fmt_span_bit_op!(BitXor, bitxor, ^); + +impl_fmt_span_bit_assign_op!(BitAndAssign, bitand_assign, &); +impl_fmt_span_bit_assign_op!(BitOrAssign, bitor_assign, |); +impl_fmt_span_bit_assign_op!(BitXorAssign, bitxor_assign, ^); + impl Debug for FmtSpan { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - match self.0 { - FmtSpanInner::None => f.write_str("FmtSpan::NONE"), - FmtSpanInner::Active => f.write_str("FmtSpan::ACTIVE"), - FmtSpanInner::Close => f.write_str("FmtSpan::CLOSE"), - FmtSpanInner::Full => f.write_str("FmtSpan::FULL"), + let mut wrote_flag = false; + let mut write_flags = |flag, flag_str| -> fmt::Result { + if self.contains(flag) { + if wrote_flag { + f.write_str(" | ")?; + } + + f.write_str(flag_str)?; + wrote_flag = true; + } + + Ok(()) + }; + + if FmtSpan::NONE | self.clone() == FmtSpan::NONE { + f.write_str("FmtSpan::NONE")?; + } else { + write_flags(FmtSpan::NEW, "FmtSpan::NEW")?; + write_flags(FmtSpan::ENTER, "FmtSpan::ENTER")?; + write_flags(FmtSpan::EXIT, "FmtSpan::EXIT")?; + write_flags(FmtSpan::CLOSE, "FmtSpan::CLOSE")?; } - } -} -#[derive(Copy, Clone, Debug, Eq, PartialEq, Hash, Ord, PartialOrd)] -enum FmtSpanInner { - /// spans are ignored (this is the default) - None, - /// one event per enter/exit of a span - Active, - /// one event when the span is dropped - Close, - /// events at all points (new, enter, exit, drop) - Full, + Ok(()) + } } pub(super) struct FmtSpanConfig { @@ -1096,13 +1145,16 @@ impl FmtSpanConfig { } } pub(super) fn trace_new(&self) -> bool { - matches!(self.kind, FmtSpan::FULL) + self.kind.contains(FmtSpan::NEW) } - pub(super) fn trace_active(&self) -> bool { - matches!(self.kind, FmtSpan::ACTIVE | FmtSpan::FULL) + pub(super) fn trace_enter(&self) -> bool { + self.kind.contains(FmtSpan::ENTER) + } + pub(super) fn trace_exit(&self) -> bool { + self.kind.contains(FmtSpan::EXIT) } pub(super) fn trace_close(&self) -> bool { - matches!(self.kind, FmtSpan::CLOSE | FmtSpan::FULL) + self.kind.contains(FmtSpan::CLOSE) } } @@ -1149,7 +1201,7 @@ pub(super) mod test { dispatch::{set_default, Dispatch}, }; - use super::TimingDisplay; + use super::{FmtSpan, TimingDisplay}; use std::fmt; pub(crate) struct MockTime; @@ -1284,4 +1336,31 @@ pub(super) mod test { assert_eq!(fmt(123456789012), "123s"); assert_eq!(fmt(1234567890123), "1235s"); } + + #[test] + fn fmt_span_combinations() { + let f = FmtSpan::NONE; + assert_eq!(f.contains(FmtSpan::NEW), false); + assert_eq!(f.contains(FmtSpan::ENTER), false); + assert_eq!(f.contains(FmtSpan::EXIT), false); + assert_eq!(f.contains(FmtSpan::CLOSE), false); + + let f = FmtSpan::ACTIVE; + assert_eq!(f.contains(FmtSpan::NEW), false); + assert_eq!(f.contains(FmtSpan::ENTER), true); + assert_eq!(f.contains(FmtSpan::EXIT), true); + assert_eq!(f.contains(FmtSpan::CLOSE), false); + + let f = FmtSpan::FULL; + assert_eq!(f.contains(FmtSpan::NEW), true); + assert_eq!(f.contains(FmtSpan::ENTER), true); + assert_eq!(f.contains(FmtSpan::EXIT), true); + assert_eq!(f.contains(FmtSpan::CLOSE), true); + + let f = FmtSpan::NEW | FmtSpan::CLOSE; + assert_eq!(f.contains(FmtSpan::NEW), true); + assert_eq!(f.contains(FmtSpan::ENTER), false); + assert_eq!(f.contains(FmtSpan::EXIT), false); + assert_eq!(f.contains(FmtSpan::CLOSE), true); + } } diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index a77b4594c6..3ccd948c6a 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -642,18 +642,33 @@ where /// - `FmtSpan::NONE`: No events will be synthesized when spans are /// created, entered, exited, or closed. Data from spans will still be /// included as the context for formatted events. This is the default. - /// - `FmtSpan::ACTIVE`: Events will be synthesized when spans are entered - /// or exited. + /// - `FmtSpan::NEW`: An event will be synthesized when spans are created. + /// - `FmtSpan::ENTER`: An event will be synthesized when spans are entered. + /// - `FmtSpan::EXIT`: An event will be synthesized when spans are exited. /// - `FmtSpan::CLOSE`: An event will be synthesized when a span closes. If /// [timestamps are enabled][time] for this formatter, the generated /// event will contain fields with the span's _busy time_ (the total /// time for which it was entered) and _idle time_ (the total time that /// the span existed but was not entered). + /// - `FmtSpan::ACTIVE`: An event will be synthesized when spans are entered + /// or exited. /// - `FmtSpan::FULL`: Events will be synthesized whenever a span is /// created, entered, exited, or closed. If timestamps are enabled, the /// close event will contain the span's busy and idle time, as /// described above. /// + /// The options can be enabled in any combination. For instance, the following + /// will synthesize events whenever spans are created and closed: + /// + /// ```rust + /// use tracing_subscriber::fmt::format::FmtSpan; + /// use tracing_subscriber::fmt; + /// + /// let subscriber = fmt() + /// .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) + /// .finish(); + /// ``` + /// /// Note that the generated events will only be part of the log output by /// this formatter; they will not be recorded by other `Collector`s or by /// `Subscriber`s added to this subscriber.