tracing+tracing_subscriber日志库
tarcing流程
Subscriber和Layer不是串行的两步，而是组合在一起的一个整体
graph TD
A["tracing::info!()"] --> B[Event 数据]
C["tracing::span!()"] --> D[Span 数据]
B --> E[全局 Subscriber<br/>（Registry + Layers 组合体）]
D --> E
E --> F[内部 Layer 依次处理<br/>过滤、格式化、采样...]
F --> G["输出到 stdout / 文件 / JSON / OTLP 等"]
tarcing日志级别
输出
Event
- debug!：级别为 DEBUG，用于调试目的的信息，比如变量值、中间状态、流程分支等。
- trace!：级别为 TRACE，是最细粒度的超详细跟踪，通常记录非常底层的步骤（如进入/离开函数、循环体内部状态、协议交互细节），平时一般不会开启。
ERROR > WARN > INFO > DEBUG > TRACE
tarcing用法
默认启用
info级别输出， 可以通过RUST_LOG=debug cargo run调整输出级别
use tracing::{info, error, debug, warn, trace};
fn main() {
// 需要创建Subscriber和Layer(默认的)
tracing_subscriber::fmt::init();
debug!("debug message");
trace!("trace message");
info!("server started");
error!("something wrong");
warn!("something wrong");
}
2026-08-05T13:20:32.362457Z INFO test_tracing: server started
2026-08-05T13:20:32.362576Z ERROR test_tracing: something wrong
2026-08-05T13:20:32.362588Z WARN test_tracing: something wrong
创建Subscriber和Layer
tracing_subscriber::fmt::init()
这是一个便捷函数，内部等价于默认配置的
tracing_subscriber::fmt().init()
- 使用默认配置初始化
subscriber - 读取
RUST_LOG环境变量作为日志级别过滤器（如果启用了env-filter这个feature） - 无法自定义任何格式、输出目标、过滤规则等
- 代码最简洁，适合快速原型或简单场景
// 内部等价于
tracing_subscriber::fmt()
// 设置日志输出级别
.with_env_filter(
// 从环境变量RUST_LOG读取日志级别，没有默认info级别
tracing_subscriber::EnvFilter::from_default_env()
)
.init();
tracing_subscriber::fmt().init()
tracing_subscriber::fmt()构建了SubscriberBuilder
tracing_subscriber::fmt()
// 设置日志输出级别
.with_env_filter(
// 永远不会读 RUST_LOG, 默认info级别
tracing_subscriber::EnvFilter::default()
)
.init();
tracing_subscriber::fmt()
# 创建SubscriberBuilder对象
SubscriberBuilder::default()
# SubscriberBuilder下可以设置不同的参数
SubscriberBuilder {
filter,
fmt,
writer,
timer,
ansi,
event_format,
span_events,
}
# 默认设置
inner
|
+-- writer = stdout # 输出
|
+-- timer = SystemTime # 时间格式utc
|
+-- formatter = Full # 输出格式
|
+-- ansi = true # 开启颜色
|
+-- fields formatter # 输出格式
# 变为subscriber
## builder <= SubscriberBuilder
let subscriber = builder.finish();
# 设置为全局subscriber
tracing::subscriber::set_global_default(
subscriber
);
fmt()
|
|
SubscriberBuilder::default()
|
|
配置 Builder
|
|
.init()
|
|
finish()
|
|
fmt::Subscriber
|
|
set_global_default()
|
|
tracing::info!()
|
|
Event进入Subscriber
SubscriberBuilder配置
SubscriberBuilder
│
├── 过滤(Filter)
│
├── 输出目标(Writer)
│
├── 格式化(Format)
│
├── 时间(Timer)
│
├── Span行为
│
├── Event行为
│
└── 其他显示选项
日志过滤级别-Filter
| 方法 | 类型参数变化 | 效果 |
|---|---|---|
.with_max_level(level) |
F = LevelFilter |
全局最大级别，如 Level::DEBUG 只输出 DEBUG 及以上 |
.with_env_filter(filter) |
F = EnvFilter |
复杂过滤规则，支持模块/span/field 分级，可读取 RUST_LOG |
with_max_level
use tracing::{info, error, debug, warn, trace, Level};
fn main() {
tracing_subscriber::fmt()
// 简单固定级别
.with_max_level(tracing::Level::TRACE)
.init();
trace!("trace message");
debug!("debug message");
info!("server started");
error!("something wrong");
warn!("something wrong");
}
2026-08-05T15:17:15.909030Z TRACE test_tracing: trace message
2026-08-05T15:17:15.909136Z DEBUG test_tracing: debug message
2026-08-05T15:17:15.909143Z INFO test_tracing: server started
2026-08-05T15:17:15.909147Z ERROR test_tracing: something wrong
2026-08-05T15:17:15.909151Z WARN test_tracing: something wrong
with_env_filter
复杂动态规则
use tracing::{info, error, debug, warn, trace};
fn main() {
tracing_subscriber::fmt()
.with_env_filter("trace")
.init();
trace!("trace message");
debug!("debug message");
info!("server started");
error!("something wrong");
warn!("something wrong");
}
2026-08-05T15:18:09.674623Z TRACE test_tracing: trace message
2026-08-05T15:18:09.674803Z DEBUG test_tracing: debug message
2026-08-05T15:18:09.674816Z INFO test_tracing: server started
2026-08-05T15:18:09.674826Z ERROR test_tracing: something wrong
2026-08-05T15:18:09.674876Z WARN test_tracing: something wrong
案例
use tracing::{info, error, debug, warn, trace};
use tracing_subscriber::filter::EnvFilter;
fn main() {
// 从环境变量读取RUST_LOG，没有的话默认设置debug级别输出
let filter = EnvFilter::try_from_default_env()
.unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
trace!("trace message");
debug!("debug message");
info!("server started");
error!("something wrong");
warn!("something wrong");
}
2026-08-05T15:19:43.994212Z DEBUG test_tracing: debug message
2026-08-05T15:19:43.994314Z INFO test_tracing: server started
2026-08-05T15:19:43.994319Z ERROR test_tracing: something wrong
2026-08-05T15:19:43.994324Z WARN test_tracing: something wrong
格式化配置-Format
- compact需要在span数据中才会有效果
| 方法 | 默认值 | 效果 |
|---|---|---|
.with_target(true/false) |
true |
是否显示模块路径，如 my_crate::module |
.with_file(true/false) |
false |
是否显示源文件名 |
.with_line_number(true/false) |
false |
是否显示行号 |
.with_level(true/false) |
true |
是否显示日志级别（INFO/DEBUG 等） |
.with_thread_ids(true/false) |
false |
是否显示线程 ID（如 thread 12345） |
.with_thread_names(true/false) |
false |
是否显示线程名称 |
.with_ansi(true/false) |
true |
是否启用 ANSI 颜色码（终端彩色输出） |
.compact() |
— | 紧凑单行格式，减少空格 |
.pretty() |
— | 美化多行格式，适合人类阅读 |
.json() |
— | 输出 JSON 结构化格式，features需要开启json |
# 默认
2026-08-05T15:23:49.817095Z INFO test_tracing: server started
# with_target=false
2026-08-05T15:23:40.895205Z INFO server started
# with_file和with_line_number = true
2026-08-05T15:24:53.634480Z INFO test_tracing: src/main.rs:13: server started
# with_thread_ids和with_thread_names = true
2026-08-05T15:26:23.328404Z INFO main ThreadId(01) test_tracing: server started # true
# compact
2026-08-05T15:30:28.033478Z INFO test_tracing: server started
# pretty
2026-08-05T15:30:12.561473Z INFO test_tracing: server started
at src/main.rs:12
# json
{"timestamp":"2026-08-05T15:29:18.159783Z","level":"INFO","fields":{"message":"server started"},"target":"test_tracing"}
时间-Timer
| 方法 | 效果 |
|---|---|
.without_time() |
不输出时间戳 |
.with_timer(timer) |
自定义时间格式化器 |
tracing_subscriber设置时间
tracing-subscriber的features需要开启local-time
use tracing::{info, warn, error, debug};
use tracing_subscriber::{self, EnvFilter};
fn main() {
// 1.设置输出级别
let filter = EnvFilter::try_from_default_env()
.unwrap_or_else(|_| EnvFilter::new("debug"));
// 2. 初始化：这是最关键的一步，没有它日志不会输出
tracing_subscriber::fmt()
.with_env_filter(filter)
.with_timer(tracing_subscriber::fmt::time::LocalTime::rfc_3339()) // 设置时区
.init();
// 3. 使用宏记录日志
info!("info信息");
}
2026-08-05T23:35:39.716393+08:00 INFO test_tracing: info信息
chrono设置时间
cargo add chrono添加chrono
use std::fmt;
use tracing::info;
use tracing_subscriber::{
EnvFilter,
fmt::format::Writer,
fmt::time::FormatTime
};
// 需要实现自定义时间格式器
struct ChronoLocalTimer;
impl FormatTime for ChronoLocalTimer {
fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result {
write!(w, "{}", chrono::Local::now().format("%Y-%m-%d %H:%M:%S"))
}
}
fn main() {
// 设置输出级别
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter) // 绑定输出级别
.with_timer(ChronoLocalTimer)
.init();
info!("info信息");
}
2026-08-05 23:36:49 INFO test_tracing: info信息
输出-Writer
| 方法 | 效果 |
|---|---|
.with_writer(writer) |
自定义 MakeWriter，默认是 Stdout |
.with_writer(move || file) |
常见闭包写法，返回一个 io::Write |
写入文件
use tracing::info;
use tracing_subscriber::EnvFilter;
use std::fs::OpenOptions;
fn main() {
// 设置输出级别
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
// 创建文件
let file = OpenOptions::new()
.create(true).append(true).open("app.log")
.unwrap();
tracing_subscriber::fmt()
.with_env_filter(filter) // 绑定输出级别
.with_writer(move || file.try_clone().unwrap())
.with_ansi(false)
.init();
info!("info信息");
}
日志滚动
- 安装
cargo add tracing-appender
use tracing::info;
use tracing_subscriber::EnvFilter;
// 导入tracing_appender
use tracing_appender::rolling::{RollingFileAppender, Rotation};
fn main() {
// 设置输出级别
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
// RollingFileAppender
let file_appender = RollingFileAppender::new(Rotation::DAILY, "./logs", "app.log");
tracing_subscriber::fmt()
.with_env_filter(filter)
.with_writer(file_appender) // 绑定输出级别
.with_ansi(false)
.init();
info!("info信息");
}
Span 生命周期事件-FmtSpan
| 配置 | 效果 |
|---|---|
.with_span_events(FmtSpan::NONE) |
不输出 span 生命周期事件（默认） |
.with_span_events(FmtSpan::NEW) |
span 创建时输出 |
.with_span_events(FmtSpan::ENTER) |
span 进入时输出 |
.with_span_events(FmtSpan::EXIT) |
span 退出时输出 |
.with_span_events(FmtSpan::CLOSE) |
span 关闭时输出 |
.with_span_events(FmtSpan::ACTIVE) |
进入 + 退出 |
.with_span_events(FmtSpan::FULL) |
创建 + 进入 + 退出 + 关闭 |
其他配置
| 方法 | 默认值 | 说明 |
|---|---|---|
.with_current_span(true/false) |
false |
JSON 输出时，默认不附加当前 span 信息 |
.with_span_list(true/false) |
false |
JSON 输出时，默认不附加完整 span 链列表 |
.log_internal_errors(true/false) |
false |
默认不记录 subscriber 内部错误 |
.finish() |
- | 构建 Subscriber，但不注册 |
.init() |
- | 构建 + 设置为全局 Subscriber |
with_current_span
- 影响
span字段，记录当前span信息
{
"level":"INFO",
"message":"query user"
}
// 区别
{
"level":"INFO",
"message":"query user",
"span":{
"name":"request"
}
}
with_span_list
- 影响
spans字段，记录每个span的内容信息
{
"level":"INFO",
"message":"query user"
}
// 区别
{
"level":"INFO",
"message":"query user",
"spans":[
{
"name":"request",
"id":100
},
{
"name":"database"
}
]
}
案例
// 都开启
.with_current_span(true)
.with_span_list(true)
{
"level": "INFO",
"message": "query finish",
"span": {
"name": "database",
"sql": "select user",
"table": "users"
},
"spans": [
{
"name": "request",
"request_id": 100,
"user_id": 200
},
{
"name": "database",
"sql": "select user",
"table": "users"
}
]
}
tracing_subscriber::registry()
- registry + layer + layer + init
// 你写的：
tracing_subscriber::fmt().init();
// 内部实际做的：
let layer = tracing_subscriber::fmt::layer(); // 创建格式化 Layer
tracing_subscriber::registry() // 创建 Registry
.with(layer) // 挂载 Layer
.init(); // 设为全局默认值
Layer格式化输出层
use tracing_subscriber::fmt;
// 创建一个 fmt::Layer，默认配置
let layer = fmt::layer();
tracing_subscriber::fmt::layer
- tracing_subscriber::fmt::layer和SubscriberBuilder是不是一样？
let layer = tracing_subscriber::fmt::layer()
.with_target(true) // 显示模块路径
.with_file(true) // 显示文件名
.with_line_number(true) // 显示行号
.with_thread_names(true) // 显示线程名
.with_ansi(false) // 禁用颜色
.json(); // 输出 JSON 格式（而不是人类可读文本）
它和 fmt().init() 的关系
// 这两者是等价的
tracing_subscriber::fmt().init();
tracing_subscriber::registry()
.with(tracing_subscriber::fmt::layer())
.init();
默认配置
| 配置 | 默认值 |
|---|---|
| writer | stdout |
| timer | SystemTime（本地时间格式） |
| target | true |
| level | true |
| ansi | 自动判断终端 |
| thread id | false |
| thread name | false |
| span events | NONE |
| json | false |
| compact | false |
let stdout_layer = tracing_subscriber::fmt::layer();
FmtLayer {
writer: stdout,
timer: 默认时间,
formatter: 默认格式,
ansi: 自动判断,
target: true,
level: true,
}
| 配置 | SubscriberBuilder | fmt::Layer |
|---|---|---|
| 输出 writer | .with_writer() |
.with_writer() |
| ANSI颜色 | .with_ansi() |
.with_ansi() |
| 时间 | .with_timer() |
.with_timer() |
| target显示 | .with_target() |
.with_target() |
| level显示 | .with_level() |
.with_level() |
| 线程ID | .with_thread_ids() |
.with_thread_ids() |
| 线程名 | .with_thread_names() |
.with_thread_names() |
| Span生命周期 | .with_span_events() |
.with_span_events() |
| JSON格式 | .json() |
.json() |
配置多个layer
// 同时输出到 stdout 和文件
let stdout_layer = tracing_subscriber::fmt::layer();
let file_layer = tracing_subscriber::fmt::layer()
.with_writer(file_appender)
.with_ansi(false);
tracing_subscriber::registry()
.with(stdout_layer) // Layer 1: 控制台
.with(file_layer) // Layer 2: 文件
.init();
配置不同的过滤级别
let stdout_layer =
tracing_subscriber::fmt::layer()
.with_filter(LevelFilter::INFO); // info
...
let file_layer =
tracing_subscriber::fmt::layer()
.with_filter(LevelFilter::DEBUG); // debug
...
let otel_layer =
tracing_subscriber::fmt::layer()
.with_filter(LevelFilter::ERROR); // error
...
registry()
// 设置日志输出级别（这个过滤完才会到Layer的日志级别过滤）
.with(
EnvFilter::from_default_env()
)
.with(stdout_layer)
.with(file_layer)
.with(otel_layer)
Event
| 宏 | 级别 | 用途 |
|---|---|---|
trace!() |
TRACE |
最详细，如进入函数、变量值 |
debug!() |
DEBUG |
开发调试，如 SQL 语句、请求参数 |
info!() |
INFO |
正常流程，如服务启动、请求完成 |
warn!() |
WARN |
警告，如重试、降级、配置缺失 |
error!() |
ERROR |
错误，如 panic 捕获、业务异常 |
Event 的字段（Fields）格式
- 字段前缀规则
| 前缀 | 效果 | 示例 |
|---|---|---|
| 无前缀 | 调用 Value::record，默认行为 |
user_id = 42 |
? |
使用 std::fmt::Debug 输出 |
?error → error = CustomError { code: 500 } |
% |
使用 std::fmt::Display 输出 |
%id → id = "abc-123" |
info!(
target = "my_crate::auth", // 可选：覆盖默认 target
user_id = 42, // 整数字段
username = "alice", // 字符串字段
is_admin = true, // bool 字段
latency_ms = 12.5, // 浮点字段
?err, // 用 ? 前缀：使用 Debug 格式化
%request_id, // 用 % 前缀：使用 Display 格式化
"用户登录成功" // 消息（必须放在最后，是格式化字符串）
);
不同输出格式下的 Event 样子
<时间> <级别> <target>: <消息> <key=value> <key=value>
info!(user_id = 42, username = "alice", "用户登录");
# 默认
2024-08-06T00:15:30.123456Z INFO my_crate::auth: 用户登录 user_id=42 username=alice
# .compact()
2024-08-06T00:15:30.123Z INFO my_crate::auth: 用户登录 user_id=42 username=alice
# .pretty()
2024-08-06T00:15:30.123456Z INFO my_crate::auth
at src/auth.rs:25
用户登录
user_id=42
username=alice
# .json()
{
"timestamp": "2024-08-06T00:15:30.123456Z",
"level": "INFO",
"fields": {
"message": "用户登录",
"user_id": 42,
"username": "alice"
},
"target": "my_crate::auth"
}
Event
用法
在
use tracing::info;
info!(k=v,k=v,k=v..., message)
use std::fmt;
use tracing::info;
use tracing_subscriber::filter::EnvFilter;
#[derive(Debug)]
struct User {
name: String,
age: i32
}
struct User1 {
name: String,
age: i32
}
impl fmt::Display for User1 {
// 这个 trait 要求 `fmt` 使用与下面的函数完全一致的函数签名
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
// 仅将 self 的第一个元素写入到给定的输出流 `f`。返回 `fmt:Result`，此
// 结果表明操作成功或失败。注意 `write!` 的用法和 `println!` 很相似。
write!(f, "Display: {} {}", self.name, self.age)
}
}
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
// 类型显示
info!(
user_id = 42,
user_name = "alice",
success = true,
latency_ms = 12.5,
"aaa"
);
let user = User {
name: "Tom".to_string(),
age: 33
};
// ?显示debug
info!(user=?user, "aaa");
let user1: User1 = User1 {
name: "Bob".to_string(),
age: 22
};
// %显示display
info!(user1=%user1, "aaa");
}
2026-08-06T02:01:50.803728Z INFO test_tracing: aaa user_id=42 user_name="alice" success=true latency_ms=12.5
2026-08-06T02:01:50.803777Z INFO test_tracing: aaa user=User { name: "Tom", age: 33 }
2026-08-06T02:01:50.803792Z INFO test_tracing: aaa user1=Display: Bob 22
简写形式
如果变量名和字段名一致，可以简写
use std::fmt;
use tracing::info;
use tracing_subscriber::filter::EnvFilter;
#[derive(Debug)]
struct User {
name: String,
age: i32
}
struct User1 {
name: String,
age: i32
}
impl fmt::Display for User1 {
// 这个 trait 要求 `fmt` 使用与下面的函数完全一致的函数签名
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
// 仅将 self 的第一个元素写入到给定的输出流 `f`。返回 `fmt:Result`，此
// 结果表明操作成功或失败。注意 `write!` 的用法和 `println!` 很相似。
write!(f, "Display: {} {}", self.name, self.age)
}
}
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
let user_id = 42;
let user_name = "alice";
let success = true;
let latency_ms = 12.5;
// 类型显示(简写)
info!(
user_id,
user_name,
success,
latency_ms,
"aaa"
);
let user = User {
name: "Tom".to_string(),
age: 33
};
// ?显示debug(简写)
info!(?user, "aaa");
let user1: User1 = User1 {
name: "Bob".to_string(),
age: 22
};
// %显示display(简写)
info!(%user1, "aaa");
}
2026-08-06T02:03:20.513412Z INFO test_tracing: aaa user_id=42 user_name="alice" success=true latency_ms=12.5
2026-08-06T02:03:20.513461Z INFO test_tracing: aaa user=User { name: "Tom", age: 33 }
2026-08-06T02:03:20.513475Z INFO test_tracing: aaa user1=Display: Bob 22
特殊字段
use tracing::info;
use tracing_subscriber::filter::EnvFilter;
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
// key使用字符串
tracing::info!(
"http.method" = "GET",
"http.status_code" = 200,
"user.id" = 42,
"request completed"
);
}
2026-08-06T02:04:58.838273Z INFO test_tracing: request completed http.method="GET" http.status_code=200 user.id=42
错误信息
use tracing::info;
use tracing_subscriber::filter::EnvFilter;
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
let e = std::io::Error::new(std::io::ErrorKind::Other, "oh no!");
// debug错误显示
tracing::info!(
err_info=?e,
"err msg1"
);
// 简洁错误
tracing::info!(
err_info=%e,
"err msg2"
);
}
2026-08-06T02:08:18.257614Z INFO test_tracing: err msg1 err_info=Custom { kind: Other, error: "oh no!" }
2026-08-06T02:08:18.257646Z INFO test_tracing: err msg2 err_info=oh no!
输出Json对象
使用
serde_json::Value
use tracing::info;
use tracing_subscriber::filter::EnvFilter;
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
// .json()
.init();
let payload = serde_json::json!({
"user": {
"id": 42,
"name": "Alice"
},
"roles": ["admin", "user"]
});
tracing::info!(
payload = %payload,
"payload created"
);
}
2026-08-06T02:12:44.540848Z INFO test_tracing: payload created payload={"roles":["admin","user"],"user":{"id":42,"name":"Alice"}}
{"timestamp":"2026-08-06T02:12:38.609437Z","level":"INFO","fields":{"message":"payload created","payload":"{\"roles\":[\"admin\",\"user\"],\"user\":{\"id\":42,\"name\":\"Alice\"}}"},"target":"test_tracing"}
Span
在
use tracing::info_span;
info_span!(message, k=v, k=v, ...)
- 时间范围
用法
日志输出代理span信息
use tracing::info;
use tracing_subscriber::filter::EnvFilter;
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
// 创建span
let span = tracing::info_span!("handle_request", request_id = "req-123", abs=123);
// 进入span
let _enter = span.enter();
tracing::info!("start handling");
tracing::info!("query database");
tracing::info!("finish handling");
}
2026-08-06T02:22:05.576511Z INFO handle_request{request_id="req-123" abs=123}: test_tracing: start handling
2026-08-06T02:22:05.576548Z INFO handle_request{request_id="req-123" abs=123}: test_tracing: query database
2026-08-06T02:22:05.576566Z INFO handle_request{request_id="req-123" abs=123}: test_tracing: finish handling
{"timestamp":"2026-08-06T02:23:02.719962Z","level":"INFO","fields":{"message":"start handling"},"target":"test_tracing","span":{"abs":123,"request_id":"req-123","name":"handle_request"},"spans":[{"abs":123,"request_id":"req-123","name":"handle_request"}]}
{"timestamp":"2026-08-06T02:23:02.720053Z","level":"INFO","fields":{"message":"query database"},"target":"test_tracing","span":{"abs":123,"request_id":"req-123","name":"handle_request"},"spans":[{"abs":123,"request_id":"req-123","name":"handle_request"}]}
{"timestamp":"2026-08-06T02:23:02.720102Z","level":"INFO","fields":{"message":"finish handling"},"target":"test_tracing","span":{"abs":123,"request_id":"req-123","name":"handle_request"},"spans":[{"abs":123,"request_id":"req-123","name":"handle_request"}]}
函数级 span
使用
#[tracing::instrument]装饰函数
use tracing_subscriber::filter::EnvFilter;
#[tracing::instrument]
fn a(user_id:i32) {
tracing::info!("a fun");
}
#[tracing::instrument]
fn b(name: &str, age: i32) {
tracing::info!("b fun");
}
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
a(33);
b("tom", 22);
}
2026-08-06T02:28:01.319224Z INFO a{user_id=33}: test_tracing: a fun
2026-08-06T02:28:01.319287Z INFO b{name="tom" age=22}: test_tracing: b fun
{"timestamp":"2026-08-06T02:34:40.588592Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T02:34:40.588717Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"age":22,"name":"tom","name":"b"},"spans":[{"age":22,"name":"tom","name":"b"}]}
设置字段
可以设置
name和fields内容
use tracing_subscriber::filter::EnvFilter;
#[derive(Debug)]
struct User {
name: String,
age: i32
}
#[tracing::instrument(
name = "handle_aaa"
)]
fn a(user_id:i32) {
tracing::info!("a fun");
}
#[tracing::instrument(
name = "bbb",
fields(name=name, a=age)
)]
fn b(name: &str, age: i32) {
tracing::info!("b fun");
}
#[tracing::instrument(
name="ccccc",
fields(u=?user)
)]
fn c(user: User) {
tracing::info!("b fun");
}
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
// .json()
.init();
a(33);
b("tom", 22);
let u = User{
name: "ABC".to_string(),
age: 18
};
c(u);
}
2026-08-06T02:33:11.151490Z INFO handle_aaa{user_id=33}: test_tracing: a fun
2026-08-06T02:33:11.151548Z INFO bbb{age=22 name="tom" a=22}: test_tracing: b fun
2026-08-06T02:33:11.151586Z INFO ccccc{user=User { name: "ABC", age: 18 } u=User { name: "ABC", age: 18 }}: test_tracing: b fun
{"timestamp":"2026-08-06T02:33:49.475561Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"handle_aaa"},"spans":[{"user_id":33,"name":"handle_aaa"}]}
{"timestamp":"2026-08-06T02:33:49.475683Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"a":22,"age":22,"name":"tom","name":"bbb"},"spans":[{"a":22,"age":22,"name":"tom","name":"bbb"}]}
{"timestamp":"2026-08-06T02:33:49.475768Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"u":"User { name: \"ABC\", age: 18 }","user":"User { name: \"ABC\", age: 18 }","name":"ccccc"},"spans":[{"u":"User { name: \"ABC\", age: 18 }","user":"User { name: \"ABC\", age: 18 }","name":"ccccc"}]}
跳过字段
use tracing_subscriber::filter::EnvFilter;
#[derive(Debug)]
struct User {
name: String,
age: i32
}
#[tracing::instrument(
name = "handle_aaa"
)]
fn a(user_id:i32) {
tracing::info!("a fun");
}
#[tracing::instrument(
name = "bbb",
skip(age) // 跳过age
)]
fn b(name: &str, age: i32) {
tracing::info!("b fun");
}
#[tracing::instrument(
name="ccccc",
fields(un=user.name), // 设置显示user.name
skip(user) // 跳过user显示
)]
fn c(user: User) {
tracing::info!("b fun");
}
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
// .json()
.init();
a(33);
b("tom", 22);
let u = User{
name: "ABC".to_string(),
age: 18
};
c(u);
}
2026-08-06T02:38:46.791306Z INFO handle_aaa{user_id=33}: test_tracing: a fun
2026-08-06T02:38:46.791373Z INFO bbb{name="tom"}: test_tracing: b fun
2026-08-06T02:38:46.791407Z INFO ccccc{un="ABC"}: test_tracing: b fun
{"timestamp":"2026-08-06T02:38:58.662685Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"handle_aaa"},"spans":[{"user_id":33,"name":"handle_aaa"}]}
{"timestamp":"2026-08-06T02:38:58.662786Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"name":"tom","name":"bbb"},"spans":[{"name":"tom","name":"bbb"}]}
{"timestamp":"2026-08-06T02:38:58.662847Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"un":"ABC","name":"ccccc"},"spans":[{"un":"ABC","name":"ccccc"}]}
异步使用
使用tracing::instrument
use tracing_subscriber::filter::EnvFilter;
#[derive(Debug)]
struct User {
name: String,
age: i32
}
#[tracing::instrument(
name = "handle_aaa"
)]
async fn a(user_id:i32) {
tracing::info!("a fun");
}
#[tracing::instrument(
name = "bbb",
skip(age) // 跳过age
)]
async fn b(name: &str, age: i32) {
tracing::info!("b fun");
}
#[tracing::instrument(
name="ccccc",
fields(un=user.name), // 设置显示user.name
skip(user) // 跳过user显示
)]
async fn c(user: User) {
tracing::info!("b fun");
}
#[tokio::main]
async fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
// .json()
.init();
a(33).await;
b("tom", 22).await;
let u = User{
name: "ABC".to_string(),
age: 18
};
c(u).await;
}
2026-08-06T02:50:51.703696Z INFO handle_aaa{user_id=33}: test_tracing: a fun
2026-08-06T02:50:51.703757Z INFO bbb{name="tom"}: test_tracing: b fun
2026-08-06T02:50:51.703793Z INFO ccccc{un="ABC"}: test_tracing: b fun
{"timestamp":"2026-08-06T02:51:37.680037Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"handle_aaa"},"spans":[{"user_id":33,"name":"handle_aaa"}]}
{"timestamp":"2026-08-06T02:51:37.680159Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"name":"tom","name":"bbb"},"spans":[{"name":"tom","name":"bbb"}]}
{"timestamp":"2026-08-06T02:51:37.680223Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"un":"ABC","name":"ccccc"},"spans":[{"un":"ABC","name":"ccccc"}]}
手动设置
- 不会自动抓取函数参数，需要自己手动设置到
info_span中
use tracing::Instrument;
use tracing_subscriber::filter::EnvFilter;
#[derive(Debug)]
struct User {
name: String,
age: i32
}
async fn a(user_id:i32) {
tracing::info!("a fun");
}
async fn b(name: &str, age: i32) {
tracing::info!("b fun");
}
async fn c(user: User) {
tracing::info!("b fun");
}
#[tokio::main]
async fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
// .json()
.init();
let span_a = tracing::info_span!("aaa", test=222);
a(33).instrument(span_a).await;
let span_b = tracing::info_span!("bbb", ak=47);
b("tom", 22).instrument(span_b).await;
let u = User{
name: "ABC".to_string(),
age: 18
};
let span_c = tracing::info_span!("ccc", name="222");
c(u).instrument(span_c).await;
}
2026-08-06T02:55:51.894599Z INFO aaa{test=222}: test_tracing: a fun
2026-08-06T02:55:51.894675Z INFO bbb{ak=47}: test_tracing: b fun
2026-08-06T02:55:51.894712Z INFO ccc{name="222"}: test_tracing: b fun
{"timestamp":"2026-08-06T02:56:29.462345Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"test":222,"name":"aaa"},"spans":[{"test":222,"name":"aaa"}]}
{"timestamp":"2026-08-06T02:56:29.462436Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"ak":47,"name":"bbb"},"spans":[{"ak":47,"name":"bbb"}]}
{"timestamp":"2026-08-06T02:56:29.462498Z","level":"INFO","fields":{"message":"b fun"},"target":"test_tracing","span":{"name":"222","name":"ccc"},"spans":[{"name":"222","name":"ccc"}]}
span嵌套
use tracing_subscriber::filter::EnvFilter;
#[tracing::instrument]
fn a(user_id: i32) {
tracing::info!("a fun");
a1(1)
}
#[tracing::instrument]
fn a1(user_id: i32) {
tracing::info!("a1 fun");
a2(2);
}
#[tracing::instrument]
fn a2(user_id: i32) {
tracing::info!("a2 fun");
a3(3);
}
#[tracing::instrument]
fn a3(user_id: i32) {
tracing::info!("a3 fun");
}
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.init();
a(33);
}
2026-08-06T03:00:18.999276Z INFO a{user_id=33}: test_tracing: a fun
2026-08-06T03:00:18.999327Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: a1 fun
2026-08-06T03:00:18.999362Z INFO a{user_id=33}:a1{user_id=1}:a2{user_id=2}: test_tracing: a2 fun
2026-08-06T03:00:18.999396Z INFO a{user_id=33}:a1{user_id=1}:a2{user_id=2}:a3{user_id=3}: test_tracing: a3 fun
{"timestamp":"2026-08-06T03:01:05.710359Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:01:05.710460Z","level":"INFO","fields":{"message":"a1 fun"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"}]}
{"timestamp":"2026-08-06T03:01:05.710521Z","level":"INFO","fields":{"message":"a2 fun"},"target":"test_tracing","span":{"user_id":2,"name":"a2"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"},{"user_id":2,"name":"a2"}]}
{"timestamp":"2026-08-06T03:01:05.710585Z","level":"INFO","fields":{"message":"a3 fun"},"target":"test_tracing","span":{"user_id":3,"name":"a3"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"},{"user_id":2,"name":"a2"},{"user_id":3,"name":"a3"}]}
Span生命周期
FmtSpan::NEW
use tracing_subscriber::filter::EnvFilter;
use tracing_subscriber::fmt::format::FmtSpan;
#[tracing::instrument]
fn a(user_id: i32) {
tracing::info!("a fun");
a1(1)
}
#[tracing::instrument]
fn a1(user_id: i32) {
tracing::info!("a1 fun");
}
fn main() {
let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
tracing_subscriber::fmt()
.with_env_filter(filter)
.with_span_events(FmtSpan::NEW)
// .json()
.init();
a(33);
}
2026-08-06T03:09:37.552051Z INFO a{user_id=33}: test_tracing: new
2026-08-06T03:09:37.552098Z INFO a{user_id=33}: test_tracing: a fun
2026-08-06T03:09:37.552128Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: new
2026-08-06T03:09:37.552150Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: a1 fun
{"timestamp":"2026-08-06T03:09:48.849292Z","level":"INFO","fields":{"message":"new"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[]}
{"timestamp":"2026-08-06T03:09:48.849371Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:09:48.849432Z","level":"INFO","fields":{"message":"new"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:09:48.849475Z","level":"INFO","fields":{"message":"a1 fun"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"}]}
FmtSpan::ENTER
2026-08-06T03:10:25.065199Z INFO a{user_id=33}: test_tracing: enter
2026-08-06T03:10:25.065237Z INFO a{user_id=33}: test_tracing: a fun
2026-08-06T03:10:25.065271Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: enter
2026-08-06T03:10:25.065293Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: a1 fun
{"timestamp":"2026-08-06T03:10:51.254375Z","level":"INFO","fields":{"message":"enter"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:10:51.254445Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:10:51.254501Z","level":"INFO","fields":{"message":"enter"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"}]}
{"timestamp":"2026-08-06T03:10:51.254546Z","level":"INFO","fields":{"message":"a1 fun"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"}]}
FmtSpan::EXIT
2026-08-06T03:11:19.317235Z INFO a{user_id=33}: test_tracing: a fun
2026-08-06T03:11:19.317293Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: a1 fun
2026-08-06T03:11:19.317319Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: exit
2026-08-06T03:11:19.317351Z INFO a{user_id=33}: test_tracing: exit
{"timestamp":"2026-08-06T03:11:39.022204Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:11:39.022304Z","level":"INFO","fields":{"message":"a1 fun"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"}]}
{"timestamp":"2026-08-06T03:11:39.022355Z","level":"INFO","fields":{"message":"exit"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:11:39.022403Z","level":"INFO","fields":{"message":"exit"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[]}
FmtSpan::CLOSE
- time.busy: 表示任务进入span执行的时间
- time.idle: 表示span存在，当前这个任务没有在这个span运行的时间（被挂起了）
- 如果在同步代码中time.idle会很低
- 在异步中，time.idle往往比time.busy大
2026-08-06T03:12:08.817597Z INFO a{user_id=33}: test_tracing: a fun
2026-08-06T03:12:08.817650Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: a1 fun
2026-08-06T03:12:08.817686Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: close time.busy=33.3µs time.idle=6.05µs
2026-08-06T03:12:08.817731Z INFO a{user_id=33}: test_tracing: close time.busy=140µs time.idle=14.2µs
{"timestamp":"2026-08-06T03:12:19.395366Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:12:19.395462Z","level":"INFO","fields":{"message":"a1 fun"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"}]}
{"timestamp":"2026-08-06T03:12:19.395514Z","level":"INFO","fields":{"message":"close","time.busy":"50.5µs","time.idle":"6.48µs"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:12:19.395575Z","level":"INFO","fields":{"message":"close","time.busy":"211µs","time.idle":"14.3µs"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[]}
FmtSpan::FULL
2026-08-06T03:12:58.567771Z INFO a{user_id=33}: test_tracing: new
2026-08-06T03:12:58.567813Z INFO a{user_id=33}: test_tracing: enter
2026-08-06T03:12:58.567834Z INFO a{user_id=33}: test_tracing: a fun
2026-08-06T03:12:58.567863Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: new
2026-08-06T03:12:58.567885Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: enter
2026-08-06T03:12:58.567904Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: a1 fun
2026-08-06T03:12:58.567926Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: exit
2026-08-06T03:12:58.567947Z INFO a{user_id=33}:a1{user_id=1}: test_tracing: close time.busy=41.0µs time.idle=43.8µs
2026-08-06T03:12:58.567987Z INFO a{user_id=33}: test_tracing: exit
2026-08-06T03:12:58.568004Z INFO a{user_id=33}: test_tracing: close time.busy=174µs time.idle=67.2µs
{"timestamp":"2026-08-06T03:13:07.706702Z","level":"INFO","fields":{"message":"new"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[]}
{"timestamp":"2026-08-06T03:13:07.706780Z","level":"INFO","fields":{"message":"enter"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:13:07.706826Z","level":"INFO","fields":{"message":"a fun"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:13:07.706880Z","level":"INFO","fields":{"message":"new"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:13:07.706920Z","level":"INFO","fields":{"message":"enter"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"}]}
{"timestamp":"2026-08-06T03:13:07.706962Z","level":"INFO","fields":{"message":"a1 fun"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"},{"user_id":1,"name":"a1"}]}
{"timestamp":"2026-08-06T03:13:07.707008Z","level":"INFO","fields":{"message":"exit"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:13:07.707046Z","level":"INFO","fields":{"message":"close","time.busy":"87.4µs","time.idle":"79.1µs"},"target":"test_tracing","span":{"user_id":1,"name":"a1"},"spans":[{"user_id":33,"name":"a"}]}
{"timestamp":"2026-08-06T03:13:07.707103Z","level":"INFO","fields":{"message":"exit"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[]}
{"timestamp":"2026-08-06T03:13:07.707133Z","level":"INFO","fields":{"message":"close","time.busy":"323µs","time.idle":"112µs"},"target":"test_tracing","span":{"user_id":33,"name":"a"},"spans":[]}
在axum中使用日志记录
use axum::{Router, extract::Path, routing::get};
use std::time::Duration;
use std::{fmt, fs::OpenOptions};
use tower_http::trace::TraceLayer;
use tracing::{debug, info, instrument};
use tracing_subscriber::{
EnvFilter, Layer, fmt as s_fmt, layer::SubscriberExt, util::SubscriberInitExt,
};
// 需要实现自定义时间格式器
struct ChronoLocalTimer;
impl s_fmt::time::FormatTime for ChronoLocalTimer {
fn format_time(&self, w: &mut s_fmt::format::Writer<'_>) -> fmt::Result {
write!(
w,
"{}",
chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f")
)
}
}
#[tokio::main]
async fn main() {
init_tracing();
let app = Router::new()
.route("/", get(root))
.route("/users/{id}", get(get_user))
// TraceLayer 会为每个 HTTP 请求创建一个 request span
.layer(TraceLayer::new_for_http());
let listener = tokio::net::TcpListener::bind("0.0.0.0:3000").await.unwrap();
info!("listening on http://127.0.0.1:3000");
axum::serve(listener, app).await.unwrap();
}
// 创建日志记录build
fn init_tracing() {
let env_filter = EnvFilter::try_from_default_env()
.unwrap_or_else(|_| EnvFilter::new("debug,tower_http=debug"));
let file = OpenOptions::new()
.create(true)
.append(true)
.open("app.log")
.unwrap();
tracing_subscriber::registry()
.with(env_filter)
.with(
s_fmt::layer()
.with_target(false)
.with_file(true)
.with_line_number(true)
.with_timer(ChronoLocalTimer)
)
.with(
s_fmt::layer()
.compact()
.with_file(true)
.with_line_number(true)
.with_timer(ChronoLocalTimer)
.with_ansi(false)
.with_writer(move || file.try_clone().unwrap())
.with_filter(EnvFilter::new("info"))
)
.init();
}
async fn root() -> &'static str {
info!("root handler called");
"hello axum tracing"
}
#[instrument]
async fn get_user(Path(id): Path<u64>) -> String {
info!(user_id = id, "start getting user");
let user = query_user_from_db(id).await;
info!(
user_id = id,
username = %user,
"user loaded"
);
format!("user: {user}")
}
#[instrument]
async fn query_user_from_db(user_id: u64) -> String {
debug!("query started");
tokio::time::sleep(Duration::from_millis(100)).await;
debug!("query finished");
format!("user-{user_id}")
}
终端
2026-08-06 12:52:38.427 INFO src/main.rs:35: listening on http://127.0.0.1:3000
2026-08-06 12:52:44.408 DEBUG request{method=GET uri=/ version=HTTP/1.1}: /home/test/.cargo/registry/src/mirrors.tuna.tsinghua.edu.cn-4dc01642fd091eda/tower-http-0.7.0/src/trace/on_request.rs:80: started processing request
2026-08-06 12:52:44.408 INFO request{method=GET uri=/ version=HTTP/1.1}: src/main.rs:73: root handler called
2026-08-06 12:52:44.408 DEBUG request{method=GET uri=/ version=HTTP/1.1}: /home/test/.cargo/registry/src/mirrors.tuna.tsinghua.edu.cn-4dc01642fd091eda/tower-http-0.7.0/src/trace/on_response.rs:114: finished processing request latency=0 ms status=200
2026-08-06 12:52:44.409 DEBUG request{method=GET uri=/ version=HTTP/1.1}: /home/test/.cargo/registry/src/mirrors.tuna.tsinghua.edu.cn-4dc01642fd091eda/tower-http-0.7.0/src/trace/on_eos.rs:103: end of stream stream_duration=0 ms
2026-08-06 12:53:12.293 DEBUG request{method=GET uri=/users/12 version=HTTP/1.1}: /home/test/.cargo/registry/src/mirrors.tuna.tsinghua.edu.cn-4dc01642fd091eda/tower-http-0.7.0/src/trace/on_request.rs:80: started processing request
2026-08-06 12:53:12.293 INFO request{method=GET uri=/users/12 version=HTTP/1.1}:get_user{id=12}: src/main.rs:79: start getting user user_id=12
2026-08-06 12:53:12.294 DEBUG request{method=GET uri=/users/12 version=HTTP/1.1}:get_user{id=12}:query_user_from_db{user_id=12}: src/main.rs:94: query started
2026-08-06 12:53:12.395 DEBUG request{method=GET uri=/users/12 version=HTTP/1.1}:get_user{id=12}:query_user_from_db{user_id=12}: src/main.rs:98: query finished
2026-08-06 12:53:12.395 INFO request{method=GET uri=/users/12 version=HTTP/1.1}:get_user{id=12}: src/main.rs:83: user loaded user_id=12 username=user-12
2026-08-06 12:53:12.395 DEBUG request{method=GET uri=/users/12 version=HTTP/1.1}: /home/test/.cargo/registry/src/mirrors.tuna.tsinghua.edu.cn-4dc01642fd091eda/tower-http-0.7.0/src/trace/on_response.rs:114: finished processing request latency=101 ms status=200
2026-08-06 12:53:12.395 DEBUG request{method=GET uri=/users/12 version=HTTP/1.1}: /home/test/.cargo/registry/src/mirrors.tuna.tsinghua.edu.cn-4dc01642fd091eda/tower-http-0.7.0/src/trace/on_eos.rs:103: end of stream stream_duration=0 ms
app.log
- 第一个span输出带了颜色，所以第二个复用缓存span的时候输出了颜色字符
2026-08-06 12:52:38.427 INFO test_tracing: src/main.rs:35: listening on http://127.0.0.1:3000
2026-08-06 12:52:44.408 INFO test_tracing: src/main.rs:73: root handler called
2026-08-06 12:53:12.294 INFO get_user: test_tracing: src/main.rs:79: start getting user user_id=12 [3mid[0m[2m=[0m12
2026-08-06 12:53:12.395 INFO get_user: test_tracing: src/main.rs:83: user loaded user_id=12 username=user-12 [3mid[0m[2m=[0m12
修复缓存一下Layer
- file_fields格式化span和event的结构化数据
use axum::{Router, extract::Path, routing::get};
use std::time::Duration;
use std::{fmt, fs::OpenOptions};
use tower_http::trace::TraceLayer;
use tracing::{debug, info, instrument};
use tracing_subscriber::{
EnvFilter, Layer, fmt as s_fmt, layer::SubscriberExt, util::SubscriberInitExt,
field::MakeExt // 导入
};
// 需要实现自定义时间格式器
struct ChronoLocalTimer;
impl s_fmt::time::FormatTime for ChronoLocalTimer {
fn format_time(&self, w: &mut s_fmt::format::Writer<'_>) -> fmt::Result {
write!(
w,
"{}",
chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f")
)
}
}
#[tokio::main]
async fn main() {
init_tracing();
let app = Router::new()
.route("/", get(root))
.route("/users/{id}", get(get_user))
// TraceLayer 会为每个 HTTP 请求创建一个 request span
.layer(TraceLayer::new_for_http());
let listener = tokio::net::TcpListener::bind("0.0.0.0:3000").await.unwrap();
info!("listening on http://127.0.0.1:3000");
axum::serve(listener, app).await.unwrap();
}
fn init_tracing() {
let env_filter = EnvFilter::try_from_default_env()
.unwrap_or_else(|_| EnvFilter::new("debug,tower_http=debug"));
let file = OpenOptions::new()
.create(true)
.append(true)
.open("app.log")
.unwrap();
// 设置结构化输出内容
// file_fields 只影响 event 和 span 的结构化字段内容的格式化，不影响整条日志的其他元信息布局。
let file_fields = s_fmt::format::debug_fn(|writer, field, value| {
write!(writer, "{}={:?}", field, value)
})
.delimited(" ");
tracing_subscriber::registry()
.with(env_filter)
.with(
s_fmt::layer()
.with_target(false)
.with_file(true)
.with_line_number(true)
.with_timer(ChronoLocalTimer)
)
.with(
s_fmt::layer()
.fmt_fields(file_fields) // 配置结构化输出
.compact()
.with_file(true)
.with_line_number(true)
.with_timer(ChronoLocalTimer)
.with_ansi(false)
.with_writer(move || file.try_clone().unwrap())
.with_filter(EnvFilter::new("info"))
)
.init();
}
async fn root() -> &'static str {
info!("root handler called");
"hello axum tracing"
}
#[instrument]
async fn get_user(Path(id): Path<u64>) -> String {
info!(user_id = id, "start getting user");
let user = query_user_from_db(id).await;
info!(
user_id = id,
username = %user,
"user loaded"
);
format!("user: {user}")
}
#[instrument]
async fn query_user_from_db(user_id: u64) -> String {
debug!("query started");
tokio::time::sleep(Duration::from_millis(100)).await;
debug!("query finished");
format!("user-{user_id}")
}
浙公网安备 33010602011771号