use crate::{
field::RecordFields,
fmt::{format, FormatEvent, FormatFields, MakeWriter, TestWriter},
layer::{self, Context, Scope},
registry::{LookupSpan, SpanRef},
};
use format::{FmtSpan, TimingDisplay};
use std::{any::TypeId, cell::RefCell, fmt, io, marker::PhantomData, ops::Deref, time::Instant};
use tracing_core::{
field,
span::{Attributes, Id, Record},
Event, Metadata, Subscriber,
};
#[derive(Debug)]
pub struct Layer<
S,
N = format::DefaultFields,
E = format::Format<format::Full>,
W = fn() -> io::Stdout,
> {
make_writer: W,
fmt_fields: N,
fmt_event: E,
fmt_span: format::FmtSpanConfig,
_inner: PhantomData<S>,
}
#[deprecated(
since = "0.2.4",
note = "a separate layer builder type is not necessary, `Layer`s now support configuration"
)]
pub type LayerBuilder<
S,
N = format::DefaultFields,
E = format::Format<format::Full>,
W = fn() -> io::Stdout,
> = Layer<S, N, E, W>;
impl<S> Layer<S> {
#[deprecated(
since = "0.2.4",
note = "a separate layer builder is not necessary, use `Layer::new`/`Layer::default` instead"
)]
#[allow(deprecated)]
pub fn builder() -> LayerBuilder<S> {
Layer::default()
}
pub fn new() -> Self {
Self::default()
}
}
impl<S, N, E, W> Layer<S, N, E, W>
where
S: Subscriber + for<'a> LookupSpan<'a>,
N: for<'writer> FormatFields<'writer> + 'static,
W: MakeWriter + 'static,
{
pub fn event_format<E2>(self, e: E2) -> Layer<S, N, E2, W>
where
E2: FormatEvent<S, N> + 'static,
{
Layer {
fmt_fields: self.fmt_fields,
fmt_event: e,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
}
impl<S, N, E, W> Layer<S, N, E, W> {
pub fn with_writer<W2>(self, make_writer: W2) -> Layer<S, N, E, W2>
where
W2: MakeWriter + 'static,
{
Layer {
fmt_fields: self.fmt_fields,
fmt_event: self.fmt_event,
fmt_span: self.fmt_span,
make_writer,
_inner: self._inner,
}
}
pub fn with_test_writer(self) -> Layer<S, N, E, TestWriter> {
Layer {
fmt_fields: self.fmt_fields,
fmt_event: self.fmt_event,
fmt_span: self.fmt_span,
make_writer: TestWriter::default(),
_inner: self._inner,
}
}
}
impl<S, N, L, T, W> Layer<S, N, format::Format<L, T>, W>
where
N: for<'writer> FormatFields<'writer> + 'static,
{
pub fn with_timer<T2>(self, timer: T2) -> Layer<S, N, format::Format<L, T2>, W> {
Layer {
fmt_event: self.fmt_event.with_timer(timer),
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn without_time(self) -> Layer<S, N, format::Format<L, ()>, W> {
Layer {
fmt_event: self.fmt_event.without_time(),
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span.without_time(),
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn with_span_events(self, kind: FmtSpan) -> Self {
Layer {
fmt_event: self.fmt_event,
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span.with_kind(kind),
make_writer: self.make_writer,
_inner: self._inner,
}
}
#[cfg(feature = "ansi")]
#[cfg_attr(docsrs, doc(cfg(feature = "ansi")))]
pub fn with_ansi(self, ansi: bool) -> Layer<S, N, format::Format<L, T>, W> {
Layer {
fmt_event: self.fmt_event.with_ansi(ansi),
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn with_target(self, display_target: bool) -> Layer<S, N, format::Format<L, T>, W> {
Layer {
fmt_event: self.fmt_event.with_target(display_target),
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn with_level(self, display_level: bool) -> Layer<S, N, format::Format<L, T>, W> {
Layer {
fmt_event: self.fmt_event.with_level(display_level),
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn with_thread_ids(self, display_thread_ids: bool) -> Layer<S, N, format::Format<L, T>, W> {
Layer {
fmt_event: self.fmt_event.with_thread_ids(display_thread_ids),
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn with_thread_names(
self,
display_thread_names: bool,
) -> Layer<S, N, format::Format<L, T>, W> {
Layer {
fmt_event: self.fmt_event.with_thread_names(display_thread_names),
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn compact(self) -> Layer<S, N, format::Format<format::Compact, T>, W>
where
N: for<'writer> FormatFields<'writer> + 'static,
{
Layer {
fmt_event: self.fmt_event.compact(),
fmt_fields: self.fmt_fields,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
#[cfg(feature = "ansi")]
#[cfg_attr(docsrs, doc(cfg(feature = "ansi")))]
pub fn pretty(self) -> Layer<S, format::Pretty, format::Format<format::Pretty, T>, W> {
Layer {
fmt_event: self.fmt_event.pretty(),
fmt_fields: format::Pretty::default(),
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
#[cfg(feature = "json")]
#[cfg_attr(docsrs, doc(cfg(feature = "json")))]
pub fn json(self) -> Layer<S, format::JsonFields, format::Format<format::Json, T>, W> {
Layer {
fmt_event: self.fmt_event.json(),
fmt_fields: format::JsonFields::new(),
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
}
#[cfg(feature = "json")]
#[cfg_attr(docsrs, doc(cfg(feature = "json")))]
impl<S, T, W> Layer<S, format::JsonFields, format::Format<format::Json, T>, W> {
pub fn flatten_event(
self,
flatten_event: bool,
) -> Layer<S, format::JsonFields, format::Format<format::Json, T>, W> {
Layer {
fmt_event: self.fmt_event.flatten_event(flatten_event),
fmt_fields: format::JsonFields::new(),
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn with_current_span(
self,
display_current_span: bool,
) -> Layer<S, format::JsonFields, format::Format<format::Json, T>, W> {
Layer {
fmt_event: self.fmt_event.with_current_span(display_current_span),
fmt_fields: format::JsonFields::new(),
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
pub fn with_span_list(
self,
display_span_list: bool,
) -> Layer<S, format::JsonFields, format::Format<format::Json, T>, W> {
Layer {
fmt_event: self.fmt_event.with_span_list(display_span_list),
fmt_fields: format::JsonFields::new(),
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
}
impl<S, N, E, W> Layer<S, N, E, W> {
pub fn fmt_fields<N2>(self, fmt_fields: N2) -> Layer<S, N2, E, W>
where
N2: for<'writer> FormatFields<'writer> + 'static,
{
Layer {
fmt_event: self.fmt_event,
fmt_fields,
fmt_span: self.fmt_span,
make_writer: self.make_writer,
_inner: self._inner,
}
}
}
#[allow(deprecated)]
impl<S, N, E, W> LayerBuilder<S, N, E, W>
where
S: Subscriber + for<'a> LookupSpan<'a>,
N: for<'writer> FormatFields<'writer> + 'static,
E: FormatEvent<S, N> + 'static,
W: MakeWriter + 'static,
{
#[deprecated(
since = "0.2.4",
note = "`LayerBuilder` is no longer a separate type; this method is not necessary"
)]
pub fn finish(self) -> Layer<S, N, E, W> {
self
}
}
impl<S> Default for Layer<S> {
fn default() -> Self {
Layer {
fmt_fields: format::DefaultFields::default(),
fmt_event: format::Format::default(),
fmt_span: format::FmtSpanConfig::default(),
make_writer: io::stdout,
_inner: PhantomData,
}
}
}
impl<S, N, E, W> Layer<S, N, E, W>
where
S: Subscriber + for<'a> LookupSpan<'a>,
N: for<'writer> FormatFields<'writer> + 'static,
E: FormatEvent<S, N> + 'static,
W: MakeWriter + 'static,
{
#[inline]
fn make_ctx<'a>(&'a self, ctx: Context<'a, S>) -> FmtContext<'a, S, N> {
FmtContext {
ctx,
fmt_fields: &self.fmt_fields,
}
}
}
#[derive(Default)]
pub struct FormattedFields<E> {
_format_event: PhantomData<fn(E)>,
pub fields: String,
}
impl<E> FormattedFields<E> {
pub fn new(fields: String) -> Self {
Self {
fields,
_format_event: PhantomData,
}
}
}
impl<E> fmt::Debug for FormattedFields<E> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
f.debug_struct("FormattedFields")
.field("fields", &self.fields)
.finish()
}
}
impl<E> fmt::Display for FormattedFields<E> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{}", self.fields)
}
}
impl<E> Deref for FormattedFields<E> {
type Target = String;
fn deref(&self) -> &Self::Target {
&self.fields
}
}
macro_rules! with_event_from_span {
($id:ident, $span:ident, $($field:literal = $value:expr),*, |$event:ident| $code:block) => {
let meta = $span.metadata();
let cs = meta.callsite();
let fs = field::FieldSet::new(&[$($field),*], cs);
#[allow(unused)]
let mut iter = fs.iter();
let v = [$(
(&iter.next().unwrap(), Some(&$value as &dyn field::Value)),
)*];
let vs = fs.value_set(&v);
let $event = Event::new_child_of($id, meta, &vs);
$code
};
}
impl<S, N, E, W> layer::Layer<S> for Layer<S, N, E, W>
where
S: Subscriber + for<'a> LookupSpan<'a>,
N: for<'writer> FormatFields<'writer> + 'static,
E: FormatEvent<S, N> + 'static,
W: MakeWriter + 'static,
{
fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
let span = ctx.span(id).expect("Span not found, this is a bug");
let mut extensions = span.extensions_mut();
if extensions.get_mut::<FormattedFields<N>>().is_none() {
let mut buf = String::new();
if self.fmt_fields.format_fields(&mut buf, attrs).is_ok() {
let fmt_fields = FormattedFields {
fields: buf,
_format_event: PhantomData::<fn(N)>,
};
extensions.insert(fmt_fields);
}
}
if self.fmt_span.fmt_timing
&& self.fmt_span.trace_close()
&& extensions.get_mut::<Timings>().is_none()
{
extensions.insert(Timings::new());
}
if self.fmt_span.trace_new() {
with_event_from_span!(id, span, "message" = "new", |event| {
drop(extensions);
drop(span);
self.on_event(&event, ctx);
});
}
}
fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) {
let span = ctx.span(id).expect("Span not found, this is a bug");
let mut extensions = span.extensions_mut();
if let Some(FormattedFields { ref mut fields, .. }) =
extensions.get_mut::<FormattedFields<N>>()
{
let _ = self.fmt_fields.add_fields(fields, values);
} else {
let mut buf = String::new();
if self.fmt_fields.format_fields(&mut buf, values).is_ok() {
let fmt_fields = FormattedFields {
fields: buf,
_format_event: PhantomData::<fn(N)>,
};
extensions.insert(fmt_fields);
}
}
}
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 {
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>() {
let now = Instant::now();
timings.idle += (now - timings.last).as_nanos() as u64;
timings.last = now;
}
if self.fmt_span.trace_active() {
with_event_from_span!(id, span, "message" = "enter", |event| {
drop(extensions);
drop(span);
self.on_event(&event, ctx);
});
}
}
}
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 {
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>() {
let now = Instant::now();
timings.busy += (now - timings.last).as_nanos() as u64;
timings.last = now;
}
if self.fmt_span.trace_active() {
with_event_from_span!(id, span, "message" = "exit", |event| {
drop(extensions);
drop(span);
self.on_event(&event, ctx);
});
}
}
}
fn on_close(&self, id: Id, ctx: Context<'_, S>) {
if self.fmt_span.trace_close() {
let span = ctx.span(&id).expect("Span not found, this is a bug");
let extensions = span.extensions();
if let Some(timing) = extensions.get::<Timings>() {
let Timings {
busy,
mut idle,
last,
} = *timing;
idle += (Instant::now() - last).as_nanos() as u64;
let t_idle = field::display(TimingDisplay(idle));
let t_busy = field::display(TimingDisplay(busy));
with_event_from_span!(
id,
span,
"message" = "close",
"time.busy" = t_busy,
"time.idle" = t_idle,
|event| {
drop(extensions);
drop(span);
self.on_event(&event, ctx);
}
);
} else {
with_event_from_span!(id, span, "message" = "close", |event| {
drop(extensions);
drop(span);
self.on_event(&event, ctx);
});
}
}
}
fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
thread_local! {
static BUF: RefCell<String> = RefCell::new(String::new());
}
BUF.with(|buf| {
let borrow = buf.try_borrow_mut();
let mut a;
let mut b;
let mut buf = match borrow {
Ok(buf) => {
a = buf;
&mut *a
}
_ => {
b = String::new();
&mut b
}
};
let ctx = self.make_ctx(ctx);
if self.fmt_event.format_event(&ctx, &mut buf, event).is_ok() {
let mut writer = self.make_writer.make_writer();
let _ = io::Write::write_all(&mut writer, buf.as_bytes());
}
buf.clear();
});
}
unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> {
match () {
_ if id == TypeId::of::<Self>() => Some(self as *const Self as *const ()),
_ if id == TypeId::of::<E>() => Some(&self.fmt_event as *const E as *const ()),
_ if id == TypeId::of::<N>() => Some(&self.fmt_fields as *const N as *const ()),
_ if id == TypeId::of::<W>() => Some(&self.make_writer as *const W as *const ()),
_ => None,
}
}
}
pub struct FmtContext<'a, S, N> {
pub(crate) ctx: Context<'a, S>,
pub(crate) fmt_fields: &'a N,
}
impl<'a, S, N> fmt::Debug for FmtContext<'a, S, N> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
f.debug_struct("FmtContext").finish()
}
}
impl<'cx, 'writer, S, N> FormatFields<'writer> for FmtContext<'cx, S, N>
where
S: Subscriber + for<'lookup> LookupSpan<'lookup>,
N: FormatFields<'writer> + 'static,
{
fn format_fields<R: RecordFields>(
&self,
writer: &'writer mut dyn fmt::Write,
fields: R,
) -> fmt::Result {
self.fmt_fields.format_fields(writer, fields)
}
}
impl<'a, S, N> FmtContext<'a, S, N>
where
S: Subscriber + for<'lookup> LookupSpan<'lookup>,
N: for<'writer> FormatFields<'writer> + 'static,
{
pub fn visit_spans<E, F>(&self, mut f: F) -> Result<(), E>
where
F: FnMut(&SpanRef<'_, S>) -> Result<(), E>,
{
for span in self.ctx.scope() {
f(&span)?;
}
Ok(())
}
#[inline]
pub fn metadata(&self, id: &Id) -> Option<&'static Metadata<'static>>
where
S: for<'lookup> LookupSpan<'lookup>,
{
self.ctx.metadata(id)
}
#[inline]
pub fn span(&self, id: &Id) -> Option<SpanRef<'_, S>>
where
S: for<'lookup> LookupSpan<'lookup>,
{
self.ctx.span(id)
}
#[inline]
pub fn exists(&self, id: &Id) -> bool
where
S: for<'lookup> LookupSpan<'lookup>,
{
self.ctx.exists(id)
}
#[inline]
pub fn lookup_current(&self) -> Option<SpanRef<'_, S>>
where
S: for<'lookup> LookupSpan<'lookup>,
{
self.ctx.lookup_current()
}
pub fn scope(&self) -> Scope<'_, S>
where
S: for<'lookup> LookupSpan<'lookup>,
{
self.ctx.scope()
}
pub fn field_format(&self) -> &N {
self.fmt_fields
}
}
struct Timings {
idle: u64,
busy: u64,
last: Instant,
}
impl Timings {
fn new() -> Self {
Self {
idle: 0,
busy: 0,
last: Instant::now(),
}
}
}
#[cfg(test)]
mod test {
use crate::fmt::{
self,
format::{self, test::MockTime, Format},
layer::Layer as _,
test::MockWriter,
time,
};
use crate::Registry;
use format::FmtSpan;
use lazy_static::lazy_static;
use regex::Regex;
use std::sync::Mutex;
use tracing::subscriber::with_default;
use tracing_core::dispatcher::Dispatch;
#[test]
fn impls() {
let f = Format::default().with_timer(time::Uptime::default());
let fmt = fmt::Layer::default().event_format(f);
let subscriber = fmt.with_subscriber(Registry::default());
let _dispatch = Dispatch::new(subscriber);
let f = format::Format::default();
let fmt = fmt::Layer::default().event_format(f);
let subscriber = fmt.with_subscriber(Registry::default());
let _dispatch = Dispatch::new(subscriber);
let f = format::Format::default().compact();
let fmt = fmt::Layer::default().event_format(f);
let subscriber = fmt.with_subscriber(Registry::default());
let _dispatch = Dispatch::new(subscriber);
}
#[test]
fn fmt_layer_downcasts() {
let f = format::Format::default();
let fmt = fmt::Layer::default().event_format(f);
let subscriber = fmt.with_subscriber(Registry::default());
let dispatch = Dispatch::new(subscriber);
assert!(dispatch.downcast_ref::<fmt::Layer<Registry>>().is_some());
}
#[test]
fn fmt_layer_downcasts_to_parts() {
let f = format::Format::default();
let fmt = fmt::Layer::default().event_format(f);
let subscriber = fmt.with_subscriber(Registry::default());
let dispatch = Dispatch::new(subscriber);
assert!(dispatch.downcast_ref::<format::DefaultFields>().is_some());
assert!(dispatch.downcast_ref::<format::Format>().is_some())
}
#[test]
fn is_lookup_span() {
fn assert_lookup_span<T: for<'a> crate::registry::LookupSpan<'a>>(_: T) {}
let fmt = fmt::Layer::default();
let subscriber = fmt.with_subscriber(Registry::default());
assert_lookup_span(subscriber)
}
fn sanitize_timings(s: String) -> String {
let re = Regex::new("time\\.(idle|busy)=([0-9.]+)[mµn]s").unwrap();
re.replace_all(s.as_str(), "timing").to_string()
}
#[test]
fn synthesize_span_none() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(vec![]);
}
let make_writer = || MockWriter::new(&BUF);
let subscriber = crate::fmt::Subscriber::builder()
.with_writer(make_writer)
.with_level(false)
.with_ansi(false)
.with_timer(MockTime)
.finish();
with_default(subscriber, || {
let span1 = tracing::info_span!("span1", x = 42);
let _e = span1.enter();
});
let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap());
assert_eq!("", actual.as_str());
}
#[test]
fn synthesize_span_active() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(vec![]);
}
let make_writer = || MockWriter::new(&BUF);
let subscriber = crate::fmt::Subscriber::builder()
.with_writer(make_writer)
.with_level(false)
.with_ansi(false)
.with_timer(MockTime)
.with_span_events(FmtSpan::ACTIVE)
.finish();
with_default(subscriber, || {
let span1 = tracing::info_span!("span1", x = 42);
let _e = span1.enter();
});
let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap());
assert_eq!(
"fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: enter\n\
fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: exit\n",
actual.as_str()
);
}
#[test]
fn synthesize_span_close() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(vec![]);
}
let make_writer = || MockWriter::new(&BUF);
let subscriber = crate::fmt::Subscriber::builder()
.with_writer(make_writer)
.with_level(false)
.with_ansi(false)
.with_timer(MockTime)
.with_span_events(FmtSpan::CLOSE)
.finish();
with_default(subscriber, || {
let span1 = tracing::info_span!("span1", x = 42);
let _e = span1.enter();
});
let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap());
assert_eq!(
"fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: close timing timing\n",
actual.as_str()
);
}
#[test]
fn synthesize_span_close_no_timing() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(vec![]);
}
let make_writer = || MockWriter::new(&BUF);
let subscriber = crate::fmt::Subscriber::builder()
.with_writer(make_writer)
.with_level(false)
.with_ansi(false)
.with_timer(MockTime)
.without_time()
.with_span_events(FmtSpan::CLOSE)
.finish();
with_default(subscriber, || {
let span1 = tracing::info_span!("span1", x = 42);
let _e = span1.enter();
});
let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap());
assert_eq!(
" span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: close\n",
actual.as_str()
);
}
#[test]
fn synthesize_span_full() {
lazy_static! {
static ref BUF: Mutex<Vec<u8>> = Mutex::new(vec![]);
}
let make_writer = || MockWriter::new(&BUF);
let subscriber = crate::fmt::Subscriber::builder()
.with_writer(make_writer)
.with_level(false)
.with_ansi(false)
.with_timer(MockTime)
.with_span_events(FmtSpan::FULL)
.finish();
with_default(subscriber, || {
let span1 = tracing::info_span!("span1", x = 42);
let _e = span1.enter();
});
let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap());
assert_eq!(
"fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: new\n\
fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: enter\n\
fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: exit\n\
fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: close timing timing\n",
actual.as_str()
);
}
}