严格来说，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" ] }
copy
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" )
}
copy
output:
1
2
2024 - 07 - 17 T09 :33 :44.277725 Z INFO my_span : demo : belog to my_span
2024 - 07 - 17 T09 :33 :44.278300 Z INFO demo : out of my_span
copy
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" )
}
copy
output
1
2
3
4
2024 - 07 - 17 T09 :42 :39.162843 Z INFO demo : something happened
2024 - 07 - 17 T09 :42 :39.163364 Z DEBUG my_span : demo : something happened inside my_span
2024 - 07 - 17 T09 :42 :39.163768 Z INFO my_span :span_2 : demo : something went wrong in my_span and span_2
2024 - 07 - 17 T09 :42 :39.163974 Z WARN my_span : demo : something happened out of my_span
copy
虽然 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 );
}
copy
output
1
2024 - 07 - 17 T09 :48 :23.493047 Z INFO foo { ans = 42 } : demo : in foo
copy
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 )) ? ;
copy
在 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
// ...
}
copy
建议使用下面的方式，简单有效:
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
}
copy
那有同学可能要问了，是不是我们无法在异步代码中使用 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
copy
日志初始化写到文件和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" );
}
copy
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"
copy
当然，还有其它一些方式设置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" ] }
copy
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 );
}
copy
使用非阻塞输出 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" );
}
copy