新增日志与监控中的两个章节

pull/751/head
sunface 3 years ago
parent 0a565be8b4
commit a06c4ac6b6

@ -172,35 +172,14 @@
- [AWS 为何这么喜欢 Rust?](usecases/aws-rust.md)
- [Rust 最佳实践](practice/intro.md)
- [对抗编译检查](practice/fight-with-compiler/intro.md)
- [生命周期](practice/fight-with-compiler/lifetime/intro.md)
- [生命周期过大-01](practice/fight-with-compiler/lifetime/too-long1.md)
- [生命周期过大-02](practice/fight-with-compiler/lifetime/too-long2.md)
- [循环中的生命周期](practice/fight-with-compiler/lifetime/loop.md)
- [闭包碰到特征对象-01](practice/fight-with-compiler/lifetime/closure-with-static.md)
- [重复借用](practice/fight-with-compiler/borrowing/intro.md)
- [同时在函数内外使用引用](practice/fight-with-compiler/borrowing/ref-exist-in-out-fn.md)
- [智能指针引起的重复借用错误](practice/fight-with-compiler/borrowing/borrow-distinct-fields-of-struct.md)
- [类型未限制(todo)](practice/fight-with-compiler/unconstrained.md)
- [幽灵数据(todo)](practice/fight-with-compiler/phantom-data.md)
- [Rust 常见陷阱](practice/pitfalls/index.md)
- [for 循环中使用外部数组](practice/pitfalls/use-vec-in-for.md)
- [线程类型导致的栈溢出](practice/pitfalls/stack-overflow.md)
- [算术溢出导致的 panic](practice/pitfalls/arithmetic-overflow.md)
- [闭包中奇怪的生命周期](practice/pitfalls/closure-with-lifetime.md)
- [可变变量不可变?](practice/pitfalls/the-disabled-mutability.md)
- [可变借用失败引发的深入思考](practice/pitfalls/multiple-mutable-references.md)
- [不太勤快的迭代器](practice/pitfalls/lazy-iterators.md)
- [奇怪的序列 x..y](practice/pitfalls/weird-ranges.md)
- [无处不在的迭代器](practice/pitfalls/iterator-everywhere.md)
- [线程间传递消息导致主线程无法结束](practice/pitfalls/main-with-channel-blocked.md)
- [警惕 UTF-8 引发的性能隐患](practice/pitfalls/utf8-performance.md)
- [日常开发三方库精选](practice/third-party-libs.md)
- [命名规范](practice/naming.md)
- [日志和监控](practice/logs/intro.md)
- [日志详解](practice/logs/about-log.md)
- [在 Rust 中输出日志 TODO](practice/logs/logging.md)
- [使用 tracing 输出自定义的 Rust 日志](practice/logs/tracing-logger.md)
- [面试经验 doing](practice/interview.md)
- [代码开发实践 todo](practice/best-pratice.md)
- [日志记录 todo](practice/logs.md)
- [可观测性监控 todo](practice/observability.md)
<!-- - [代码开发实践 todo](practice/best-pratice.md) -->
- [手把手带你实现链表](too-many-lists/intro.md)
- [我们到底需不需要链表](too-many-lists/do-we-need-it.md)
@ -240,6 +219,31 @@
# 高级专题
---
- [征服编译错误](compiler/intro.md)
- [对抗编译检查](compiler/fight-with-compiler/intro.md)
- [生命周期](compiler/fight-with-compiler/lifetime/intro.md)
- [生命周期过大-01](compiler/fight-with-compiler/lifetime/too-long1.md)
- [生命周期过大-02](compiler/fight-with-compiler/lifetime/too-long2.md)
- [循环中的生命周期](compiler/fight-with-compiler/lifetime/loop.md)
- [闭包碰到特征对象-01](compiler/fight-with-compiler/lifetime/closure-with-static.md)
- [重复借用](compiler/fight-with-compiler/borrowing/intro.md)
- [同时在函数内外使用引用](compiler/fight-with-compiler/borrowing/ref-exist-in-out-fn.md)
- [智能指针引起的重复借用错误](compiler/fight-with-compiler/borrowing/borrow-distinct-fields-of-struct.md)
- [类型未限制(todo)](compiler/fight-with-compiler/unconstrained.md)
- [幽灵数据(todo)](compiler/fight-with-compiler/phantom-data.md)
- [Rust 常见陷阱](compiler/pitfalls/index.md)
- [for 循环中使用外部数组](compiler/pitfalls/use-vec-in-for.md)
- [线程类型导致的栈溢出](compiler/pitfalls/stack-overflow.md)
- [算术溢出导致的 panic](compiler/pitfalls/arithmetic-overflow.md)
- [闭包中奇怪的生命周期](compiler/pitfalls/closure-with-lifetime.md)
- [可变变量不可变?](compiler/pitfalls/the-disabled-mutability.md)
- [可变借用失败引发的深入思考](compiler/pitfalls/multiple-mutable-references.md)
- [不太勤快的迭代器](compiler/pitfalls/lazy-iterators.md)
- [奇怪的序列 x..y](compiler/pitfalls/weird-ranges.md)
- [无处不在的迭代器](compiler/pitfalls/iterator-everywhere.md)
- [线程间传递消息导致主线程无法结束](compiler/pitfalls/main-with-channel-blocked.md)
- [警惕 UTF-8 引发的性能隐患](compiler/pitfalls/utf8-performance.md)
- [Rust 性能优化 todo](profiling/intro.md)
- [深入内存 todo](profiling/memory/intro.md)
- [指针和引用 todo](profiling/memory/pointer-ref.md)

@ -0,0 +1 @@
# 征服编译错误

@ -0,0 +1,61 @@
# 详解日志
相比起监控,日志好理解的多:在某个时间点向指定的地方输出一条信息,里面记录着重要性、时间、地点和发生的事件,这就是日志。
> 注意,本文和 Rust 无关,我们争取从一个中立的角度去介绍何为日志
## 日志级别和输出位置
#### 日志级别
日志级别是对基本的“滚动文本”式日志记录的一个重要补充。每条日志消息都会基于其重要性或严重程度分配到一个日志级别。例如,对于某个程序,“你的电脑着火了”是一个非常重要的消息,而“无法找到配置文件”的重要等级可能就低一些;但对于另外一些程序,"无法找到配置文件" 可能才是最严重的错误,会直接导致程序无法正常启动,而“电脑着火”? 我们可能会记录为一条 `Debug` 日志(参见下文) :D。
至于到底该如何定义日志级别,这是仁者见仁的事情,并没有一个约定俗成的方式,就连很多大公司,都无法保证自己的开发者严格按照它所制定的规则来输出日。而下面是我认为的日志级别以及相关定义:
- Fatal: 程序发生致命错误,祝你好运。这种错误往往来自于程序逻辑的严重异常,例如之前提到的“无法找到配置文件”,再比如无法分配足够的硬盘空间、内存不够用等。遇到这种错误,建议立即退出或者重启程序,然后记录下相应的错误信息
- Error: 错误,一般指的是程序级别的错误或者严重的业务错误,但这种错误并不会影响程序的运行。一般的用户错误,例如用户名、密码错误等,不使用 Error 级别
- Warn: 警告,说明这条记录信息需要注意,但是不确定是否发生了错误,因此需要相关的开发来辨别下。或者这条信息既不是错误,但是级别又没有低到 info 级别,就可以用 Warn 来给出警示。例如某条用户连接异常关闭、无法找到相关的配置只能使用默认配置、XX秒后重试等
- Info: 信息,这种类型的日志往往用于记录程序的运行信息,例如用户操作或者状态的变化,再比如之前的用户名、密码错误,用户请求的开始和结束都可以记录为这个级别
- Debug: 调试信息,顾名思义是给开发者用的,用于了解程序当前的详细运行状况, 例如用户请求详细信息跟踪、读取到的配置信息、连接握手发包(连接的建立和结束往往是 Info 级别),就可以记录为 Debug 信息
可以看出,日志级别很多,特别是 Debug 日志,如果在生产环境中开启,简直就是一场灾难,每秒几百上千条都很正常。因此我们需要控制日志的最低级别:将最低级别设置为 Info 时,意味着低于 Info 的日志都不会输出对于上面的分级来说Debug 日志将不会被输出。
有些开发为了让特定的日志在控制上显示更明显,还会为不同的级别使用不同颜色的文字。
#### 输出位置
通常来说,日志可以输出两个地方:终端控制台和文件。对于前者,我们还有一个称呼标准输出,例如使用 `println!` 打印到终端的信息就是输出到标准输出中。
如果没有日志持久化的需求,你只是为了调试程序,建议输出到控制台即可。悄悄的说一句,我们还可以为不同的级别设定不同的输出位置,例如 `Debug` 日志输出到控制台,既方便开发查看,但又不会占用硬盘,而 `Info``Warning` 日志可以输出到文件 `info.log` 中,至于 `Error`、`Fatal` 则可以输出到 `error.log` 中。
但是如果大家以为只有输出到文件才能持久化日志,那你就错了,在后面的日志采集我们会详细介绍,先来看看日志查看。
## 日志查看
关于如何查看日志,相信大家都非常熟悉了,常用的方式有三种(事实上,可能也只有这三种):
- 在控制台查看,即可以直接查看输出到标准输出的日志,还可以使用 tail、cat、grep 等命令从日志文件中搜索查询或者以实时滚动的方式查看最新的日志
- 最简单的,进入到日志文件中,进行字符串搜索,或者从头到尾、从尾到头进行逐行查看
- 在可视化界面上查看,但是这个往往要配合日志采集工具,将日志采集到 ElasticSearch 或者其它搜索平台、数据中,然后再通过 kibana、grafana 等图形化服务进行搜索、查看,最重要的是可以进行日志的聚合统计,例如可以很方便的在 kibana 中查询满足指定条件的日志在某段时间内出现了多少次。
大家现在知道了,可视化,首先需要将日志集中采集起来,那么该如何采集日志呢?
## 日志采集
之前我们提到,不是只有输出到文件才能持久化日志,事实上,输出到控制台也能持久化日志。
其中的**秘诀就在于使用一个日志采集工具去从控制台的标准输出读取日志数据,然后将读取到的数据发送到日志存储平台**,例如 ElasticSearch进行集中存储。当然在存储前还需要进行日志格式、数据的处理以便只保留我们需要的格式和日志数据。
最典型的就是容器或容器云环境的日志采集,基本都是通过上面的方式进行的:容器中的进程将日志输出到标准输出,然后一个单独的日志采集服务直接读取标准输出中的日志,再通过网络发送到日志处理、存储的平台。大家发现了吗?这个流程完全不会在应用运行的本地或宿主机上存储任何日志,所以特别适合容器环境!
目前常用的日志采集工具有 filebeat、vector( Rust 开发,功能强大,性能非常高 ) 等,它们都是以 agent 的形式运行在你的应用程序旁边( 在同一个 pod 或虚拟机上 ),提供贴心的服务。
## 集中式日志存储
最后,我们再来简单介绍下日志存储。提到存储,首先不得不提的就是日志使用方式。
其实,除了 Debug 的时候,我们使用日志基本都是基于某个关键字进行搜索的,将日志存储在各台主机上的硬盘文件中,然后逐个去查询显然是非常非常低效的,最好的方式就是将日志集中收集上来后,存储在一个搜索平台中,例如 ElasticSearch。
当然,存储的时候肯定也不是简单的一行一行存储,而是需要将一条日志的多个关键词切取出来,然后以关键词索引的方式进行存储( 简化模型 ),这样我们就可以在后续使用时,通过关键词来搜索日志了。

@ -0,0 +1,6 @@
# 日志和监控
这几年 AIOps 特别火,但是你要是逮着一个运维问一下,他估计很难说出个所以然来,毕竟概念和现实往往是脱节的,前者的发展速度肯定远快于后者。
好在我大概了解这块儿领域,可以说智能化运维的核心就在于日志和监控,换而言之?何为智能,不就是基于已有的海量数据分析后进行决策吗?当然,你要说以前的知识库类型的运维决策也是智能,我也没办法杠: D
总之,不仅仅是对于开发者,对于整个技术链条的参与者,甚至包括老板,**日志和监控都是开发实践中最最重要的一环**。

@ -1,5 +1,4 @@
# 日志和监控 todo
# 在 Rust 中记录日志
```rust
if cfg!(debug_assertions) {

@ -0,0 +1,624 @@
# 使用 tracing 输出自定义的 Rust 日志
在 [tracing](https://docs.rs/crate/tracing/latest) 包出来前Rust 的日志和监控可以说是一片鱼塘,是的,连鱼龙混杂都算不上。在大名鼎鼎的 tokio 开发团队推出 `tracing` 后,我现在坚定的认为 `tracing` 就是未来!
> 截至目前rust编译器团队、GraphQL 都在使用 tracing而且 tokio 在密谋一件大事:基于 tracing 开发一套终端交互式 debug 工具: [console](https://github.com/tokio-rs/console)
基于这种坚定的信仰,我们决定将公司之前使用的 `log` 包替换成 `tracing` ,但是有一个问题:后者提供的 JSON logger 总感觉不是那个味儿。这意味着,对于程序员来说,最快乐的时光又要到来了:定制自己的开发工具。
好了,闲话少说,下面我们一起来看看该如何构建自己的 logger以及深入了解 tracing 的一些原理,当然你也可以只选择来凑个热闹,总之,开始吧!
## 打地基(1)
首先,使用 `cargo new --bin test-tracing` 创建一个新的二进制类型( binary )的项目。
然后引入以下依赖:
```toml
# in cargo.toml
[dependencies]
serde_json = "1"
tracing = "0.1"
tracing-subscriber = "0.3"
```
其中 `tracing-subscriber` 用于订阅正在发生的日志、监控事件,然后可以对它们进行进一步的处理。`serde_json` 可以帮我们更好的处理格式化的 JSON毕竟咱们要解决的问题就来自于 JSON logger。
下面来实现一个基本功能:设置自定义的 logger并使用 `info!` 来打印一行日志。
```rust
// in examples/figure_0/main.rs
use tracing::info;
use tracing_subscriber::prelude::*;
mod custom_layer;
use custom_layer::CustomLayer;
fn main() {
// 设置 `tracing-subscriber` 对 tracing 数据的处理方式
tracing_subscriber::registry().with(CustomLayer).init();
// 打印一条简单的日志。用 `tracing` 的行话来说,`info!` 将创建一个事件
info!(a_bool = true, answer = 42, message = "first example");
}
```
大家会发现,上面引入了一个模块 `custom_layer` 下面从该模块开始,来实现我们的自定义 logger。首先`tracing-subscriber` 提供了一个特征 [`Layer`](https://docs.rs/tracing-subscriber/0.3/tracing_subscriber/layer/trait.Layer.html) 专门用于处理 `tracing` 的各种事件( span, event )。
```rust
// in examples/figure_0/custom_layer.rs
use tracing_subscriber::Layer;
pub struct CustomLayer;
impl<S> Layer<S> for CustomLayer where S: tracing::Subscriber {}
```
由于还没有填入任何代码,运行该示例比你打的水漂还无力 - 毫无效果。
## 捕获事件
`tracing` 中,当 `info!`、`error!` 等日志宏被调用时,就会产生一个相应的[事件 Event](https://docs.rs/tracing/0.1/tracing/event/struct.Event.html)。
而我们首先,就要为之前的 `Layer` 特征实现 `on_event` 方法。
```rust,editable
// in examples/figure_0/custom_layer.rs
where
S: tracing::Subscriber,
{
fn on_event(
&self,
event: &tracing::Event<'_>,
_ctx: tracing_subscriber::layer::Context<'_, S>,
) {
println!("Got event!");
println!(" level={:?}", event.metadata().level());
println!(" target={:?}", event.metadata().target());
println!(" name={:?}", event.metadata().name());
for field in event.fields() {
println!(" field={}", field.name());
}
}
}
```
从代码中可以看出,我们打印了事件中包含的事件名、日志等级以及事件发生的代码路径。运行后,可以看到以下输出:
```properties
$ cargo run --example figure_1
Got event!
level=Level(Info)
target="figure_1"
name="event examples/figure_1/main.rs:10"
field=a_bool
field=answer
field=message
```
但是奇怪的是,我们无法通过 API 来获取到具体的 `field` 值。还有就是,上面的输出还不是 JSON 格式。
现在问题来了,要创建自己的 logger不能获取 `filed` 显然是不靠谱的。
### 访问者模式
在设计上,`tracing` 作出了一个选择:永远不会自动存储产生的事件数据( spans, events )。如果我们要获取这些数据,就必须自己手动存储。
解决办法就是使用访问者模式(Visitor Pattern):手动实现 `Visit` 特征去获取事件中的值。`Visit` 为每个 `tracing` 可以处理的类型都提供了对应的 `record_X` 方法。
```rust
// in examples/figure_2/custom_layer.rs
struct PrintlnVisitor;
impl tracing::field::Visit for PrintlnVisitor {
fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
println!(" field={} value={}", field.name(), value)
}
fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
println!(" field={} value={}", field.name(), value)
}
fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
println!(" field={} value={}", field.name(), value)
}
fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
println!(" field={} value={}", field.name(), value)
}
fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
println!(" field={} value={}", field.name(), value)
}
fn record_error(
&mut self,
field: &tracing::field::Field,
value: &(dyn std::error::Error + 'static),
) {
println!(" field={} value={}", field.name(), value)
}
fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
println!(" field={} value={:?}", field.name(), value)
}
}
```
然后在之前的 `on_event` 中来使用这个新的访问者: `event.record(&mut visitor)` 可以访问其中的所有值。
```rust
// in examples/figure_2/custom_layer.rs
fn on_event(
&self,
event: &tracing::Event<'_>,
_ctx: tracing_subscriber::layer::Context<'_, S>,
) {
println!("Got event!");
println!(" level={:?}", event.metadata().level());
println!(" target={:?}", event.metadata().target());
println!(" name={:?}", event.metadata().name());
let mut visitor = PrintlnVisitor;
event.record(&mut visitor);
}
```
这段代码看起来有模有样,来运行下试试:
```properties
$ cargo run --example figure_2
Got event!
level=Level(Info)
target="figure_2"
name="event examples/figure_2/main.rs:10"
field=a_bool value=true
field=answer value=42
field=message value=first example
```
Bingo ! 一切完美运行
### 构建 JSON logger
目前为止,离我们想要的 JSON logger 只差一步了。下面来实现一个 `JsonVisitor` 替代之前的 `PrintlnVisitor` 用于构建一个 JSON 对象。
```rust
// in examples/figure_3/custom_layer.rs
impl<'a> tracing::field::Visit for JsonVisitor<'a> {
fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
self.0
.insert(field.name().to_string(), serde_json::json!(value));
}
fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
self.0
.insert(field.name().to_string(), serde_json::json!(value));
}
fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
self.0
.insert(field.name().to_string(), serde_json::json!(value));
}
fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
self.0
.insert(field.name().to_string(), serde_json::json!(value));
}
fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
self.0
.insert(field.name().to_string(), serde_json::json!(value));
}
fn record_error(
&mut self,
field: &tracing::field::Field,
value: &(dyn std::error::Error + 'static),
) {
self.0.insert(
field.name().to_string(),
serde_json::json!(value.to_string()),
);
}
fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
self.0.insert(
field.name().to_string(),
serde_json::json!(format!("{:?}", value)),
);
}
}
```
```rust
// in examples/figure_3/custom_layer.rs
fn on_event(
&self,
event: &tracing::Event<'_>,
_ctx: tracing_subscriber::layer::Context<'_, S>,
) {
// Covert the values into a JSON object
let mut fields = BTreeMap::new();
let mut visitor = JsonVisitor(&mut fields);
event.record(&mut visitor);
// Output the event in JSON
let output = serde_json::json!({
"target": event.metadata().target(),
"name": event.metadata().name(),
"level": format!("{:?}", event.metadata().level()),
"fields": fields,
});
println!("{}", serde_json::to_string_pretty(&output).unwrap());
}
```
继续运行:
```properties
$ cargo run --example figure_3
{
"fields": {
"a_bool": true,
"answer": 42,
"message": "first example"
},
"level": "Level(Info)",
"name": "event examples/figure_3/main.rs:10",
"target": "figure_3"
}
```
终于,我们实现了自己的 logger并且成功地输出了一条 JSON 格式的日志。并且新实现的 `Layer` 就可以添加到 `tracing-subscriber` 中用于记录日志事件。
下面再来一起看看如何使用`tracing` 提供的 `period-of-time spans` 为日志增加更详细的上下文信息。
### 何为 span
在之前我们多次提到 span 这个词,但是何为 span
不知道大家知道分布式追踪不?在分布式系统中每一个请求从开始到返回,会经过多个服务,这条请求路径被称为请求跟踪链路( trace ),可以看出,一条链路是由多个部分组成,我们可以简单的把其中一个部分认为是一个 span。
跟 log 是对某个时间点的记录不同span 记录的是一个时间段。当程序开始执行一系列任务时span 就会开始当这个系列任务结束后span 也随之结束。
由此可见tracing 其实不仅仅是一个日志库,它还是一个分布式追踪的库,可以帮助我们采集信息,然后上传给 jaeger 等分布式追踪平台,最终实现对指定应用程序的监控。
在理解后,再来看看该如何为自定义的 logger 实现 spans。
### 打地基(2)
先来创建一个外部 span 和一个内部 span从概念上来说spans 和 events 创建的东东类似以下嵌套结构:
- 进入外部 span
- 进入内部 span
- 事件已创建,内部 span 是它的父 span外部 span 是它的祖父 span
- 结束内部 span
- 结束外部 span
> 有些同学可能还是不太理解,你就把 span 理解成为监控埋点,进入 span == 埋点开始,结束 span == 埋点结束
在下面的代码中,当使用 `span.enter()` 创建的 span 超出作用域时,将自动退出:根据 `Drop` 特征触发的顺序,`inner_span` 将先退出,然后才是 `outer_span` 的退出。
```rust
// in examples/figure_5/main.rs
use tracing::{debug_span, info, info_span};
use tracing_subscriber::prelude::*;
mod custom_layer;
use custom_layer::CustomLayer;
fn main() {
tracing_subscriber::registry().with(CustomLayer).init();
let outer_span = info_span!("outer", level = 0);
let _outer_entered = outer_span.enter();
let inner_span = debug_span!("inner", level = 1);
let _inner_entered = inner_span.enter();
info!(a_bool = true, answer = 42, message = "first example");
}
```
再回到事件处理部分,通过使用 `examples/figure_0/main.rs` 我们能获取到事件的父 span当然前提是它存在。但是在实际场景中直接使用 `ctx.event_scope(event)` 来迭代所有 span 会更加简单好用。
注意,这种迭代顺序类似于栈结构,以上面的代码为例,先被迭代的是 `inner_span`,然后才是 `outer_span`
当然,如果你不想以类似于出栈的方式访问,还可以使用 `scope.from_root()` 直接反转,此时的访问将从最外层开始: `outer -> innter`
对了,为了使用 `ctx.event_scope()`,我们的订阅者还需实现 `LookupRef`。提前给出免责声明:这里的实现方式有些诡异,大家可能难以理解,但是..我们其实也无需理解,只要这么用即可。
> 译者注:这里用到了高阶生命周期 HRTB( Higher Ranke Trait Bounds ) 的概念,一般的读者无需了解,感兴趣的可以看看(这里)[https://doc.rust-lang.org/nomicon/hrtb.html]
```rust
// in examples/figure_5/custom_layer.rs
impl<S> Layer<S> for CustomLayer
where
S: tracing::Subscriber,
// 好可怕! 还好我们不需要理解它,只要使用即可
S: for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
{
fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
// 父 span
let parent_span = ctx.event_span(event).unwrap();
println!("parent span");
println!(" name={}", parent_span.name());
println!(" target={}", parent_span.metadata().target());
println!();
// 迭代范围内的所有的 spans
let scope = ctx.event_scope(event).unwrap();
for span in scope.from_root() {
println!("an ancestor span");
println!(" name={}", span.name());
println!(" target={}", span.metadata().target());
}
}
}
```
运行下看看效果:
```properties
$ cargo run --example figure_5
parent span
name=inner
target=figure_5
an ancestor span
name=outer
target=figure_5
an ancestor span
name=inner
target=figure_5
```
细心的同学可能会发现,这里怎么也没有 field 数据?没错,而且恰恰是这些 field 包含的数据才让日志和监控有意义。那我们可以像之前一样,使用访问器 Visitor 来解决吗?
### span 的数据在哪里
答案是No。因为 `ctx.event_scope ` 返回的东东没有任何办法可以访问其中的字段。
不知道大家还记得我们为何之前要使用访问器吗?很简单,因为 `tracing` 默认不会去存储数据,既然如此,那 `span` 这种跨了某个时间段的,就更不可能去存储数据了。
现在只能看看 `Layer` 特征有没有提供其它的方法了,哦呦,发现了一个 `on_new_span`,从名字可以看出,该方法是在 `span` 创建时调用的。
```rust
// in examples/figure_6/custom_layer.rs
impl<S> Layer<S> for CustomLayer
where
S: tracing::Subscriber,
S: for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
{
fn on_new_span(
&self,
attrs: &tracing::span::Attributes<'_>,
id: &tracing::span::Id,
ctx: tracing_subscriber::layer::Context<'_, S>,
) {
let span = ctx.span(id).unwrap();
println!("Got on_new_span!");
println!(" level={:?}", span.metadata().level());
println!(" target={:?}", span.metadata().target());
println!(" name={:?}", span.metadata().name());
// Our old friend, `println!` exploration.
let mut visitor = PrintlnVisitor;
attrs.record(&mut visitor);
}
}
```
```properties
$ cargo run --example figure_6
Got on_new_span!
level=Level(Info)
target="figure_7"
name="outer"
field=level value=0
Got on_new_span!
level=Level(Debug)
target="figure_7"
name="inner"
field=level value=1
```
芜湖! 我们的数据回来了!但是这里有一个隐患:只能在创建的时候去访问数据。如果仅仅是为了记录 spans那没什么大问题但是如果我们随后需要记录事件然后去尝试访问之前的 span 呢?此时 span 的数据已经不存在了!
如果 `tracing` 不能存储数据,那我们这些可怜的开发者该怎么办?
### 自己存储 span 数据
何为一个优秀的程序员?能偷懒的时候绝不多动半跟手指,但是需要勤快的时候,也是自己动手丰衣足食的典型。
因此,既然 `tracing` 不支持,那就自己实现吧。先确定一个目标:捕获 span 的数据,然后存储在某个地方以便后续访问。
好在 `tracing-subscriber` 提供了扩展 extensions 的方式,可以让我们轻松地存储自己的数据,该扩展甚至可以跟每一个 span 联系在一起!
虽然我们可以把之前见过的 `BTreeMap<String, serde_json::Value>` 存在扩展中,但是由于扩展数据是被 registry 中的所有layers 所共享的,因此出于私密性的考虑,还是只保存私有字段比较合适。这里使用一个 newtype 模式来创建新的类型:
```rust
// in examples/figure_8/custom_layer.rs
#[derive(Debug)]
struct CustomFieldStorage(BTreeMap<String, serde_json::Value>);
```
每次发现一个新的 span 时,都基于它来构建一个 JSON 对象,然后将其存储在扩展数据中。
```rust
// in examples/figure_8/custom_layer.rs
fn on_new_span(
&self,
attrs: &tracing::span::Attributes<'_>,
id: &tracing::span::Id,
ctx: tracing_subscriber::layer::Context<'_, S>,
) {
// 基于 field 值来构建我们自己的 JSON 对象
let mut fields = BTreeMap::new();
let mut visitor = JsonVisitor(&mut fields);
attrs.record(&mut visitor);
// 使用之前创建的 newtype 包裹下
let storage = CustomFieldStorage(fields);
// 获取内部 span 数据的引用
let span = ctx.span(id).unwrap();
// 获取扩展,用于存储我们的 span 数据
let mut extensions = span.extensions_mut();
// 存储!
extensions.insert::<CustomFieldStorage>(storage);
}
```
这样,未来任何时候我们都可以取到该 span 包含的数据( 例如在 `on_event` 方法中 )。
```rust
// in examples/figure_8/custom_layer.rs
fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
let scope = ctx.event_scope(event).unwrap();
println!("Got event!");
for span in scope.from_root() {
let extensions = span.extensions();
let storage = extensions.get::<CustomFieldStorage>().unwrap();
println!(" span");
println!(" target={:?}", span.metadata().target());
println!(" name={:?}", span.metadata().name());
println!(" stored fields={:?}", storage);
}
}
```
### 功能齐全的 JSON logger
截至目前,我们已经学了不少东西,下面来利用这些知识实现最后的 JSON logger。
```rust
// in examples/figure_9/custom_layer.rs
fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
// All of the span context
let scope = ctx.event_scope(event).unwrap();
let mut spans = vec![];
for span in scope.from_root() {
let extensions = span.extensions();
let storage = extensions.get::<CustomFieldStorage>().unwrap();
let field_data: &BTreeMap<String, serde_json::Value> = &storage.0;
spans.push(serde_json::json!({
"target": span.metadata().target(),
"name": span.name(),
"level": format!("{:?}", span.metadata().level()),
"fields": field_data,
}));
}
// The fields of the event
let mut fields = BTreeMap::new();
let mut visitor = JsonVisitor(&mut fields);
event.record(&mut visitor);
// And create our output
let output = serde_json::json!({
"target": event.metadata().target(),
"name": event.metadata().name(),
"level": format!("{:?}", event.metadata().level()),
"fields": fields,
"spans": spans,
});
println!("{}", serde_json::to_string_pretty(&output).unwrap());
}
```
```properties
$ cargo run --example figure_9
{
"fields": {
"a_bool": true,
"answer": 42,
"message": "first example"
},
"level": "Level(Info)",
"name": "event examples/figure_9/main.rs:16",
"spans": [
{
"fields": {
"level": 0
},
"level": "Level(Info)",
"name": "outer",
"target": "figure_9"
},
{
"fields": {
"level": 1
},
"level": "Level(Debug)",
"name": "inner",
"target": "figure_9"
}
],
"target": "figure_9"
}
```
嗯,完美。
### 等等,你说功能齐全?
上面的代码在发布到生产环境后,依然运行地相当不错,但是我发现还缺失了一个功能: span 在创建之后,依然要能记录数据。
```rust
// in examples/figure_10/main.rs
let outer_span = info_span!("outer", level = 0, other_field = tracing::field::Empty);
let _outer_entered = outer_span.enter();
// Some code...
outer_span.record("other_field", &7);
```
如果基于之前的代码运行上面的代码,我们将不会记录 `other_field`,因为该字段在收到 `on_new_span` 事件时,还不存在。
对此,`Layer` 提供了 `on_record` 方法:
```rust
// in examples/figure_10/custom_layer.rs
fn on_record(
&self,
id: &tracing::span::Id,
values: &tracing::span::Record<'_>,
ctx: tracing_subscriber::layer::Context<'_, S>,
) {
// 获取正在记录数据的 span
let span = ctx.span(id).unwrap();
// 获取数据的可变引用,该数据是在 on_new_span 中创建的
let mut extensions_mut = span.extensions_mut();
let custom_field_storage: &mut CustomFieldStorage =
extensions_mut.get_mut::<CustomFieldStorage>().unwrap();
let json_data: &mut BTreeMap<String, serde_json::Value> = &mut custom_field_storage.0;
// 使用我们的访问器老朋友
let mut visitor = JsonVisitor(json_data);
values.record(&mut visitor);
}
```
终于,在最后,我们拥有了一个功能齐全的自定义的 JSON logger大家快去尝试下吧。当然你也可以根据自己的需求来定制专属于你的 logger毕竟方法是一通百通的。
> 在以下 github 仓库,可以找到完整的代码: https://github.com/bryanburgers/tracing-blog-post

@ -1 +0,0 @@
# 可观测性监控 todo
Loading…
Cancel
Save