日志行

主线位置：事件主线全程。调用点上的字段写法决定 ValueSet 里装什么；生效的 EnvFilter 决定它能不能过门；fmt 的 Full 格式把它拼成一行写进 stdout；之后由 docker 收走、轮转。

flowchart TB
  site["warn!(error = %e, ...)"] --> filt["EnvFilter：hyper_util=warn,info"]
  filt --> fmtl["fmt：Full 格式"]
  fmtl --> stdout["stdout，带 ANSI"]
  stdout --> docker["docker json-file"]
  docker --> rotate["10m × 5 轮转"]

本页的站点源码链接都指向本站仓库的提交 89a61b1。生产里生效的 subscriber 是 dioxus-logger 装的，不是 main.rs 里那段，过滤器是 hyper_util=warn,info，见 subscriber 的初始化。

133 处调用

在 89a61b1 的 crates/ 下数 tracing::<级别>!( 形式的调用（本站没有 use tracing::info 这样导入后裸写宏的地方），共 133 处：

按写法分：

有一处既有字段又在消息里拼值，同时算在第一行和第三行。字段里 error = %e 出现 42 次，是最常见的一种；用 ? 按 Debug 记的有 7 次。42 处写了 target:，其中 41 处是 "pay_audit"，1 处是 "rate_limit"。消息里拼值的 13 处全在 pay_audit 下。大多数消息以 search:、startup:、moderation: 这样的小写前缀开头。

字段写法本身在 宏展开 和 字段：Field、Value 与 Visit 里讲过。下面挑几处看它们在 fmt 输出里的样子。

数值字段：按值记录

main.rs 第 322 行，搜索索引定时刷新成功：

          Ok(r) => tracing::info!(
            upserts = r.upserts,
            deletes = r.deletes,
            elapsed_ms = r.elapsed_ms,
            "search: index refreshed"
          ),

upserts、deletes 是 usize，elapsed_ms 是 u64，都实现了 Value，subscriber 收到的是 record_u64，输出 upserts=17。同一件事在 reindex_incremental 里还有一条（search/src/engine.rs 第 518 行），用的是简写 upserts, deletes, elapsed_ms,，等于 upserts = upserts；它的 target 是 module_search::engine，所以按代码，一次成功的刷新在 info 下产生两行。main.rs 第 356 行的 info!(interval_secs, "...") 也是这种简写。

% 和 ?

%x 用 Display，?x 用 Debug。本站的错误几乎都用 %e；? 留给没有 Display 的类型，比如 moderation/src/hook.rs 第 58 行：

    tracing::info!(
      stages = ?pipeline.stage_names(),
      "moderation: shared pipeline (re)initialized"
    );

不加 % 或 ? 的字符串字段走 record_str，fmt 给它加引号（下一节）。course/src/server.rs 第 2064 行的支付回调审计日志两种都有：

  tracing::info!(
    target: "pay_audit",
    provider = "alipay",
    out_trade_no = %params.get("out_trade_no").map(|s| s.as_str()).unwrap_or(""),
    trade_status = %params.get("trade_status").map(|s| s.as_str()).unwrap_or(""),
    total_amount = %params.get("total_amount").map(|s| s.as_str()).unwrap_or(""),
    "notify received"
  );

provider="alipay" 带引号，out_trade_no=... 不带。字段的值可以是任意表达式，这里是从参数表里取值、取不到就用空串；只有在过了级别过滤之后才求值（级别过滤的几道门）。

自定义 target

target: "pay_audit" 把支付相关的日志从模块路径里摘出来，放到一个固定的名字下。main.rs 第 352 行的注释「回填/关单明细已在 target=pay_audit 日志留痕」说的就是它。EnvFilter 的指令按 target 前缀匹配，RUST_LOG=info,pay_audit=debug 这样的写法就能单独调它（EnvFilter）。fmt 输出里 target 那一段写成 pay_audit:。

消息里拼值的写法（course/src/server.rs 第 2346 行）：

      tracing::warn!(
        target: "pay_audit",
        "stripe {}: {} order {} refunded{}",
        kind,
        row.product_kind,
        row.out_trade_no,
        if revoked { " + purchase entitlement revoked" } else { "" }
      );

这几个值都进了 message 字段的文字里，不是单独的字段：对 fmt 输出没有区别，但 subscriber 拿不到 out_trade_no 这个字段名，JSON 格式下也只有一段 message。

一行生产日志

下面两行来自生产容器的日志（去掉了 ANSI 颜色码）：

2026-10-23T17:40:58.362282Z  WARN app: search: index refresh failed error=search: open_or_create failed: An IO error occurred: 'Permission denied (os error 13) at path "/app/data/search-index/.tmp4E0TCa"'
2026-10-23T17:50:59.951165Z  INFO app: search: index refreshed upserts=17 deletes=0 elapsed_ms=275

它们来自 main.rs 第 317 行起的刷新循环：

    tokio::spawn(async {
      let mut ticker = tokio::time::interval(std::time::Duration::from_secs(600));
      loop {
        ticker.tick().await;
        match module_search::engine::reindex_incremental().await {
          Ok(r) => tracing::info!(
            upserts = r.upserts,
            deletes = r.deletes,
            elapsed_ms = r.elapsed_ms,
            "search: index refreshed"
          ),
          Err(e) => tracing::warn!(error = %e, "search: index refresh failed"),
        }
      }
    });

tokio::time::interval 的第一次 tick 立即完成，所以进程一启动就刷新一次，之后每 600 秒一次（见 tokio 卷 Sleep 的一生 的 interval 一节）。

用生产里真正生效的 subscriber 复现这两行。依赖同 subscriber 的初始化（dioxus-logger、dioxus-cli-config 0.7.9，tracing-subscriber 0.3.23），M2 Max、rustc 1.99.0，--release，RUST_LOG=info，NO_COLOR=1：

struct IncrementalReport {
  upserts: usize,
  deletes: usize,
  elapsed_ms: u64,
}

fn main() {
  // 生产里真正生效的 subscriber
  dioxus_logger::initialize_default();

  let r = IncrementalReport { upserts: 17, deletes: 0, elapsed_ms: 275 };
  // crates/app/src/main.rs 第 322 行；那里是 app crate 的根模块，target 就是 "app"
  tracing::info!(
    target: "app",
    upserts = r.upserts,
    deletes = r.deletes,
    elapsed_ms = r.elapsed_ms,
    "search: index refreshed"
  );

  // reindex_incremental 的错误类型是 String，文字由 engine.rs 第 137 行的 format! 拼出
  let e: String = format!(
    "search: open_or_create failed: {}",
    "An IO error occurred: 'Permission denied (os error 13) at path \"/app/data/search-index/.tmp4E0TCa\"'"
  );
  tracing::warn!(target: "app", error = %e, "search: index refresh failed");
  // 对照：换成 ?e
  tracing::warn!(target: "app", error = ?e, "search: index refresh failed");
}

跑 3 次，除时间戳外相同。前两行：

2026-10-23T20:38:53.872889Z  INFO app: search: index refreshed upserts=17 deletes=0 elapsed_ms=275
2026-10-23T20:38:53.873510Z  WARN app: search: index refresh failed error=search: open_or_create failed: An IO error occurred: 'Permission denied (os error 13) at path "/app/data/search-index/.tmp4E0TCa"'

时间戳之后的字节和生产日志完全一样。每一段由 Format<Full>::format_event 的哪一步写出，fmt 的「Full 格式」用同一行日志逐段对照过；这里只补本站特有的几处：

error= 后面的文字是一层层 Display 拼起来的：

1. search: open_or_create failed: 来自 search/src/engine.rs 第 137 行的 format!("search: open_or_create failed: {}", e)，reindex_incremental 的错误类型就是 String。
2. An IO error occurred: '...' 是 tantivy 0.26.1 的 TantivyError::IoError 的 Display（#[error("An IO error occurred: '{0}'")]）。
3. Permission denied (os error 13) at path "/app/data/search-index/.tmp4E0TCa" 是 IO 错误本身。 at path "..." 的写法和 tempfile 3.27.0 的 PathError 的 Display（"{} at path {:?}"）一致，路径用 Debug 写，所以带双引号。tantivy 0.26.1 的 MmapDirectory 在 atomic_write 里用 tempfile::Builder::new().tempfile_in(parent_path) 在索引目录里建临时文件，.tmp4E0TCa 就是这样的临时文件名。

这一行把问题说全了：哪一步（open_or_create）、什么错误（Permission denied）、在哪个路径（/app/data/search-index/ 下建临时文件）。容器里的进程以 app 用户运行（Dockerfile 第 154 行的 USER app），而挂在 /app/data/search-index 的 docker 卷属于 root。2026-10-23（UTC）改成在镜像里预先建好挂载点、属主设为 app 用户之后，刷新恢复正常，就是第二行的 INFO。

RUST_LOG 与日志轮转

容器的环境变量在 docker-compose.yml 第 107 行：

      # tracing 输出级别
      RUST_LOG: ${RUST_LOG:-info}

${RUST_LOG:-info} 是 compose 的插值：插值用的 RUST_LOG（来自运行 compose 的 shell 环境或项目目录的 .env）未设置或为空时取 info，所以容器里不会出现空的 RUST_LOG。镜像的 ENV 里也有一份 RUST_LOG=info（Dockerfile 第 157 行起），compose 的 environment 覆盖它。生效的过滤器是 dioxus-logger 构造的 hyper_util=warn,info。调级别就是改这个变量，比如 info,pay_audit=debug，重建容器后生效；逗号后不能加空格（EnvFilter），dioxus-logger 用 from_env_lossy，坏的那一段会在 stderr 打一行 ignoring ... 后被丢掉，其余照用。

日志去哪由 compose 文件开头的锚点决定（第 25 行）：

# 日志轮转：docker 默认 json-file 不限大小，长期运行会占满磁盘。每个容器最多 5 × 10MB。
x-logging: &default-logging
  driver: json-file
  options:
    max-size: "10m"
    max-file: "5"

app 和 postgres 两个服务都写了 logging: *default-logging。fmt::Layer 默认写 stdout（make_writer: io::stdout），EnvFilter 的 ignoring 提示用 eprintln! 写 stderr；docker 把两者都收进 json-file，单个文件到 10MB 就换一个，最多保留 5 个。docker compose logs app 读的就是这些文件。tracing-subscriber 自己不做轮转；要在进程里写文件并轮转，用的是 tracing-appender，本站没有用它。

日志里的 ANSI 颜色码

上面那两行是去掉颜色码之后的样子。容器里的原始输出带着 ANSI 转义序列，因为 fmt::Layer 的默认值只看两件事：

        // only enable ANSI when the feature is enabled, and the NO_COLOR
        // environment variable is unset or empty.
        let ansi = cfg!(feature = "ansi") && env::var("NO_COLOR").map_or(true, |v| v.is_empty());

它不检查 stdout 是不是终端。本站开着 tracing-subscriber 的默认 feature（含 ansi），dioxus-logger 没有调用 with_ansi，compose 和 Dockerfile 里也没有 NO_COLOR，所以写进管道、写进 docker 的都是带颜色码的文本。去掉 NO_COLOR=1，把复现程序的第一行输出接到 cat -v：

^[[2m2026-10-23T20:38:54.097484Z^[[0m ^[[32m INFO^[[0m ^[[2mapp^[[0m^[[2m:^[[0m search: index refreshed ^[[3mupserts^[[0m^[[2m=^[[0m17 ^[[3mdeletes^[[0m^[[2m=^[[0m0 ^[[3melapsed_ms^[[0m^[[2m=^[[0m275

^[ 是 ESC。时间戳和 target 是暗色（2m），级别是绿色（32m），字段名是斜体（3m）。docker compose logs 在终端里看是彩色的；用 grep 按 upserts=17 这样的字面量搜，会因为 upserts 和 = 之间夹着 ^[[0m^[[2m 而搜不到。

动脑筋答案

复现程序的第三行，3 次相同（除时间戳）：

2026-10-23T20:38:53.873516Z  WARN app: search: index refresh failed error="search: open_or_create failed: An IO error occurred: 'Permission denied (os error 13) at path \"/app/data/search-index/.tmp4E0TCa\"'"

• ?e 用 String 的 Debug：整段加上双引号，里面的双引号转义成 \"；单引号不转义。
• %e 用 Display，原样写出，没有外层引号。日志里 error= 之后一直到行尾都是错误文字，读起来更顺，但字段值的边界要靠「它是最后一个字段」来判断；?e 的引号把边界标清楚了，代价是转义。

小结

• 133 处调用：warn! 最多（71），没有 trace!。100 处是「字段 + 固定消息」，错误统一写 error = %e（42 处）；13 处在消息里拼值，全在 target: "pay_audit" 下。
• 数值字段走 record_u64；不加 %、? 的字符串字段走 record_str，fmt 给它加引号；% 原样写，? 加引号并转义。
• 生产里那一行 WARN app: search: index refresh failed error=... 由 dioxus-logger 的 fmt 按 Full 格式拼出，target app 是 crate 根模块的模块路径；错误文字是本站、tantivy、tempfile 三层 Display 的拼接，它直接指出了索引目录权限的问题。
• RUST_LOG 由 compose 的 ${RUST_LOG:-info} 给出，生效的过滤器是 hyper_util=warn,info；日志走 docker json-file，每个容器最多 5 个 10MB 的文件。
• fmt 默认不检查 stdout 是否是终端，日志里带 ANSI 颜色码；NO_COLOR 非空可以关掉（tracing-subscriber 0.3.18 起）。