Rust in Everything
基于 tracing 0.1.44

和 log 互通

主线位置：事件主线的两条旁路。一条从 tracing 出去：info! 展开出的代码在 Event::dispatch 旁边多一段 __tracing_log!，把事件再发给 log 的 logger。一条从 log 进来：log::info! 交给 LogTracer，它构造一个 tracing Event，直接交给当前 dispatcher 的 event，接上事件主线的最后一段。

flowchart TB
  tm["tracing::info!"] --> gates{"四道门"}
  gates -->|过了| ed["Event::dispatch"]
  gates --> tl["__tracing_log!"]
  ed --> tl
  tl --> hb{"log-always 或从未设过"}
  hb -->|否| stop1["不发 log 记录"]
  hb -->|是| lg["log::logger().log"]
  lm["log::info!"] --> lg
  lg -->|logger 是 LogTracer| lt["LogTracer::log"]
  lg -->|别的 logger| other["例如打印到终端"]
  lt --> dr["dispatch_record"]
  dr --> de["Dispatch::event"]
  ed --> de
  de --> sub["tracing subscriber"]

log 是 Rust 里更早、更普及的日志门面，tracing 要和它共存：用 tracing 的库，可能被只装了 log logger 的程序使用；用 tracing 的程序，依赖里大量的库还在用 log。两个方向各有一个开关：tracing 自己的 log / log-always feature（tracing → log），tracing-log crate 的 LogTracer（log → tracing）。本页分别看它们什么时候起作用，再把各种组合实际跑一遍，回答「两边都开会不会重复、会不会丢」。宏开了 log feature 后多展开出哪些代码见 宏展开，两个 feature 在 Cargo.toml 里的定义见 源码地图。

tracing → log：log feature

__tracing_log! 在不开 log feature 时是一个展开成空的宏（L3259），开了以后是：

#[cfg(feature = "log")]
#[doc(hidden)]
#[macro_export]
macro_rules! __tracing_log {
    ($level:expr, $callsite:expr, $value_set:expr) => {
        $crate::if_log_enabled! { $level, {
            use $crate::log;
            let level = $crate::level_to_log!($level);
            if level <= log::max_level() {
                let meta = $callsite.metadata();
                let log_meta = log::Metadata::builder()
                    .level(level)
                    .target(meta.target())
                    .build();
                let logger = log::logger();
                if logger.enabled(&log_meta) {
                    $crate::__macro_support::__tracing_log(meta, logger, log_meta, $value_set)
                }
            }
        }}
    };
}

一条 tracing 事件要变成 log 记录，要连过四关：if_log_enabled!（下面讲）、log::max_level()（log 的运行时最大级别，没人调过 log::set_max_level 时是 Off）、logger.enabled(..)、最后 __tracing_log 函数用调用点的文件、行号、模块路径和 target 拼一条 log::Record。消息由 LogValueSet 格式化：第一个字段是 message 时只写值，其余字段写成 name=value。

event! 在两个分支里都调它：四道门都过了的分支，和没过的 else 分支。没过门也要调，是因为「tracing 这边没人要」恰恰是需要转给 log 的情况，比如根本没装 tracing subscriber。

什么叫「没有 subscriber」：has_been_set

if_log_enabled! 有三个版本，按 feature 选。只开 log 时是 L3304：

#[cfg(all(feature = "log", not(feature = "log-always")))]
#[doc(hidden)]
#[macro_export]
macro_rules! if_log_enabled {
    // ...
    ($lvl:expr, $if_log:block else $else_block:block) => {
        if $crate::level_to_log!($lvl) <= $crate::log::STATIC_MAX_LEVEL {
            if !$crate::dispatcher::has_been_set() {
                $if_log
            } else {
                $else_block
            }
        } else {
            $else_block
        }
    };
}

开了 log-always 的版本（L3327）去掉了 has_been_set 那一层，只比 log 的编译期最大级别；两个都不开的版本（L3289）直接走 else。

关键是 has_been_set，它读的是 tracing-core 的全局 EXISTS：

/// Returns true if a `tracing` dispatcher has ever been set.
///
/// This may be used to completely elide trace points if tracing is not in use
/// at all or has yet to be initialized.
#[doc(hidden)]
#[inline(always)]
pub fn has_been_set() -> bool {
    EXISTS.load(Ordering::Relaxed)
}

注意文档里的「ever」。EXISTS 只有两处写，都是写 true：set_global_default 成功时，和 State::set_default 每次被调用时（Dispatch：全局与线程局部 讲过这个只增不减的标志）。没有任何地方把它改回 false。所以 log feature 的转发条件准确地说是：这个进程里从来没有设过任何 dispatcher，不论全局的还是任何一个线程的线程默认。下面几种情况都不转发：

  • 装了全局 subscriber，即使它把这条事件过滤掉了；
  • 别的线程上 set_default 过，当前线程上其实没有 subscriber；
  • set_default 的守卫早就 drop 了。

后两种情况下，事件既不进 tracing（当前线程没有 subscriber），也不进 log（has_been_set 已经是 true）。先预测一下：

❗IMPORTANT
动脑筋：after the guard is dropped 去哪了？

先装一个把记录打印成 log| ... 的 log logger，发一条 tracing 事件；然后在同一个线程上 set_default 一个 fmt subscriber，立刻把守卫 drop 掉；再发一条：

set_log_logger();
tracing::info!("before set_default");
drop(tracing::subscriber::set_default(fmt()));
tracing::info!("after the guard is dropped");

这时线程上没有任何 tracing subscriber，全局也没设。tracing 不开 feature、开 log、开 log-always 三种情况下，两条事件各从哪里出来？（set_log_logger 和 fmt 的定义见下面的实验程序，这段就是它的 after-scoped 模式。）

这个设计服务的是库：一个库开 log feature，它的用户如果只用 log，能看到库里的 tracing 事件；用户一旦用了 tracing，库就不再额外发一份 log 记录，避免和 LogTracer 一起造成重复。crate 文档（lib.rs 第 647 行起）的说法是：「This is intended primarily for use in libraries which wish to emit diagnostics that can be consumed by applications using tracing or log, without paying the additional overhead of emitting both forms of diagnostics when tracing is in use」。

📝NOTE
冷知识：最早的 log feature 是「总是转发」

tracing 0.1.9 之前，开了 log feature 的宏无条件地同时发 tracing 事件和 log 记录。#346 的说明写了问题：「When tracing-log is being used to convert log records into tracing events, this results in duplicate events being observed: those emitted by the event macros directly, and those generated from the log records they emit by tracing-log」。

解决办法用的正是上一节的标志：「In tracing-core 0.1.6, we added an internal API for checking if a tracing subscriber has ever been set」，有了它，宏可以在 tracing 已被使用时不发 log 记录。原来的行为没有删，保留成一个新的 log-always feature，留给「log records might be output to the console while tracing is used to generate metrics or for performance profiling」这种两边分开收集的程序。这个 PR 修的是 #204，首次发布于 tracing 0.1.9，CHANGELOG：「The log feature will now only cause tracing spans and events to emit log records when a Subscriber is not in use」。

span 也会发 log 记录

Span 上的操作也有 if_log_enabled!（Span 与 Entered 里 do_enter、do_exit、record_all、Drop 后面那几段），走 Span::log，用两个专门的 target：

时机target级别消息
创建（门通过，make_with）有字段时是调用点的 target，否则 tracing::spanspan 的级别++ name; 字段
创建（门没通过，宏里调 record_all）同上span 的级别name; 字段
record同上span 的级别name; 字段
进入 / 退出tracing::span::activeTRACE-> name; / <- name;
关闭（Span drop）tracing::spanTRACE-- name;

span 有 Inner 时，消息末尾再加 span=<id>。这些记录靠的是 Span 里的 meta：开了 log feature 时，被过滤掉的 span 由 new_disabled(meta) 构造，meta 还在，inner 为 None，于是没有 subscriber 时 span 的进出照样能写进 log。

log → tracing：LogTracer

反方向由 tracing-log 0.2.0 负责。LogTracer 实现 log::Log，只有一个字段 ignore_crates: Box<[String]>。它的 enabled 三步：

    fn enabled(&self, metadata: &log::Metadata<'_>) -> bool {
        // First, check the log record against the current max level enabled by
        // the current `tracing` subscriber.
        if metadata.level().as_trace() > tracing_core::LevelFilter::current() {
            // If the log record's level is above that, disable it.
            return false;
        }

        // Okay, it wasn't disabled by the max level — do we have any specific
        // modules to ignore?
        if !self.ignore_crates.is_empty() {
            // ...
        }

        try_cache_interest(metadata, || {
            // Finally, check if the current `tracing` dispatcher cares about this.
            dispatcher::get_default(|dispatch| dispatch.enabled(&metadata.as_trace()))
        })
    }

依次是 tracing 的全局 LevelFilter::current()（第二道门，见 级别过滤的几道门）、忽略的 crate 前缀、当前 dispatcher 的 enabled。try_cache_interest 只有开了 tracing-log 的 interest-cache feature 才缓存，默认 feature（log-tracer、std）里没有它，tracing-subscriber 也没开，所以就是直接调闭包。log 再判断一次 enabled，通过后交给 dispatch_record：

pub(crate) fn dispatch_record(record: &log::Record<'_>) {
    dispatcher::get_default(|dispatch| {
        let filter_meta = record.as_trace();
        if !dispatch.enabled(&filter_meta) {
            return;
        }

        let (_, keys, meta) = loglevel_to_cs(record.level());

        // ...

        dispatch.event(&Event::new(
            meta,
            &meta.fields().value_set(&[
                (&keys.message, Some(record.args() as &dyn field::Value)),
                (&keys.target, Some(&record.target())),
                (&keys.module, module),
                (&keys.file, file),
                (&keys.line, line),
            ]),
        ));
    });
}

tracing 的事件需要一个 &'static Metadata，而 log 记录的 target、文件、行号都是运行时的值。tracing-log 的办法是每个级别一个固定的假调用点（log_cs! 生成五个），元数据的名字是 "log event"、target 是 "log"、没有文件行号，字段固定为 message、log.target、log.module_path、log.file、log.line，真实的值放进这几个字段。subscriber 想还原原来的 target 和行号，要用 NormalizeEvent::normalized_metadata：它先看事件的调用点是不是这五个之一（is_log），是的话从字段里读出值，造一个非 'static 的 Metadata。fmt 格式化事件时就是这样做的，所以下面实验里经 LogTracer 进来的那行显示的 target 是 interop，不是 log。

dispatch_record 直接调 Dispatch::event，没有经过 tracing 的宏，所以不会再走一遍 __tracing_log!：即使两个方向都开着，一条记录最多绕一圈，不会死循环。

谁装上它：try_init

很少有人手动调 LogTracer::init()。tracing-subscriber 的默认 feature 里有 tracing-log，SubscriberInitExt::try_init：

    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(())
    }

fmt().init() / fmt().try_init() 经由 SubscriberBuilder::try_init 走到这里。两件事有先后：先设全局 subscriber，再装 LogTracer，并把 log::set_max_level 设成 tracing 当前的最大级别，log 那边比它详细的记录在 log 的宏里就被挡掉。Builder::init 用的是 log::set_boxed_logger，log 的 logger 也只能设一次。

这个顺序带来一个容易误判的结果：如果程序在这之前已经装了别的 log logger，try_init 返回 Err(SetLoggerError)，但 tracing 的全局 subscriber 已经装上了，只是 LogTracer 没装上。下面实验的 logger-then-try-init 就是这种情况。

实验：各种组合到底输出什么

一个程序，七种模式，分别放进三个只差 tracing feature 的 crate 里编译：不开、开 log、开 log-always。每种模式都调一次 log::info! 和一次 tracing::info!，部分模式再建一个带字段的 span、进入、打一条事件。log 那边的 logger 是一个把每条记录打印成 log| ... 的最小实现，tracing 那边是 fmt，两者都写 stdout。

tracing = "=0.1.44"            # 第二个 crate 加 features = ["log"]，第三个加 features = ["log-always"]
tracing-subscriber = "=0.3.23"
tracing-log = "=0.2.0"
log = "0.4"

use log::{Log, Metadata, Record};

// 一个最小的 log 实现：每条记录打印一行，前缀 "log|"
struct Stdout;

impl Log for Stdout {
  fn enabled(&self, _: &Metadata) -> bool {
    true
  }
  fn log(&self, r: &Record) {
    println!("log| {:<5} {}: {}", r.level(), r.target(), r.args());
  }
  fn flush(&self) {}
}

static STDOUT: Stdout = Stdout;

fn set_log_logger() {
  log::set_logger(&STDOUT).unwrap();
  log::set_max_level(log::LevelFilter::Trace);
}

fn fmt() -> impl tracing::Subscriber + Send + Sync {
  tracing_subscriber::fmt().with_ansi(false).without_time().finish()
}

fn emit() {
  log::info!("from log");
  tracing::info!("from tracing");
}

fn emit_span() {
  let span = tracing::info_span!("req", id = 1);
  let _g = span.enter();
  tracing::info!("in span");
}

fn main() {
  let mode = std::env::args().nth(1).unwrap();
  println!("== {mode}");
  match mode.as_str() {
    // 什么都不装
    "none" => emit(),
    // 只装 log 的 logger，不装 tracing subscriber
    "log-only" => {
      set_log_logger();
      emit();
      emit_span();
    }
    // 只装 tracing subscriber（set_global_default，不装 LogTracer）
    "fmt-global" => {
      tracing::subscriber::set_global_default(fmt()).unwrap();
      emit();
    }
    // fmt().init()：tracing subscriber + LogTracer
    "fmt-init" => {
      tracing_subscriber::fmt().with_ansi(false).without_time().init();
      emit();
      emit_span();
    }
    // 只装 LogTracer，没有 tracing subscriber
    "logtracer-only" => {
      tracing_log::LogTracer::init().unwrap();
      emit();
    }
    // 先装 log 的 logger，再 fmt().try_init()
    "logger-then-try-init" => {
      set_log_logger();
      let r = tracing_subscriber::fmt().with_ansi(false).without_time().try_init();
      println!("try_init: {r:?}");
      emit();
    }
    // 先装 log 的 logger；某个线程短暂 set_default 过一次
    "after-scoped" => {
      set_log_logger();
      tracing::info!("before set_default");
      drop(tracing::subscriber::set_default(fmt()));
      tracing::info!("after the guard is dropped");
    }
    _ => unreachable!("未知模式"),
  }
}

M2 Max、rustc 1.99.0、--release（log 解析到 0.4.34），三个 crate 各跑全部模式，整组跑 3 次输出相同。after-scoped 是上面动脑筋的那段，它的输出留到「动脑筋答案」，下面每段到它之前为止。

不开 log feature：

== none
== log-only
log| INFO  interop: from log
== fmt-global
 INFO interop: from tracing
== fmt-init
 INFO interop: from log
 INFO interop: from tracing
 INFO req{id=1}: interop: in span
== logtracer-only
== logger-then-try-init
try_init: Err(SetLoggerError(()))
log| INFO  interop: from log
 INFO interop: from tracing

开 log feature：

== none
== log-only
log| INFO  interop: from log
log| INFO  interop: from tracing
log| INFO  interop: req; id=1
log| TRACE tracing::span::active: -> req;
log| INFO  interop: in span
log| TRACE tracing::span::active: <- req;
log| TRACE tracing::span: -- req;
== fmt-global
 INFO interop: from tracing
== fmt-init
 INFO interop: from log
 INFO interop: from tracing
 INFO req{id=1}: interop: in span
== logtracer-only
== logger-then-try-init
try_init: Err(SetLoggerError(()))
log| INFO  interop: from log
 INFO interop: from tracing

开 log-always feature：

== none
== log-only
log| INFO  interop: from log
log| INFO  interop: from tracing
log| INFO  interop: req; id=1
log| TRACE tracing::span::active: -> req;
log| INFO  interop: in span
log| TRACE tracing::span::active: <- req;
log| TRACE tracing::span: -- req;
== fmt-global
 INFO interop: from tracing
== fmt-init
 INFO interop: from log
 INFO interop: from tracing
 INFO interop: from tracing
 INFO interop: ++ req; id=1 span=1
 INFO req{id=1}: interop: in span
 INFO req{id=1}: interop: in span
== logtracer-only
== logger-then-try-init
try_init: Err(SetLoggerError(()))
log| INFO  interop: from log
 INFO interop: from tracing
log| INFO  interop: from tracing

把「from log」和「from tracing」各出现几次整理成表（fmt 那一行算 tracing 输出，log| 那一行算 log 输出）：

模式装了什么不开loglog-always
none什么都没装都丢都丢都丢
log-only只有 log loggertracing 事件丢都 1 次都 1 次
fmt-global只有 tracing subscriberlog 记录丢log 记录丢log 记录丢
fmt-initsubscriber + LogTracer都 1 次都 1 次tracing 事件 2 次
logtracer-only只有 LogTracer都丢都丢都丢
logger-then-try-initlog logger + subscriber各走各的，1 次各走各的，1 次tracing 事件两边各 1 次

逐个解释：

  • 重复只有一种：log-always 加 fmt().init()。事件先由 Event::dispatch 交给 fmt 打一次；__tracing_log! 不看 has_been_set，再发一条 log 记录，log 的 logger 是 LogTracer，它又变成一个 tracing 事件交给 fmt，第二次。span 也一样：++ req; id=1 span=1 是 span 创建时的 log 记录被 LogTracer 转回来的，in span 两次。-> req; 这些 TRACE 记录没有出现：Span::log 拿 span 自己的级别（INFO）去比 log::max_level()，能过；但记录本身是 TRACE，到 LogTracer::enabled 第一步就被挡掉，TRACE 比 tracing 当前的最大级别 INFO 详细。crate 文档说「libraries generally should not enable the "log-always" feature」，给的理由是「as doing so will prevent applications from being able to opt out of the log records」。重复是同一件事的另一面：feature 会在整个依赖图里合并，一个库开了它，所有用 fmt().init() 的程序里的事件都会打两遍（见 每条日志打印两次）。
  • 只开 log、装了 LogTracer，不重复：has_been_set() 为真，__tracing_log! 什么也不做。
  • log-only：开了 log feature，没有 tracing subscriber，tracing 事件和 span 的进出都变成 log 记录。被过滤掉的 span 走的是宏里的 record_all，所以消息是 req; id=1 而没有 ++，也没有 span= 后缀（它没有 Inner）。
  • fmt-global：只设全局 subscriber、不装 LogTracer，log 的 logger 还是默认的空实现，log::info! 全丢。三个 crate 都一样，tracing 的 feature 管不到这个方向。
  • logtracer-only：只有 LogTracer 没有 subscriber。进程里从没创建过 Dispatch，全局 MAX_LEVEL 还是初值 OFF，LogTracer::enabled 第一步就返回 false，log 记录到不了 tracing。开 log 时 tracing 事件没过门，else 分支里转给 log（has_been_set 为假，LogTracer::init 默认把 log 的最大级别设成 Trace），到了 LogTracer 同样被第一步挡掉。
  • logger-then-try-init：try_init 返回错误，但 from tracing 照样由 fmt 打印出来了，全局 subscriber 已经装上；from log 走的是先装的那个 logger。log-always 时 tracing 事件两边各出现一次，这正是这个 feature 设计的用法：log 和 tracing 各自收集一份。
📝NOTE
没有蠢问题

问： 既然 log-always 加 LogTracer 会重复，LogTracer 为什么不认出「这条 log 记录是 tracing 自己发的」，跳过它？

答： 到了 LogTracer::log 手里，只剩一条 log::Record：级别、target、消息、文件行号，和任何别的库用 log::info! 发出来的记录没有区别。tracing 发出的记录没有带任何标记，LogTracer 只能靠 target 前缀判断。它提供的手段正是这个：LogTracer::builder().ignore_crate("某个库")，把开了 log-always 的那个库的记录整个忽略掉。这需要在程序里自己调 LogTracer::builder()...init()，并且不能再用会自动装 LogTracer 的 fmt().init()（或者关掉 tracing-subscriber 的 tracing-log feature）。

动脑筋答案

三个 crate 分别运行 interop after-scoped，各跑 3 次输出相同。不开 log：

== after-scoped

开 log：

== after-scoped
log| INFO  interop: before set_default

开 log-always：

== after-scoped
log| INFO  interop: before set_default
log| INFO  interop: after the guard is dropped
  • 不开 log：tracing 事件从不进 log，两条都没有 tracing subscriber 接，都丢。
  • 开 log：第一条发出时 EXISTS 还是 false，转给 log。set_default 把 EXISTS 置成 true，守卫 drop 只把线程默认换回 None，EXISTS 不变。第二条：线程上没有 subscriber，tracing 那边丢；has_been_set() 为真，log 那边也不发。两边都没有。
  • 开 log-always：不看 has_been_set，两条都转给 log。

实际程序里这种情况来自测试：一个测试用 set_default 装过 subscriber，同一进程里后面的测试、或者别的线程，即使只装了 log 的 logger，也看不到开 log feature 的库发出的 tracing 事件了。

小结

  • tracing → log 靠 tracing 的 log feature：宏里的 __tracing_log! 在 Event::dispatch 旁边再发一条 log 记录，span 的创建、进出、关闭也会发。
  • 只开 log 时，条件是 !has_been_set()：进程里从没设过任何 dispatcher（全局或任何线程的 set_default），标志只增不减。log-always 去掉这个条件，总是转发（tracing 0.1.9，#346）。
  • log → tracing 靠 tracing-log 的 LogTracer：每个级别一个固定的假调用点，真实的 target、文件、行号放进 log.* 字段，NormalizeEvent 再还原；它直接调 Dispatch::event，不经过宏。
  • fmt().init() / try_init() 默认（tracing-log feature）先设全局 subscriber 再装 LogTracer，并把 log 的最大级别设成 tracing 当前的；log logger 已存在时返回错误，但 subscriber 已经装上了。
  • 实测：只开 log 加 LogTracer 不重复；log-always 加 LogTracer 每条 tracing 事件输出两次；只装一边时另一边的日志丢失。

💬 关联讨论

发起讨论
加载中...