fmt

tracing = "=0.1.44"
tracing-subscriber = { version = "=0.3.23", features = ["json"] }

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,
    is_ansi: bool,
    ansi_sanitization: bool,
    log_internal_errors: bool,
    _inner: PhantomData<fn(S)>,
}

pub trait FormatEvent<S, N>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
{
    /// Write a log message for [`Event`] in [`FmtContext`] to the given [`Writer`].
    fn format_event(
        &self,
        ctx: &FmtContext<'_, S, N>,
        writer: Writer<'_>,
        event: &Event<'_>,
    ) -> fmt::Result;
}

pub trait FormatFields<'writer> {
    /// Format the provided `fields` to the provided [`Writer`], returning a result.
    fn format_fields<R: RecordFields>(&self, writer: Writer<'writer>, fields: R) -> fmt::Result;

    fn add_fields(
        &self,
        current: &'writer mut FormattedFields<Self>,
        fields: &span::Record<'_>,
    ) -> fmt::Result {
        // ...
    }
}

    fn on_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 fields = FormattedFields::<N>::new(String::new());
            fields.was_ansi = self.is_ansi;
            fields.was_ansi_sanitized = self.ansi_sanitization;
            if self
                .fmt_fields
                .format_fields(fields.as_writer(), attrs)
                .is_ok()
            {
                extensions.insert(fields);
            } else {
                // ... eprintln! 一条错误
            }
        }
        // ... 下面是 with_span_events 的计时和 NEW 事件，后面讲
    }

use tracing::span::{Attributes, Id, Record};
use tracing::{Subscriber, field, info, info_span};
use tracing_subscriber::fmt::{self, FormattedFields, format::DefaultFields};
use tracing_subscriber::layer::{Context, Layer};
use tracing_subscriber::prelude::*;
use tracing_subscriber::registry::LookupSpan;

// 放在 fmt::Layer 外面一层：Layered 先调内层，所以它看到的是 fmt 处理完之后的 Extensions
struct Peek;

impl Peek {
  fn show<S: Subscriber + for<'a> LookupSpan<'a>>(&self, hook: &str, id: &Id, ctx: &Context<'_, S>) {
    let span = ctx.span(id).unwrap();
    let ext = span.extensions();
    let fields = ext.get::<FormattedFields<DefaultFields>>();
    println!("[peek {hook}] {}: {:?}", span.name(), fields.map(|f| f.fields.as_str()));
  }
}

impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for Peek {
  fn on_new_span(&self, _: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
    self.show("on_new_span", id, &ctx);
  }
  fn on_record(&self, id: &Id, _: &Record<'_>, ctx: Context<'_, S>) {
    self.show("on_record", id, &ctx);
  }
}

fn main() {
  tracing_subscriber::registry()
    .with(fmt::layer().with_ansi(false).without_time())
    .with(Peek)
    .init();

  let span = info_span!("login", method = "oauth", user = field::Empty);
  let _g = span.enter();
  info!("before record");
  span.record("user", "alice");
  info!("after record");
}

[peek on_new_span] login: Some("method=\"oauth\"")
 INFO login{method="oauth"}: extensions: before record
[peek on_record] login: Some("method=\"oauth\" user=\"alice\"")
 INFO login{method="oauth" user="alice"}: extensions: after record

    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        thread_local! {
            static BUF: RefCell<String> = const { 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, event);
            if self
                .fmt_event
                .format_event(
                    &ctx,
                    format::Writer::new(&mut buf)
                        .with_ansi(self.is_ansi)
                        .with_ansi_sanitization(self.ansi_sanitization),
                    event,
                )
                .is_ok()
            {
                let mut writer = self.make_writer.make_writer_for(event.metadata());
                let res = io::Write::write_all(&mut writer, buf.as_bytes());
                if self.log_internal_errors {
                    if let Err(e) = res {
                        eprintln!("[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: {}\n", e);
                    }
                }
            } else if self.log_internal_errors {
                // ... 格式化失败时写一条错误说明
            }

            buf.clear();
        });
    }

[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: Broken pipe (os error 32)

Err(e) => tracing::warn!(error = %e, "search: index refresh failed"),

fn main() {
  tracing_subscriber::fmt().with_ansi(false).init();
  let e = std::io::Error::other("connection refused");
  // 本站 crates/app/src/main.rs 里那一行；target 写死成 "app"，等同于在 app crate 根模块里调用
  tracing::warn!(target: "app", error = %e, "search: index refresh failed");
}

2026-10-23T18:16:47.781508Z  WARN app: search: index refresh failed error=connection refused$

        self.format_timestamp(&mut writer)?;

        if self.display_level {
            // ...
            write!(writer, "{} ", fmt_level)?;
        }
        // ... display_thread_name / display_thread_id，默认关
        if let Some(scope) = ctx.event_scope() {
            // ...
            for span in scope.from_root() {
                write!(writer, "{}", bold.paint(span.metadata().name()))?;
                seen = true;

                let ext = span.extensions();
                if let Some(fields) = &ext.get::<FormattedFields<N>>() {
                    if !fields.is_empty() {
                        write!(writer, "{}{}{}", bold.paint("{"), fields, bold.paint("}"))?;
                    }
                }
                write!(writer, "{}", dimmed.paint(":"))?;
            }

            if seen {
                writer.write_char(' ')?;
            }
        };

        if self.display_target {
            write!(
                writer,
                "{}{} ",
                dimmed.paint(meta.target()),
                dimmed.paint(":")
            )?;
        }
        // ... display_filename / display_line_number，默认关
        ctx.format_fields(writer.by_ref(), event)?;
        writeln!(writer)

use tracing::{info, info_span, warn};

fn work() {
  let req = info_span!("request", id = 7, path = "/search");
  let _r = req.enter();
  let q = info_span!("query", q = "tokio");
  let _q = q.enter();
  info!(hits = 3, "search done");
  warn!(error = %"timeout", "index refresh failed");
}

fn main() {
  let which = std::env::args().nth(1).unwrap_or_default();
  let b = tracing_subscriber::fmt().with_ansi(false);
  match which.as_str() {
    "full" => b.init(),
    "compact" => b.compact().init(),
    "pretty" => b.pretty().init(),
    "json" => b.json().init(),
    _ => panic!("full|compact|pretty|json"),
  }
  work();
}

2026-10-23T18:15:11.343430Z  INFO request{id=7 path="/search"}:query{q="tokio"}: formats: search done hits=3
2026-10-23T18:15:11.343542Z  WARN request{id=7 path="/search"}:query{q="tokio"}: formats: index refresh failed error=timeout

2026-10-23T18:15:11.346436Z  INFO request:query: formats: search done hits=3 id=7 path="/search" q="tokio"
2026-10-23T18:15:11.346450Z  WARN request:query: formats: index refresh failed error=timeout id=7 path="/search" q="tokio"

  2026-10-23T18:15:11.349214Z  INFO formats: search done, hits: 3
    at src/bin/formats.rs:8
    in formats::query with q: "tokio"
    in formats::request with id: 7, path: "/search"

  2026-10-23T18:15:11.349231Z  WARN formats: index refresh failed, error: timeout
    at src/bin/formats.rs:9
    in formats::query with q: "tokio"
    in formats::request with id: 7, path: "/search"

{"timestamp":"2026-10-23T18:15:11.351848Z","level":"INFO","fields":{"message":"search done","hits":3},"target":"formats","span":{"q":"tokio","name":"query"},"spans":[{"id":7,"path":"/search","name":"request"},{"q":"tokio","name":"query"}]}
{"timestamp":"2026-10-23T18:15:11.351867Z","level":"WARN","fields":{"message":"index refresh failed","error":"timeout"},"target":"formats","span":{"q":"tokio","name":"query"},"spans":[{"id":7,"path":"/search","name":"request"},{"q":"tokio","name":"query"}]}

struct Timings {
    idle: u64,
    busy: u64,
    last: Instant,
    entered_count: u64,
}

            // on_enter
            if let Some(timings) = extensions.get_mut::<Timings>() {
                if timings.entered_count == 0 {
                    let now = Instant::now();
                    timings.idle += (now - timings.last).as_nanos() as u64;
                    timings.last = now;
                }
                timings.entered_count += 1;
            }

            // on_exit
            if let Some(timings) = extensions.get_mut::<Timings>() {
                timings.entered_count -= 1;
                if timings.entered_count == 0 {
                    let now = Instant::now();
                    timings.busy += (now - timings.last).as_nanos() as u64;
                    timings.last = now;
                }
            }

use std::thread::sleep;
use std::time::Duration;

use tracing::info_span;
use tracing_subscriber::fmt::format::FmtSpan;

fn ms(n: u64) -> Duration {
  Duration::from_millis(n)
}

fn main() {
  tracing_subscriber::fmt()
    .with_ansi(false)
    .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
    .init();

  let span = info_span!("job", id = 1);
  sleep(ms(30)); // 创建后、第一次进入前：idle
  span.in_scope(|| sleep(ms(20))); // busy
  sleep(ms(40)); // 两次进入之间：idle
  span.in_scope(|| sleep(ms(10))); // busy
  drop(span); // 最后一次退出到关闭：几乎为 0 的 idle
}

2026-10-23T18:15:57.832382Z  INFO job{id=1}: span_events: new
2026-10-23T18:15:57.960686Z  INFO job{id=1}: span_events: close time.busy=45.0ms time.idle=83.3ms

2026-10-23T18:15:58.138168Z  INFO job{id=1}: span_events: new
2026-10-23T18:15:58.264281Z  INFO job{id=1}: span_events: close time.busy=36.7ms time.idle=89.4ms

2026-10-23T18:15:58.451977Z  INFO job{id=1}: span_events: new
2026-10-23T18:15:58.586818Z  INFO job{id=1}: span_events: close time.busy=45.0ms time.idle=89.8ms

use std::thread::sleep;
use std::time::Duration;

use tracing::info_span;
use tracing_subscriber::fmt::format::FmtSpan;

fn main() {
  tracing_subscriber::fmt()
    .with_ansi(false)
    .with_span_events(FmtSpan::CLOSE)
    .init();

  let span = info_span!("outer");
  let _a = span.enter();
  sleep(Duration::from_millis(50));
  {
    let _b = span.enter(); // 同一个 span 再进一次
    sleep(Duration::from_millis(50));
  }
  sleep(Duration::from_millis(50));
  drop(_a);
  drop(span);
}

2026-10-23T18:15:58.132072Z  INFO outer: reenter: close time.busy=167ms time.idle=999ns
2026-10-23T18:15:58.448521Z  INFO outer: reenter: close time.busy=181ms time.idle=1.88µs
2026-10-23T18:15:58.767473Z  INFO outer: reenter: close time.busy=178ms time.idle=1.88µs

pub trait MakeWriter<'a> {
    type Writer: io::Write;

    fn make_writer(&'a self) -> Self::Writer;

    fn make_writer_for(&'a self, meta: &Metadata<'_>) -> Self::Writer {
        let _ = meta;
        self.make_writer()
    }
}

stdout only:
 INFO test_writer_stderr: where do I go?
stderr only:

use std::io::{self, Write};

use tracing::{Level, debug, error, info, warn};
use tracing_subscriber::fmt::writer::MakeWriterExt;

// 一个给每次 write 加前缀的 writer，用来看出一行进了哪个出口
struct Tagged(&'static str);

impl Write for Tagged {
  fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
    let mut out = io::stdout().lock();
    out.write_all(self.0.as_bytes())?;
    out.write_all(buf)?;
    Ok(buf.len())
  }
  fn flush(&mut self) -> io::Result<()> {
    Ok(())
  }
}

fn main() {
  let alerts = (|| Tagged("[alerts] ")).with_max_level(Level::WARN);
  let console = || Tagged("[console] ");
  let audit = || Tagged("[audit] ");

  // WARN 及以上进 alerts，其余进 console；每一行另外抄一份给 audit
  let make_writer = alerts.or_else(console).and(audit);

  tracing_subscriber::fmt()
    .with_ansi(false)
    .without_time()
    .with_max_level(Level::DEBUG)
    .with_writer(make_writer)
    .init();

  debug!("cache miss");
  info!("request done");
  warn!("slow query");
  error!("db down");
}

[console] DEBUG writers: cache miss
[audit] DEBUG writers: cache miss
[console]  INFO writers: request done
[audit]  INFO writers: request done
[alerts]  WARN writers: slow query
[audit]  WARN writers: slow query
[alerts] ERROR writers: db down
[audit] ERROR writers: db down

pub struct SubscriberBuilder<
    N = format::DefaultFields,
    E = format::Format<format::Full>,
    F = LevelFilter,
    W = fn() -> io::Stdout,
> {
    filter: F,
    inner: Layer<Registry, N, E, W>,
}

    pub fn finish(self) -> Subscriber<N, E, F, W> {
        let subscriber = self.inner.with_subscriber(Registry::default());
        Subscriber {
            inner: self.filter.with_subscriber(subscriber),
        }
    }

    fn try_init(self) -> Result<(), TryInitError> {
        dispatcher::set_global_default(self.into()).map_err(TryInitError::new)?;

        // Since we are setting the global default subscriber, we can
        // opportunistically go ahead and set its global max level hint as
        // the max level for the `log` crate as well. This should make
        // skipping `log` diagnostics much faster.
        #[cfg(feature = "tracing-log")]
        tracing_log::LogTracer::builder()
            // Note that we must call this *after* setting the global default
            // subscriber, so that we get its max level hint.
            .with_max_level(tracing_core::LevelFilter::current().as_log())
            .init()
            .map_err(TryInitError::new)?;

        Ok(())
    }

fn main() {
  println!("log::max_level before = {}", log::max_level());
  tracing_subscriber::fmt().with_max_level(tracing::Level::DEBUG).init();
  println!("log::max_level after  = {}", log::max_level());

  let err = tracing_subscriber::fmt().try_init().unwrap_err();
  println!("try_init: {err}");
  println!("try_init: {err:?}");

  tracing_subscriber::fmt().init();
}

log::max_level before = OFF
log::max_level after  = DEBUG
try_init: a global default trace dispatcher has already been set
try_init: SetGlobalDefaultError("a global default trace dispatcher has already been set")

thread 'main' (1403719) panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.23/src/fmt/mod.rs:520:14:
Unable to install global subscriber: SetGlobalDefaultError("a global default trace dispatcher has already been set")
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

thread 'main' (1434268) panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.23/src/util.rs:94:14:
failed to set global default subscriber: SetGlobalDefaultError("a global default trace dispatcher has already been set")
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

 INFO reentrant: from inside Debug
 INFO reentrant: outer event value=Noisy