add 日志 - tracing

src/SUMMARY.md

@@ -175,7 +175,7 @@
 - [日志和监控](logs/intro.md)
     - [日志详解](logs/about-log.md)
     - [日志门面 log](logs/log.md)
-    - [使用 tracing 记录日志 TODO](logs/tracing.md)
+    - [使用 tracing 记录日志](logs/tracing.md)
     - [自定义 tracing 的输出格式](logs/tracing-logger.md)
     - [监控 TODO](logs/observe/intro.md)
       - [监控详解 TODO](logs/observe/about-observe.md)

src/logs/tracing.md

@@ -12,6 +12,16 @@
 > 在分布式追踪中，trace_id 都是由 SDK 自动生成和往后透穿，对于用户的使用来说是完全透明的。如果你要手动用日志的方式来实现请求链路的追踪，那么就必须考虑 trace_id 的手动生成、透传，以及不同语言之间的协议规范等问题
 
 ## 一个简单例子
+
+开始之前，需要先将 `tracing` 添加到项目的 `Cargo.toml` 中:
+
+```toml
+[dependencies]
+tracing = "0.1"
+```
+
+注意，在写作本文时，`0.2` 版本已经快要出来了，所以具体使用的版本请大家以阅读时为准。
+
 下面的例子中将同时使用 `log` 和 `tracing` :
 ```rust
 use log;
@@ -73,22 +83,7 @@ fn main() {
 } // 这里 enter 将被 drop，`my_span` 也随之结束
 ```
 
-需要注意，如果是在异步编程时使用，要避免以下使用方式:
-```rust
-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
-
-    // ...
-}
-```
-
-### Event
+### Event 事件
 `Event` 代表了某个时间点发生的事件，这方面它跟日志类似，但是不同的是，`Event` 还可以产生在 span 的上下文中。
 
 ```rust
@@ -113,11 +108,114 @@ fn main() {
 2022-04-09T14:51:38.383111Z DEBUG my_span: test_tracing: something happened inside my_span
 ```
 
-虽然 `event` 在哪里都可以使用，但是最好只在 span 的上下文中使用：用于代表一个时间点发生的事件，例如记录 HTTP 请求返回的状态码，从队列中获取一个对象，等等。
+虽然 `event` 在哪里都可以使用，**但是最好只在 span 的上下文中使用**：用于代表一个时间点发生的事件，例如记录 HTTP 请求返回的状态码，从队列中获取一个对象，等等。
+
+### Collector 收集器
+当 `Span` 或 `Event` 发生时，它们会被实现了 `Collect` 特征的收集器所记录或聚合。这个过程是通过通知的方式实现的：当 `Event` 发生或者 `Span` 开始/结束时，会调用 `Collect` 特征的[相应方法](https://tracing-rs.netlify.app/tracing/trait.collect#tymethod.event)通知 Collector。
+
+#### tracing-subscriber
+我们前面提到只有使用了 [`tracing-subscriber`](https://docs.rs/tracing-subscriber/) 后，日志才能输出到控制台中。
+
+之前大家可能还不理解，现在应该明白了，它是一个 Collector，可以将记录的日志收集后，再输出到控制台中。
+
+## 使用方法
+
+### `span!` 宏
+`span!` 宏可以用于创建一个 `Span` 结构体，然后通过调用结构体的 `enter` 方法来开始，再通过超出作用域时的 `drop` 来结束。
+
+```rust
+use tracing::{span, Level};
+fn main() {
+    let span = span!(Level::TRACE, "my_span");
+
+    // `enter` 返回一个 RAII ，当其被 drop 时，将自动结束该 span
+    let enter = span.enter();
+    // 这里开始进入 `my_span` 的上下文
+    // 下面执行一些任务，并记录一些信息到 `my_span` 中
+    // ...
+} // 这里 enter 将被 drop，`my_span` 也随之结束
+```
+
+### #[instrument]
+如果想要将某个函数的整个函数体都设置为 span 的范围，最简单的方法就是为函数标记上 `#[instrument]`，此时 tracing 会自动为函数创建一个 span，span 名跟函数名相同，在输出的信息中还会自动带上函数参数。
+
+```rust
+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);
+}
+```
+
+```shell
+2022-04-10T02:44:12.885556Z  INFO foo{ans=42}: test_tracing: in foo
+```
+
+关于 `#[instrument]` 详细说明，请参见[官方文档](https://tracing-rs.netlify.app/tracing/attr.instrument.html)。
+
+### in_scope
+对于没有内置 tracing 支持或者无法使用 `#instrument` 的函数，例如外部库的函数，我们可以使用 `Span` 结构体的 `in_scope` 方法，它可以将同步代码包裹在一个 span 中：
+```rust
+use tracing::info_span;
+
+let json = info_span!("json.parse").in_scope(|| serde_json::from_slice(&buf))?;
+```
+
+### 在 async 中使用 span 
+需要注意，如果是在异步编程时使用，要避免以下使用方式:
+```rust
+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
+
+    // ...
+}
+```
+
+我们建议使用以下方式，简单又有效:
+```rust
+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` 语法了，原因上面也说过，但是可以通过下面的方式来曲线使用：
+```rust
+use tracing::Instrument;
+
+let my_future = async {
+    // ...
+};
 
+my_future
+    .instrument(tracing::info_span!("my_future"))
+    .await
+```
 
-## spans 嵌套
 
+### spans 嵌套
+`tracing` 的 span 不仅仅是上面展示的基本用法，它们还可以进行嵌套！
 ```rust
 use tracing::{debug, info, span, Level};
 use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};
@@ -128,7 +226,7 @@ fn main() {
     let scope = span!(Level::DEBUG, "foo");
     let _enter = scope.enter();
     info!("Hello in foo scope");
-    debug!("before enter bar scope");
+    debug!("before entering bar scope"); 
     {
         let scope = span!(Level::DEBUG, "bar", ans = 42);
         let _enter = scope.enter();
@@ -139,3 +237,208 @@ fn main() {
     debug!("end bar scope");
 }
 ```
+
+```shell
+INFO foo: log_test: Hello in foo scope
+DEBUG foo: log_test: before entering bar scope
+DEBUG foo:bar{ans=42}: log_test: enter bar scope
+INFO foo:bar{ans=42}: log_test: In bar scope
+DEBUG foo:bar{ans=42}: log_test: end bar scope
+DEBUG foo: log_test: end bar scope
+```
+
+在上面的日志中，`foo:bar` 不仅包含了 `foo` 和 `bar` span 名，还显示了它们之间的嵌套关系。
+
+
+## 对宏进行配置
+
+### 日志级别和目标
+`span!` 和 `event!` 宏都需要设定相应的日志级别，而且它们支持可选的 `target` 或 `parent` 参数( 只能二者选其一 )，该参数用于描述事件发生的位置，如果父 span 没有设置，`target` 参数也没有提供，那这个位置默认分别是当前的 span 和 当前的模块。
+
+```rust
+use tracing::{debug, info, span, Level,event};
+use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};
+
+fn main() {
+    tracing_subscriber::registry().with(fmt::layer()).init();
+
+    let s = span!(Level::TRACE, "my span");
+    // 没进入 span，因此输出日志将不回带上 span 的信息
+    event!(target: "app_events", Level::INFO, "something has happened 1!");
+
+    // 进入 span ( 开始 )
+    let _enter = s.enter();
+    // 没有设置 target 和 parent
+    // 这里的对象位置分别是当前的 span 名和模块名
+    event!(Level::INFO, "something has happened 2!");
+    // 设置了 target
+    // 这里的对象位置分别是当前的 span 名和 target
+    event!(target: "app_events",Level::INFO, "something has happened 3!");
+
+    let span = span!(Level::TRACE, "my span 1");
+    // 这里就更为复杂一些，留给大家作为思考题
+    event!(parent: &span, Level::INFO, "something has happened 4!");
+}
+```
+
+### 记录字段
+我们可以通过语法 `field_name = field_value` 来输出结构化的日志
+
+```rust
+// 记录一个事件，带有两个字段:
+//  - "answer", 值是 42
+//  - "question", 值是 "life, the universe and everything"
+event!(Level::INFO, answer = 42, question = "life, the universe, and everything");
+
+// 日志输出 -> INFO test_tracing: answer=42 question="life, the universe, and everything"
+```
+
+#### 捕获环境变量
+还可以捕获环境中的变量:
+
+```rust
+let user = "ferris";
+
+// 下面的简写方式
+span!(Level::TRACE, "login", user);
+// 等价于:
+span!(Level::TRACE, "login", user = user);
+```
+
+```rust
+use tracing::{info, span, Level};
+use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};
+
+fn main() {
+    tracing_subscriber::registry().with(fmt::layer()).init();
+
+    let user = "ferris";
+    let s = span!(Level::TRACE, "login", user);
+    let _enter = s.enter();
+
+    info!(welcome="hello", user);
+    // 下面一行将报错，原因是这种写法是格式化字符串的方式，必须使用 info!("hello {}", user)
+    // info!("hello", user);
+}
+
+// 日志输出 -> INFO login{user="ferris"}: test_tracing: welcome="hello" user="ferris"
+```
+
+#### 字段名的多种形式
+字段名还可以包含 `.` :
+```rust
+let user = "ferris";
+let email = "ferris@rust-lang.org";
+event!(Level::TRACE, user, user.email = email);
+
+// 还可以使用结构体
+let user = User {
+    name: "ferris",
+    email: "ferris@rust-lang.org",
+};
+
+// 直接访问结构体字段，无需赋值即可使用
+span!(Level::TRACE, "login", user.name, user.email);
+
+// 字段名还可以使用字符串
+event!(Level::TRACE, "guid:x-request-id" = "abcdef", "type" = "request");
+
+// 日志输出 -> 
+// TRACE test_tracing: user="ferris" user.email="ferris@rust-lang.org"
+// TRACE test_tracing: user.name="ferris" user.email="ferris@rust-lang.org"
+// TRACE test_tracing: guid:x-request-id="abcdef" type="request"
+```
+
+#### ?
+`?` 符号用于说明该字段将使用 `fmt::Debug` 来格式化。
+
+```rust
+ #[derive(Debug)]
+struct MyStruct {
+    field: &'static str,
+}
+
+let my_struct = MyStruct {
+    field: "Hello world!",
+};
+
+// `my_struct` 将使用 Debug 的形式输出
+event!(Level::TRACE, greeting = ?my_struct);
+// 等价于:
+event!(Level::TRACE, greeting = tracing::field::debug(&my_struct));
+
+// 下面代码将报错, my_struct 没有实现 Display
+// event!(Level::TRACE, greeting = my_struct);
+
+// 日志输出 -> TRACE test_tracing: greeting=MyStruct { field: "Hello world!" }
+```
+
+#### %
+`%` 说明字段将用 `fmt::Display` 来格式化。
+
+```rust
+// `my_struct.field` 将使用 `fmt::Display` 的格式化形式输出
+event!(Level::TRACE, greeting = %my_struct.field);
+// 等价于:
+event!(Level::TRACE, greeting = tracing::field::display(&my_struct.field));
+
+// 作为对比，大家可以看下 Debug 和正常的字段输出长什么样
+event!(Level::TRACE, greeting = ?my_struct.field);
+event!(Level::TRACE, greeting = my_struct.field);
+
+// 下面代码将报错, my_struct 没有实现 Display
+// event!(Level::TRACE, greeting = %my_struct);
+```
+
+```shell
+2022-04-10T03:49:00.834330Z TRACE test_tracing: greeting=Hello world!
+2022-04-10T03:49:00.834410Z TRACE test_tracing: greeting=Hello world!
+2022-04-10T03:49:00.834422Z TRACE test_tracing: greeting="Hello world!"
+2022-04-10T03:49:00.834433Z TRACE test_tracing: greeting="Hello world!"
+```
+
+#### Empty
+字段还能标记为 `Empty`，用于说明该字段目前没有任何值，但是可以在后面进行记录。
+
+```rust
+use tracing::{trace_span, field};
+
+let span = trace_span!("my_span", greeting = "hello world", parting = field::Empty);
+
+// ...
+
+// 现在，为 parting 记录一个值
+span.record("parting", &"goodbye world!");
+```
+
+#### 格式化字符串
+除了以字段的方式记录信息，我们还可以使用格式化字符串的方式( 同 `println!` 、`format!` )。
+
+> 注意，当字段跟格式化的方式混用时，必须把格式化放在最后，如下所示
+
+```rust
+let question = "the ultimate question of life, the universe, and everything";
+let answer = 42;
+event!(
+    Level::DEBUG,
+    question.answer = answer,
+    question.tricky = true,
+    "the answer to {} is {}.", question, answer
+);
+
+// 日志输出 -> DEBUG test_tracing: the answer to the ultimate question of life, the universe, and everything is 42. question.answer=42 question.tricky=true
+```
+
+## 文件输出
+截至目前，我们上面的日志都是输出到控制台中。
+
+针对文件输出，`tracing` 提供了一个专门的库 [tracing-appender](https://github.com/tokio-rs/tracing/tree/master/tracing-appender)，大家可以查看官方文档了解更多。
+
+
+## 总结 & 推荐
+至此，`tracing` 的介绍就已结束，相信大家都看得出，它比上个章节的 `log` 及兄弟们要更加复杂一些，一方面是因为它能更好的支持异步编程环境，另一方面就是它还是一个分布式追踪的库，对于后者，我们将在后续的监控章节进行讲解。
+
+如果你让我推荐使用哪个，那我的建议是:
+
+- 对于简单的工程，例如用于 POC（ Proof of Concepts ） 目的，使用 `log` 即可
+- 对于需要认真对待，例如生产级或优秀的开源项目，建议使用 tracing 的方式，一举解决日志和监控的后顾之忧