【跟小嘉学 Rust 编程】三十一、Rust的日志与追踪

前言

本章节讲解日志与监控系统的可观测性(Observability) 通常由三个维度日志(Logging)、指标(Metric)和追踪(Tracing)。

• 日志离散的错误信息和状态信息
• 指标记录和呈现可聚合的数据
• 追踪单个请求的一系列事件

主要教材参考 《The Rust Programming Language》
主要教材参考 《Rust For Rustaceans》
主要教材参考 《The Rustonomicon》
主要教材参考 《Rust 高级编程》
主要教材参考 《Cargo 指南》
主要教材参考 《Rust 异步编程》

---

一、日志详解

1.1、 日志级别

日志级别是对基本的“滚动文本”式日志记录的一个重要补充。每条日志消息都回基于其重要性或严重程度分配到一个日志级别。

• Fatal程序发生致命错误此类错误往往来自于程序逻辑的严重异常例如无法分配足够的硬盘空间、内存不足等建议立即退出或重启程序
• Error错误一般指的是程序级别的错误或严重的业务错误但是这种错误并不会影响程序的运行。
• Warn警告说明这条记录需要注意但是不确定是否发生了错误因粗需要相关的开发人员来辨别。
• Info信息此类往往用于记录程序的运行信息例如用户操作或状态的变化
• Debug调试信息是给开发者用的应用了解程序当前的详细运行状况例如请求信息追踪等

1.2、输出位置

一般而言日志可以输出的两个地方终端控制台(标准输出/标准错误)和文件。

如果没有日志持久化的需求你只是为了调试程序建议输出到控制台即可。悄悄的说一句我们还可以为不同的级别设定不同的输出位置例如 Debug 日志输出到控制台既方便开发查看但又不会占用硬盘而 Info 和 Warning 日志可以输出到文件 info.log 中至于 Error、Fatal 则可以输出到 error.log 中。

1.3、日志的查看

• 可以使用 tail、cat、grep等命令
• 打开文件搜索
• 在可视化界面配合日志采集工具到 ElasticSearch 或其他搜索平台然后通过 kibana、grafana 等进行搜索查看。

1.4、日志采集

我们可以使用日志采集工具去控制台等标准输出读取日志数据然后将读取到的数据发送给到日志存储平台(ElasticSearch).

目前常用的日志采集工具有filebeat、vector等他们都是以 agent 的形式运行在你的应用程序旁边

二、日志门面(logging facade)

2.1、日志门面介绍

就如同 slf4j 是 Java 的日志门面库log 也是 Rust 的日志门面库目前由官方积极维护。

cargo add log

既然是门面log 自然定义了一套统一的日志特征和API将日志的操作进行了抽象定义。

2.1、Log 特征

pub trait Log: Sync + Send {
    fn enabled(&self, metadata: &Metadata<'_>) -> bool;
    fn log(&self, record: &Record<'_>);
    fn flush(&self);
}

• enabled用于判断某条带有元数据的日志是否能被记录它对于 log_enabled宏特别有用
• log回记录 record 所代表的日志
• flush回将缓存中的日志刷到输出中例如标准输出或文件

2.2、日志宏

log 为我们不同的日志级别提供了不同的日志宏

use log::{info, trace, warn};

pub fn shave_the_yak(yak: &mut Yak) {
    trace!("Commencing yak shaving");

    loop {
        match find_a_razor() {
            Ok(razor) => {
                info!("Razor located: {}", razor);
                yak.shave(razor);
                break;
            }
            Err(err) => {
                warn!("Unable to locate a razor: {}, retrying", err);
            }
        }
    }
}

2.3、日志输出

log 仅仅是日志门面库不具备完整的日志库功能。如果你是 rust 库的开发者只要在库中使用门面库即可具体的日志库交由用户选择和绑定

2.3.1、env_logger

1、添加依赖

cargo add env_logger

2、使用

use log::{debug, error, log_enabled, info, Level};

fn main() {
    // 注意env_logger 必须尽可能早的初始化
    env_logger::init();

    debug!("this is a debug {}", "message");
    error!("this is printed by default");

    if log_enabled!(Level::Info) {
        let x = 3 * 4; // expensive computation
        info!("the answer was: {}", x);
    }
}

此时i可以通过环境变量(RUST_LOG)设置日志级别

默认情况下env_logger 会输出到标错误如果你要输出到标准输出 可以使用 builder 来改变日志对象(target);

2.3.2、实现 log 特征

use log::{Record, Level, Metadata};
struct SimpleLogger;
impl log::Log for SimpleLogger {
    fn enabled(&self, metadata: &Metadata) -> bool {
        metadata.level() <= Level::Info
    }
    fn log(&self, record: &Record) {
        if self.enabled(record.metadata()) {
            println!("{} - {}", record.level(), record.args());
        }
    }
    fn flush(&self) {}
}

三、追踪(tracing)

3.1、追踪(tracing)

随着微服务的流行现在一个产品有多个系统组成是非常常见的这种情况下一条用户请求可能会横跨几个甚至几十个服务。此时再用传统的日志方式去跟踪这条用户请求就变得较为困难这就是分布式追踪在现代化监控系统中这么炽手可热的原因。

关于分布式追踪在后面的监控章节进行详细介绍大家只要知道分布式追踪的核心就是在请求的开始生成一个 trace_id然后将该 trace_id 一直往后透穿请求经过的每个服务都会使用该 trace_id 记录相关信息最终将整个请求形成一个完整的链路予以记录下来。

那么后面当要查询这次请求的相关信息时只要使用 trace_id 就可以获取整个请求链路的所有信息了非常简单好用。看到这里相信大家也明白为什么这个库的名称叫 tracing 了吧

至于为何把它归到日志库的范畴呢因为 tracing 支持 log 门面库的 API因此它既可以作为分布式追踪的 SDK 来使用也可以作为日志库来使用。

在分布式追踪中trace_id 都是由 SDK 自动生成和往后透穿对于用户的使用来说是完全透明的。如果你要手动用日志的方式来实现请求链路的追踪那么就必须考虑 trace_id 的手动生成、透传以及不同语言之间的协议规范等问题

3.2、使用

3.2.1、添加依赖

cargo add tracing

3.2.1、使用

use log;
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};

fn main() {
    // 只有注册 subscriber 后 才能在控制台上看到日志输出
    tracing_subscriber::registry()
        .with(fmt::layer())
        .init();
    
    // 调用 `log` 包的 `info!`
    log::info!("Hello world");
    
    let foo = 42;
    // 调用 `tracing` 包的 `info!`
    tracing::info!(foo, "Hello from tracing");
}

tracing 在 API上使用了 log 的规范。

3.3、异步编程中使用

在异步编程中异步任务的执行没有确定的顺序那么输出的日志将没有确定的日志并混在一起无法按照我们想要的逻辑顺序串联起来。

归根到底在于日志只能针对某个时间点进行记录缺乏上下文信息而线程间的执行顺序又是不确定的因此日志就有些无能为力。而 tracing 为了解决这个问题引入了 span 的概念( 这个概念也来自于分布式追踪 )一个 span 代表了一个时间段拥有开始和结束时间在此期间的所有类型数据、结构化数据、文本数据都可以记录其中。

大家发现了吗 span 是可以拥有上下文信息的这样就能帮我们把信息按照所需的逻辑性串联起来了。

3.4、tracing的核心概念

3.4.1、span

相比起日志只能记录在某个时间点发生的事件span 最大的意义就在于它可以记录一个过程也就是在某一段时间内发生的事件流。既然是记录时间段那自然有开始和结束:

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` 也随之结束

3.4.2、event

Event 代表了某个时间点发生的事件这方面它跟日志类似但是不同的是Event 还可以产生在 span 的上下文中。

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");
}

虽然 event 在哪里都可以使用但是最好只在 span 的上下文中使用用于代表一个时间点发生的事件例如记录 HTTP 请求返回的状态码从队列中获取一个对象等等。

3.4.3、collector

当 Span 或 Event 发生时它们会被实现了 Collect 特征的收集器所记录或聚合。这个过程是通过通知的方式实现的当 Event 发生或者 Span 开始/结束时会调用 Collect 特征的相应方法通知 Collector。

3.5、tracing-subscriber

只有使用了 tracing-subscriber 日志才会输出到控制台

cargo add tracing-subscriber

3.6、#[instrument]

如果想要将某个函数的整个函数体都设置为 span 的范围最简单的方法就是为函数标记上 #[instrument]此时 tracing 会自动为函数创建一个 spanspan 名跟函数名相同在输出的信息中还会自动带上函数参数。

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);
}

对于没有内置 tracing 支持或者无法使用 #instrument 的函数例如外部库的函数我们可以使用 Span 结构体的 in_scope 方法它可以将同步代码包裹在一个 span 中