Ghi log trong Rust với log và tracing

Khi có gì đó trục trặc trong chương trình, bạn muốn biết ngay trước đó nó đang làm gì. Đó là công việc của việc ghi log (logging). Một bản log giống như nhật ký hải trình của một con tàu: những ghi chú ngắn, mỗi dòng có thời gian và mức độ quan trọng, để sau này bạn đọc lại và hiểu chuyện gì đã xảy ra.

Bạn có thể rải println! khắp nơi, nhưng sẽ sớm gặp giới hạn của nó. Bạn không thể tắt nó mà không sửa code. Bạn không thể nói “chỉ cho tôi xem các cảnh báo”. Và nó trộn ghi chú gỡ lỗi của bạn vào kết quả thật của chương trình. Các crate ghi log của Rust giải quyết cả ba vấn đề. Trên trang này, bạn sẽ học hai crate phổ biến nhất: log (cùng env_logger) và tracing.

Các thông điệp log và chuỗi in ra trong ví dụ được giữ bằng tiếng Anh, vì chúng xuất hiện trong những đoạn kết quả thật mà chúng tôi đã chạy trên terminal.

Sao không dùng luôn println!?

Đây là sự khác biệt gói gọn trong một bảng:

	println!	một crate ghi log
Bật/tắt không cần biên dịch lại	Không	Có, bằng biến RUST_LOG
Các mức (error, warn, info, …)	Không	Có
Cho biết thông điệp đến từ đâu	Không	Có (tên module)
Ghi ra đâu	stdout	mặc định là stderr (env_logger)

Dòng cuối quan trọng hơn bạn tưởng. stdout là kết quả thật của chương trình, thứ mà ai đó có thể chuyển (pipe) vào một file hay một chương trình khác. stderr là kênh phụ cho những thông điệp về lần chạy. Log thuộc về stderr, nên my_app > result.txt chỉ lưu kết quả, còn log vẫn hiện ra trên terminal.

Facade log và env_logger

Crate log cho bạn năm macro, mỗi macro một mức, từ nghiêm trọng nhất đến ít nghiêm trọng nhất: error!, warn!, info!, debug! và trace!. Chúng hoạt động giống hệt println!, cùng cách định dạng {}.

Nhưng tự mình thì log không in ra gì cả. Nó là một facade (mặt tiền): một bộ macro chuẩn mà thư viện nào cũng dùng được, mà không phải chọn cách hiển thị thông điệp. Ứng dụng của bạn chọn một logger để thật sự ghi chúng ra. Logger đơn giản nhất là env_logger. Thêm cả hai vào dự án:

cargo add log env_logger

[dependencies]
log = "0.4"
env_logger = "0.11"

Giờ gọi env_logger::init() một lần, ở đầu main, rồi cứ thế ghi log:

use log::{debug, error, info, warn};

fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide called with a={a}, b={b}");
    if b == 0.0 {
        warn!("refusing to divide {a} by zero");
        return None;
    }
    Some(a / b)
}

fn main() {
    env_logger::init();
    info!("calculator starting");

    println!("10 / 4 = {:?}", divide(10.0, 4.0));
    println!("1 / 0 = {:?}", divide(1.0, 0.0));

    error!("this is what an error line looks like");
}

Kết quả:

10 / 4 = Some(2.5)
1 / 0 = None

▶ Tự chạy thử

Kết quả ở trên chỉ là stdout, tức kết quả thật của chương trình. Các dòng log đi ra stderr. Trên Playground, chúng hiện ở khu vực “Standard Error” riêng.

Hãy để ý một điều: mặc định, env_logger chỉ hiện lỗi (error). Để thấy nhiều hơn, hãy đặt biến môi trường RUST_LOG khi chạy chương trình. Đây là stderr và stdout trông như thế nào khi chúng tôi chạy nó trên terminal với RUST_LOG=debug cargo run (chúng tôi thay mỗi dấu thời gian bằng …; của bạn sẽ hiện ngày giờ hiện tại):

[… INFO  my_app] calculator starting
[… DEBUG my_app] divide called with a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide called with a=1, b=0
[… WARN  my_app] refusing to divide 1 by zero
1 / 0 = None
[… ERROR my_app] this is what an error line looks like

Mỗi dòng log cho thấy mức và module mà nó đến từ (my_app, tên của crate). Những dòng trơn không có ngoặc vuông là kết quả của println!.

Chọn những gì bạn muốn thấy với RUST_LOG

Một mức sẽ hiện mức đó và mọi mức nghiêm trọng hơn. Vì vậy RUST_LOG=warn hiện cảnh báo và lỗi; RUST_LOG=trace hiện tất cả.

RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # chỉ warn và error
RUST_LOG=off cargo run       # không có log nào

Trên Windows PowerShell, hãy đặt biến trước: $env:RUST_LOG="debug"; cargo run.

Bạn cũng có thể lọc theo module. Điều này rất tiện khi một thư viện quá “lắm lời”, hoặc khi bạn chỉ quan tâm tới một phần code của mình. Đây là một chương trình có module db:

use log::{debug, info};

mod db {
    use log::{debug, trace};

    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("looking up user {id}");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("lookup result: {name:?}");
        name
    }
}

fn main() {
    env_logger::init();
    info!("server starting");

    for id in [1, 3] {
        match db::find_user(id) {
            Some(name) => println!("user {id}: {name}"),
            None => println!("user {id}: not found"),
        }
    }

    debug!("all lookups done");
}

Kết quả:

user 1: Ada
user 3: not found

▶ Tự chạy thử

Một vài bộ lọc chúng tôi đã thử, và những gì chúng in ra stderr (dấu thời gian được thay bằng …):

$ RUST_LOG=my_app=trace cargo run       # everything from our crate
[… INFO  my_app] server starting
[… TRACE my_app::db] looking up user 1
[… DEBUG my_app::db] lookup result: Some("Ada")
user 1: Ada
[… TRACE my_app::db] looking up user 3
[… DEBUG my_app::db] lookup result: None
user 3: not found
[… DEBUG my_app] all lookups done

$ RUST_LOG=my_app::db=debug cargo run   # only the db module, debug and up
[… DEBUG my_app::db] lookup result: Some("Ada")
user 1: Ada
[… DEBUG my_app::db] lookup result: None
user 3: not found

Bộ lọc đầu tiên hiện mọi thứ từ crate của chúng ta; bộ lọc thứ hai chỉ hiện module db, từ mức debug trở lên. Bạn có thể kết hợp nhiều quy tắc bằng dấu phẩy: RUST_LOG=info,my_app::db=trace nghĩa là “mức info cho mọi thứ, nhưng mức trace cho module db”. Một cái bẫy nhỏ: bộ lọc dùng tên crate với dấu gạch dưới. Một package tên my-app sẽ ghi log dưới tên my_app.

Đặt mức mặc định trong code

Thường thì bạn muốn info vẫn hiện ra ngay cả khi RUST_LOG chưa được đặt. Hãy dùng env_logger::Builder thay vì init(). Bạn cũng có thể tắt dấu thời gian, rất tiện cho các công cụ nhỏ:

use env_logger::Env;
use log::{debug, info};

fn main() {
    // Hiện `info` trở lên, trừ khi RUST_LOG nói khác.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();

    info!("app started");
    debug!("you only see this with RUST_LOG=debug");

    let total: u32 = (1..=10).sum();
    println!("total = {total}");
}

Kết quả:

total = 55

▶ Tự chạy thử

Không có dấu thời gian, stderr thật từ cargo run ngắn gọn và sạch sẽ:

[INFO  my_app] app started

Log có cấu trúc với tracing

log cho bạn những dòng văn bản. tracing cho bạn sự kiện kèm dữ liệu, được gom vào các span. Nó do đội ngũ Tokio xây dựng, và là thứ mà các web framework bất đồng bộ (async) như axum sử dụng. Thêm nó như sau:

cargo add tracing tracing-subscriber

Ba ý tưởng cần học:

• Event (sự kiện) giống như các dòng log: info!, warn! và các anh em, cùng tên với trong log.
• Field (trường) gắn dữ liệu dưới dạng key = value: info!(user_id = 42, "logged in"). Các công cụ có thể tìm kiếm và lọc theo những trường này, thay vì phải phân tích văn bản.
• Span mô tả một quãng công việc, như “đang xử lý đơn hàng 7”. Mọi event bên trong một span đều được gắn nhãn span đó.

Giống log, tracing cần một subscriber để hiển thị bất cứ thứ gì. tracing_subscriber::fmt() là subscriber chuẩn. Một điều bất ngờ: mặc định nó ghi ra stdout, nên ta chuyển nó sang stderr bằng .with_writer(std::io::stderr):

use tracing::{info, info_span, warn};

fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stderr)
        .init();

    info!(user_id = 42, "logged in");

    let span = info_span!("checkout", order_id = 7);
    let _guard = span.enter();

    let items = [1200, 350, 999];
    let total: u32 = items.iter().sum();
    info!(items = items.len(), total, "cart totalled");

    if total > 2000 {
        warn!(total, limit = 2000, "order needs manual review");
    }

    println!("order total: {total}");
}

Kết quả:

order total: 2549

▶ Tự chạy thử

Đây là stderr từ lần chạy của chúng tôi (dấu thời gian được thay bằng …, đã bỏ màu):

…  INFO my_app: logged in user_id=42
…  INFO checkout{order_id=7}: my_app: cart totalled items=3 total=2549
…  WARN checkout{order_id=7}: my_app: order needs manual review total=2549 limit=2000

Bạn thấy hai dòng cuối bắt đầu bằng checkout{order_id=7} chứ? Đó là span. Chừng nào _guard còn sống, mọi event đều nằm “bên trong” checkout. Viết total không thôi là cách viết tắt của total = total.

#[instrument]: một span cho mỗi lời gọi

Tự tạo span bằng tay mãi cũng mệt. Hãy đặt #[instrument] lên một hàm, và tracing sẽ tạo một span cho mỗi lời gọi, ghi lại các đối số dưới dạng field (chúng cần cài đặt Debug):

use tracing::{debug, info, instrument};

#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "discount computed");
    price - off
}

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::DEBUG)
        .with_writer(std::io::stderr)
        .init();

    let final_price = apply_discount(2500, 10);
    info!(final_price, "done");
    println!("final price: {final_price}");
}

Kết quả:

final price: 2250

▶ Tự chạy thử

stderr từ lần chạy của chúng tôi:

… DEBUG apply_discount{price=2500 percent=10}: my_app: discount computed off=250
…  INFO my_app: done final_price=2250

Subscriber fmt() hiện info trở lên trừ khi bạn bảo khác; đó là lý do ta đặt .with_max_level(tracing::Level::DEBUG). Nếu bạn muốn RUST_LOG hoạt động giống như với env_logger, hãy bật feature env-filter và dùng EnvFilter:

[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter"] }

use tracing_subscriber::EnvFilter;

tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::from_default_env())
    .with_writer(std::io::stderr)
    .init();

Nên chọn cái nào?

• Công cụ dòng lệnh nhỏ hay script? log + env_logger. Thiết lập tí xíu, văn bản thuần, xong.
• Web server, code bất đồng bộ, hay nhiều tác vụ chạy cùng lúc? tracing. Span giúp theo dõi một thông điệp thuộc về request nào, ngay cả khi hàng trăm request chạy cùng lúc.
• Đang viết một thư viện? Chỉ dùng các macro (log hoặc tracing) và không bao giờ gọi init(). Ứng dụng sẽ quyết định cách hiển thị log.

Bạn không phải chọn một lần cho mãi mãi. Thiết lập mặc định của tracing-subscriber cũng nhận các thông điệp từ crate log, nên các thư viện dùng cái nào thì log cũng hiện ra cùng nhau.

Lỗi thường gặp

Quên thiết lập logger. Nếu bạn không bao giờ gọi env_logger::init() (hoặc init() của một subscriber tracing), các macro vẫn biên dịch bình thường và in ra… không gì cả. Không lỗi, không cảnh báo. Nếu log của bạn biến mất, hãy kiểm tra điều này trước tiên, rồi kiểm tra RUST_LOG.

Gọi init() hai lần. Chỉ có thể có một logger toàn cục. Lời gọi thứ hai sẽ panic. Đây là thông báo thật:

thread 'main' (12345) panicked at …/env_logger-0.11.11/src/logger.rs:901:16:
env_logger::init should not be called after logger initialized: SetLoggerError(())

Thông báo panic nói rằng không được gọi env_logger::init sau khi logger đã được khởi tạo. Hãy gọi nó một lần, ở ngay đầu main. Trong test, hãy dùng let _ = env_logger::builder().is_test(true).try_init();, cách này trả về lỗi thay vì panic.

Drop span guard ngay lập tức. let _ = span.enter(); trông vô hại, nhưng _ không phải là tên biến: guard bị drop ngay trên dòng đó, nên span kết thúc ngay lập tức. Lần chạy của chúng tôi in ra INFO my_app: handling request mà không có span nào cả. Hãy đặt tên cho guard, như let _guard = span.enter();, để nó sống tới cuối phạm vi.

Tóm tắt

• Dùng một crate ghi log thay vì println! để có thể lọc theo mức và giữ log ở stderr, tách khỏi kết quả thật.
• log cho bạn error!, warn!, info!, debug!, trace!; env_logger::init() in chúng ra.
• RUST_LOG điều khiển những gì bạn thấy: RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace.
• tracing thêm field có cấu trúc (info!(user_id = 42, "logged in")) và span; #[instrument] tạo một span cho mỗi lời gọi hàm.
• Thư viện chỉ dùng macro; ứng dụng thiết lập logger một lần.

Kiểm tra nhanh

Kiểm tra nhanh

1. Bạn chạy một chương trình dùng env_logger mà không đặt RUST_LOG. Bạn thấy những dòng log nào?

Tất cả Chỉ info! trở lên Chỉ error! Không dòng nào

2. Mặc định env_logger ghi thông điệp log ra đâu?

stdout stderr Một file tên log.txt

3. RUST_LOG=warn hiện những gì?

Chỉ cảnh báo Cảnh báo và mọi thứ ít nghiêm trọng hơn Cảnh báo và lỗi

4. Đặt #[instrument] lên một hàm có tác dụng gì?

Đo thời gian hàm chạy và in ra Tạo một span cho mỗi lời gọi, với các đối số là field Làm hàm chạy nhanh hơn Bật ghi log cho toàn bộ chương trình

5. Bạn đang viết một crate thư viện. Nó nên làm gì với việc ghi log?

Dùng các macro ghi log, nhưng để ứng dụng thiết lập logger Gọi env_logger::init() khi thư viện được nạp Dùng println! để lúc nào cũng hiện ra

Điểm: 0 / 5

Đọc thêm

• Tài liệu crate log (tiếng Anh): năm macro và cách facade hoạt động, kèm lời khuyên cho tác giả thư viện.
• Tài liệu env_logger (tiếng Anh): cú pháp RUST_LOG đầy đủ và mọi tùy chọn của Builder.
• Tài liệu tracing (tiếng Anh): span, event, field và #[instrument] một cách chi tiết.
• Tài liệu tracing-subscriber (tiếng Anh): các tùy chọn định dạng, EnvFilter và kết quả dạng JSON.
• Getting started with Tracing — Tokio (tiếng Anh): hướng dẫn thân thiện từ chính đội ngũ duy trì tracing.