subscriber: change FmtSpan to a combinable bitflag (#1277)

This backports #1277 from `master`.

Fixes #1136.

Allows arbitrarily combining different FmtSpan events to listen to.

Motivation
----------

The idea is to allow any combination of `FmtSpan` options, such as the
currently unachievable combination of `FmtSpan::NEW | FmtSpan::CLOSE`.

Solution
--------

Make `FmtSpan` behave like a bitflag that can be combined using the
bitwise or operator ( `|` ) while maintaining backward compatibility by
keeping the same names for all existing presets and keeping the
implementation details hidden.
This commit is contained in:
Zicklag 2021-03-11 12:45:24 -06:00 committed by Eliza Weisman
parent f3eb5ccf2d
commit a947c5a63f
3 changed files with 149 additions and 40 deletions

View File

@ -259,18 +259,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 `Subscriber`s or by
/// `Layer`s added to this subscriber.
@ -627,7 +642,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::<Timings>() {
@ -636,7 +651,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);
@ -647,7 +662,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::<Timings>() {
@ -656,7 +671,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);

View File

@ -1088,40 +1088,89 @@ impl<'a, F> fmt::Debug for FieldFnVisitor<'a, F> {
///
/// See also [`with_span_events`](../struct.SubscriberBuilder.html#method.with_span_events).
#[derive(Clone, Eq, PartialEq, Ord, PartialOrd)]
pub struct FmtSpan(FmtSpanInner);
pub struct FmtSpan(u8);
impl FmtSpan {
/// spans are ignored (this is the default)
pub const NONE: FmtSpan = FmtSpan(FmtSpanInner::None);
/// one event per enter/exit of a span
pub const ACTIVE: FmtSpan = FmtSpan(FmtSpanInner::Active);
/// 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(FmtSpanInner::Close);
/// events at all points (new, enter, exit, drop)
pub const FULL: FmtSpan = FmtSpan(FmtSpanInner::Full);
}
pub const CLOSE: FmtSpan = FmtSpan(1 << 3);
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"),
}
/// spans are ignored (this is the default)
pub const NONE: FmtSpan = FmtSpan(0);
/// one event per enter/exit of a span
pub const ACTIVE: FmtSpan = FmtSpan(FmtSpan::ENTER.0 | FmtSpan::EXIT.0);
/// events at all points (new, enter, exit, drop)
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
}
}
#[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,
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 {
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")?;
}
Ok(())
}
}
pub(super) struct FmtSpanConfig {
@ -1143,13 +1192,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)
}
}
@ -1193,7 +1245,7 @@ pub(super) mod test {
use lazy_static::lazy_static;
use tracing::{self, subscriber::with_default};
use super::TimingDisplay;
use super::{FmtSpan, TimingDisplay};
use std::{fmt, sync::Mutex};
pub(crate) struct MockTime;
@ -1380,4 +1432,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);
}
}

View File

@ -623,18 +623,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 `Subscriber`s or by
/// `Layer`s added to this subscriber.