严格来说，tracing 并不是一个日志库，而是一个分布式跟踪的 SDK，用于采集监控数据的。
随着微服务的流行，现在一个产品有多个系统组成是非常常见的，这种情况下，一条用户请求可能会横跨几个甚至几十个服务。此时再用传统的日志方式去跟踪这条用户请求就变得较为困难，这就是分布式追踪在现代化监控系统中这么炽手可热的原因。
关于分布式追踪，在后面的监控章节进行详细介绍，大家只要知道：分布式追踪的核心就是在请求的开始生成一个 trace_id，然后将该 trace_id 一直往后透穿，请求经过的每个服务都会使用该 trace_id 记录相关信息，最终将整个请求形成一个完整的链路予以记录下来。
那么后面当要查询这次请求的相关信息时，只要使用 trace_id 就可以获取整个请求链路的所有信息了，非常简单好用。看到这里，相信大家也明白为什么这个库的名称叫 tracing 了吧？
至于为何把它归到日志库的范畴呢？因为 tracing 支持 log 门面库的 API，因此，它既可以作为分布式追踪的 SDK 来使用，也可以作为日志库来使用。
在分布式追踪中，trace_id 都是由 SDK 自动生成和往后透穿，对于用户的使用来说是完全透明的。如果你要手动用日志的方式来实现请求链路的追踪，那么就必须考虑 trace_id 的手动生成、透传，以及不同语言之间的协议规范等问题
异步编程中的挑战#
除了分布式追踪，在异步编程中使用传统的日志也是存在一些问题的，最大的挑战就在于异步任务的执行没有确定的顺序，那么输出的日志也将没有确定的顺序并混在一起，无法按照我们想要的逻辑顺序串联起来。
归根到底，在于日志只能针对某个时间点进行记录，缺乏上下文信息，而线程间的执行顺序又是不确定的，因此日志就有些无能为力。而 tracing 为了解决这个问题，引入了 span 的概念( 这个概念也来自于分布式追踪 )，一个 span 代表了一个时间段，拥有开始和结束时间，在此期间的所有类型数据、结构化数据、文本数据都可以记录其中。
大家发现了吗？ span 是可以拥有上下文信息的，这样就能帮我们把信息按照所需的逻辑性串联起来了。
tracing 库#
tracing 中最重要的三个概念是 Span、Event 和 Collector。
tracing 各个模块#
tracing: 作用域内的结构化日志记录和诊断系统。
tracing_appender: 记录事件和跨度的编写者。也就是将日志写入文件或者控制台。
tracing_error: 增强错误处理跟踪诊断信息的实用工具。
tracing_flame: 用于生成折叠堆栈跟踪以生成Inferno火焰图和火焰图表的跟踪订阅者。
tracing_log: 用于连接标准库日志系统和tracing系统的连接器。
tracing_subscriber: 用于实现和组成tracing订阅者的工具集合。
Span 跨度#
相比起日志只能记录在某个时间点发生的事件，span 最大的意义就在于它可以记录一个过程，也就是在某一段时间内发生的事件流。既然是记录时间段，那自然有开始和结束:
Cargo.toml
1
2
3
4
5
6
7
8
9
10
| [package]
name = "demo"
version = "0.1.0"
edition = "2021"
# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
[dependencies]
tracing = "0.1.37"
tracing-subscriber = { version = "0.3.16", features = ["env-filter", "json"] }
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
| use tracing::{info, span, Level};
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};
fn main() {
tracing_subscriber::registry().with(fmt::layer()).init();
let span = span!(Level::TRACE, "my_span");
{
// `enter` 返回一个 RAII ，当其被 drop 时，将自动结束该 span
let enter = span.enter();
// 这里开始进入 `my_span` 的上下文
// 下面执行一些任务，并记录一些信息到 `my_span` 中
// ...
info!("belog to my_span");
} // 这里 enter 将被 drop，`my_span` 也随之结束
info!("out of my_span")
}
|
output:
1
2
| 2024-07-17T09:33:44.277725Z INFO my_span: demo: belog to my_span
2024-07-17T09:33:44.278300Z INFO demo: out of my_span
|
Event 事件#
Event 代表了某个时间点发生的事件，这方面它跟日志类似，但是不同的是，Event 还可以产生在 span 的上下文中。
在 tracing 中，当 info!、error! 等日志宏被调用时，就会产生一个相应的事件 Event。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
| use tracing::{event, span, Level};
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};
fn main() {
tracing_subscriber::registry().with(fmt::layer()).init();
// 在 span 的上下文之外记录一次 event 事件
event!(Level::INFO, "something happened");
let span = span!(Level::INFO, "my_span");
let _guard = span.enter();
// 在 "my_span" 的上下文中记录一次 event
event!(Level::DEBUG, "something happened inside my_span");
// span 嵌套
let s2 = span!(Level::WARN, "span_2");
let _g2 = s2.enter();
// 在两个span 中记录一次event
event!(Level::INFO, "something went wrong in my_span and span_2");
drop(_g2); // 先drop里面的span 才行
// 强行结束span 的lifetime
event!(Level::WARN, "something happened out of my_span")
}
|
output
1
2
3
4
| 2024-07-17T09:42:39.162843Z INFO demo: something happened
2024-07-17T09:42:39.163364Z DEBUG my_span: demo: something happened inside my_span
2024-07-17T09:42:39.163768Z INFO my_span:span_2: demo: something went wrong in my_span and span_2
2024-07-17T09:42:39.163974Z WARN my_span: demo: something happened out of my_span
|
虽然 event 在哪里都可以使用，但是最好只在 span 的上下文中使用：用于代表一个时间点发生的事件，例如记录 HTTP 请求返回的状态码，从队列中获取一个对象，等等。
Collector 收集器#
当 Span 或 Event 发生时，它们会被实现了 Collect 特征的收集器所记录或聚合。这个过程是通过通知的方式实现的：当 Event 发生或者 Span 开始/结束时，会调用 Collect 特征的相应方法通知 Collector。
tracing-subscriber#
我们前面提到只有使用了 tracing-subscriber 后，日志才能输出到控制台中。
之前大家可能还不理解，现在应该明白了，它是一个 Collector，可以将记录的日志收集后，再输出到控制台中。
使用方法#
span! 宏 跨度！ 宏#
span! 宏可以用于创建一个 Span 结构体，然后通过调用结构体的 enter 方法来开始，再通过超出作用域时的 drop 来结束。
span! 宏可以用于创建一个 Span 结构体，然后通过调用结构体的 enter 方法来开始，再通过超出作用域时的 drop 来结束。
上面span已经给出例子
#[instrument]#
如果想要将某个函数的整个函数体都设置为 span 的范围，最简单的方法就是为函数标记上 #[instrument]，此时 tracing 会自动为函数创建一个 span，span 名跟函数名相同，在输出的信息中还会自动带上函数参数。
1
2
3
4
5
6
7
8
9
10
11
12
| use tracing::{info, instrument};
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};
#[instrument]
fn foo(ans: i32) {
info!("in foo");
}
fn main() {
tracing_subscriber::registry().with(fmt::layer()).init();
foo(42);
}
|
output
1
| 2024-07-17T09:48:23.493047Z INFO foo{ans=42}: demo: in foo
|
in_scope#
对于没有内置 tracing 支持或者无法使用 #instrument 的函数，例如外部库的函数，我们可以使用 Span 结构体的 in_scope 方法，它可以将同步代码包裹在一个 span 中：
1
2
3
| use tracing::info_span;
let json = info_span!("json.parse").in_scope(|| serde_json::from_slice(&buf))?;
|
在 async 中使用 span#
需要注意，如果是在异步编程时使用，要避免以下使用方式:
1
2
3
4
5
6
7
8
9
10
11
| async fn my_async_function() {
let span = info_span!("my_async_function");
// WARNING: 该 span 直到 drop 后才结束，因此在 .await 期间，span 依然处于工作中状态
let _enter = span.enter();
// 在这里 span 依然在记录，但是 .await 会让出当前任务的执行权，然后运行时会去运行其它任务，此时这个 span 可能会记录其它任务的执行信息，最终记录了不正确的 trace 信息
some_other_async_function().await
// ...
}
|
建议使用下面的方式，简单有效:
1
2
3
4
5
6
7
8
9
10
| use tracing::{info, instrument};
use tokio::{io::AsyncWriteExt, net::TcpStream};
use std::io;
#[instrument]
async fn write(stream: &mut TcpStream) -> io::Result<usize> {
let result = stream.write(b"hello world\n").await;
info!("wrote to stream; success={:?}", result.is_ok());
result
}
|
那有同学可能要问了，是不是我们无法在异步代码中使用 span.enter 了，答案是：是也不是。
是，你无法直接使用 span.enter 语法了，原因上面也说过，但是可以通过下面的方式来曲线使用：
1
2
3
4
5
6
7
8
9
| use tracing::Instrument;
let my_future = async {
// ...
};
my_future
.instrument(tracing::info_span!("my_future"))
.await
|
日志初始化写到文件和console 中#
- 在同一个线程中写入到文件
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
| use tracing::{debug, error, event, info, Level};
use tracing_appender::rolling;
use tracing_subscriber::{
filter, fmt,
fmt::{format::Writer, time::FormatTime},
layer::SubscriberExt,
registry,
util::SubscriberInitExt,
Layer,
};
// 用来格式化日志的输出时间格式
struct LocalTimer;
// // 注意，使用chrono::Local::now()的效率相对会差一些，因为每次获取时间都要探测本机的时区。因此可改进为使用Offset的方式，明确指定时区，无需探测：
// impl FormatTime for LocalTimer {
// fn format_time(&self, w: &mut Writer<'_>) -> std::fmt::Result {
// write!(w, "{}", chrono::Local::now().format("%FT%T%.3f"))
// }
// }
const fn east8() -> Option<chrono::FixedOffset> {
chrono::FixedOffset::east_opt(8 * 3600)
}
impl FormatTime for LocalTimer {
fn format_time(&self, w: &mut Writer<'_>) -> std::fmt::Result {
let now = chrono::Utc::now().with_timezone(&east8().unwrap());
write!(w, "{}", now.format("%FT%T%.3f"))
}
}
pub fn logger_init() {
// 文件输出层
let file_appender = rolling::daily("logs/", "log");
// let (non_blocking_appender, _guard) = non_blocking(file_appender); // 输出非阻塞
registry()
// first layer for console output, use pretty formatter and level filter
.with(
fmt::layer()
.with_timer(LocalTimer)
.pretty()
.with_filter(filter::LevelFilter::from(Level::WARN)),
)
// second layer for log file appender, use json formatter, no filter
.with(
fmt::layer()
.with_timer(LocalTimer)
.with_ansi(false)
.json()
.with_writer(file_appender)
.with_filter(filter::LevelFilter::from_level(Level::INFO)),
)
.init();
// _guard
}
fn main() {
// tracing_subscriber::fmt::init();
let _ = logger_init();
event!(Level::INFO, passwd = "passwd");
let foo = 42;
info!(foo, "Hello from tracing");
debug!(foo, "hello at debug level");
error!(foo, "error will be in file");
}
|
cargo.toml
1
2
3
4
5
| [dependencies]
tracing = "0.1.37"
tracing-subscriber = { version = "0.3.16", features = ["json"] }
tracing-appender = "0.2"
chrono = "0.4"
|
当然，还有其它一些方式设置tracing-subscriber日志时间的时区和格式。例如可以通过它的fmt::time::OffsetTime指定时区，不过它使用的是time crate，因此如果记录非UTC时区，则先设置Cargo.toml：
1
2
| tracing-subscriber = {version = "0.3", features = ["time"]}
time = { version = "0.3", features = ["macros"] }
|
1
2
3
4
5
6
7
8
9
10
11
| use time::macros::{format_description, offset};
use tracing_subscriber::fmt::time::OffsetTime;
fn main() {
let time_fmt = format_description!("[year]-[month]-[day]T[hour]:[minute]:[second].[subsecond digits:3]");
let timer = OffsetTime::new(offset!(+8), time_fmt);
tracing_subscriber::fmt().with_timer(timer).init();
let offset = 2;
tracing::info!("offset: {}, hello world", offset);
}
|
- 使用非阻塞输出
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
|
use tracing::{debug, error, event, info, Level};
use tracing_appender::non_blocking;
use tracing_appender::rolling;
use tracing_subscriber::{
filter, fmt,
fmt::{format::Writer, time::FormatTime},
layer::SubscriberExt,
registry,
util::SubscriberInitExt,
Layer,
};
// 用来格式化日志的输出时间格式
struct LocalTimer;
// // 注意，使用chrono::Local::now()的效率相对会差一些，因为每次获取时间都要探测本机的时区。因此可改进为使用Offset的方式，明确指定时区，无需探测：
// impl FormatTime for LocalTimer {
// fn format_time(&self, w: &mut Writer<'_>) -> std::fmt::Result {
// write!(w, "{}", chrono::Local::now().format("%FT%T%.3f"))
// }
// }
const fn east8() -> Option<chrono::FixedOffset> {
chrono::FixedOffset::east_opt(8 * 3600)
}
impl FormatTime for LocalTimer {
fn format_time(&self, w: &mut Writer<'_>) -> std::fmt::Result {
let now = chrono::Utc::now().with_timezone(&east8().unwrap());
write!(w, "{}", now.format("%FT%T%.3f"))
}
}
pub fn logger_init() -> non_blocking::WorkerGuard {
// 文件输出层
let file_appender = rolling::daily("logs/", "log");
let (non_blocking_appender, _guard) = non_blocking(file_appender); // 输出非阻塞
registry()
// first layer for console output, use pretty formatter and level filter
.with(
fmt::layer()
.with_timer(LocalTimer)
.pretty()
.with_filter(filter::LevelFilter::from(Level::WARN)),
)
// second layer for log file appender, use json formatter, no filter
.with(
fmt::layer()
.with_timer(LocalTimer)
.with_ansi(false)
.json()
.with_writer(non_blocking_appender)
.with_filter(filter::LevelFilter::from_level(Level::INFO)),
)
.init();
_guard
}
fn main() {
// 需注意，使用tracing_appender时，因为是先缓冲日志信息，而不是直接写入文件。他要求必须在main()函数中使用Guard，否则guard被丢弃将不会写入任何信息到文件
let _g = logger_init();
event!(Level::INFO, passwd = "passwd");
let foo = 42;
info!(foo, "Hello from tracing");
debug!(foo, "hello at debug level");
error!(foo, "error will be in file");
}
|