Skip to content

Commit

Permalink
subscriber: change FmtSpan to a combinable bitflag (#1277)
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
zicklag authored and hawkw committed Mar 12, 2021
1 parent 73b472e commit 4ac4e8c
Show file tree
Hide file tree
Showing 3 changed files with 145 additions and 36 deletions.
27 changes: 21 additions & 6 deletions tracing-subscriber/src/fmt/fmt_layer.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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>() {
Expand All @@ -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);
Expand All @@ -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>() {
Expand All @@ -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);
Expand Down
135 changes: 107 additions & 28 deletions tracing-subscriber/src/fmt/format/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
/// 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 {
Expand All @@ -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)
}
}

Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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);
}
}
19 changes: 17 additions & 2 deletions tracing-subscriber/src/fmt/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down

0 comments on commit 4ac4e8c

Please sign in to comment.