Lewati ke konten
Ferris the Rust crabTutorial Rust

Logging di Rust dengan log dan tracing

Saat ada yang salah di sebuah program, kamu ingin tahu apa yang sedang dikerjakannya tepat sebelum itu terjadi. Untuk itulah logging (pencatatan log) ada. Log itu seperti buku harian kapal: catatan-catatan pendek, masing-masing dengan waktu dan tingkat kepentingan, yang bisa kamu baca nanti untuk memahami apa yang terjadi.

Kamu bisa saja menaburkan println! di mana-mana, tapi kamu akan segera menemui batasnya. Kamu tidak bisa mematikannya tanpa mengubah kode. Kamu tidak bisa bilang “tampilkan peringatannya saja”. Dan catatan debug-mu jadi tercampur dengan output program yang sebenarnya. Crate (library Rust) untuk logging menyelesaikan ketiga masalah itu. Di halaman ini kamu akan belajar dua yang paling populer: log (bersama env_logger) dan tracing.

Kenapa tidak println! saja?

Section titled “Kenapa tidak println! saja?”

Ini perbedaannya dalam satu tabel:

println! crate logging
Menyalakan/mematikan tanpa compile ulang Tidak Ya, dengan variabel RUST_LOG
Level (error, warn, info, …) Tidak Ya
Menunjukkan asal pesan Tidak Ya (nama modul)
Ke mana pesannya pergi stdout stderr secara default (env_logger)

Baris terakhir itu lebih penting daripada kelihatannya. stdout adalah hasil program yang sebenarnya, yang mungkin di-pipe seseorang ke file atau ke program lain. stderr adalah jalur samping untuk pesan tentang jalannya program. Log tempatnya di stderr, sehingga my_app > hasil.txt hanya menyimpan hasilnya, sementara log tetap muncul di terminal.

Facade log dan env_logger

Section titled “Facade log dan env_logger”

Crate log memberimu lima makro, satu per level, dari yang paling serius sampai yang paling ringan: error!, warn!, info!, debug!, dan trace!. Cara pakainya sama persis seperti println!, dengan format {} yang sama.

Tapi log sendiri tidak mencetak apa pun. Ia adalah sebuah facade: sekumpulan makro standar yang bisa dipakai setiap library, tanpa harus memilih bagaimana pesannya ditampilkan. Aplikasimu yang memilih sebuah logger untuk benar-benar menuliskannya. Yang paling sederhana adalah env_logger. Tambahkan keduanya ke proyekmu:

Terminal window
cargo add log env_logger
[dependencies]
log = "0.4"
env_logger = "0.11"

Sekarang panggil env_logger::init() sekali, di awal main, lalu silakan mencatat log:

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


fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide dipanggil dengan a={a}, b={b}");
    if b == 0.0 {
        warn!("menolak membagi {a} dengan nol");
        return None;
    }
    Some(a / b)
}


fn main() {
    env_logger::init();
    info!("kalkulator dimulai");


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


    error!("beginilah tampilan baris error");
}

Output:

10 / 4 = Some(2.5)
1 / 0 = None
▶ Coba sendiri

Output di atas hanya stdout, yaitu hasil program yang sebenarnya. Baris-baris log pergi ke stderr. Di Playground, baris itu muncul di bagian terpisah bernama “Standard Error”.

Perhatikan satu hal: secara default, env_logger hanya menampilkan error. Untuk melihat lebih banyak, atur variabel lingkungan RUST_LOG saat menjalankan program. Ini tampilan stderr dan stdout bersama-sama saat kami menjalankannya di terminal dengan RUST_LOG=debug cargo run (setiap timestamp kami ganti dengan …; punyamu akan menampilkan tanggal dan jam saat itu):

[… INFO  my_app] kalkulator dimulai
[… DEBUG my_app] divide dipanggil dengan a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide dipanggil dengan a=1, b=0
[… WARN  my_app] menolak membagi 1 dengan nol
1 / 0 = None
[… ERROR my_app] beginilah tampilan baris error

Setiap baris log menunjukkan level dan modul asalnya (my_app, nama crate-nya). Baris biasa tanpa kurung siku adalah output println!.

Memilih apa yang tampil dengan RUST_LOG

Section titled “Memilih apa yang tampil dengan RUST_LOG”

Sebuah level menampilkan level itu dan semua yang lebih serius. Jadi RUST_LOG=warn menampilkan peringatan dan error; RUST_LOG=trace menampilkan semuanya.

Terminal window
RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # hanya warn dan error
RUST_LOG=off cargo run       # tidak ada log sama sekali

Di Windows PowerShell, atur variabelnya dulu: $env:RUST_LOG="debug"; cargo run.

Kamu juga bisa memfilter per modul. Ini sangat membantu kalau ada library yang terlalu “cerewet”, atau kalau kamu hanya peduli pada satu bagian kodemu. Ini program dengan modul db:

use log::{debug, info};


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


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


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


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


    debug!("semua pencarian selesai");
}

Output:

pengguna 1: Ada
pengguna 3: tidak ditemukan
▶ Coba sendiri

Beberapa filter yang kami coba, dan apa yang tercetak di stderr (timestamp diganti dengan …):

$ RUST_LOG=my_app=trace cargo run       # semua dari crate kita
[… INFO  my_app] server dimulai
[… TRACE my_app::db] mencari pengguna 1
[… DEBUG my_app::db] hasil pencarian: Some("Ada")
pengguna 1: Ada
[… TRACE my_app::db] mencari pengguna 3
[… DEBUG my_app::db] hasil pencarian: None
pengguna 3: tidak ditemukan
[… DEBUG my_app] semua pencarian selesai


$ RUST_LOG=my_app::db=debug cargo run   # hanya modul db, debug ke atas
[… DEBUG my_app::db] hasil pencarian: Some("Ada")
pengguna 1: Ada
[… DEBUG my_app::db] hasil pencarian: None
pengguna 3: tidak ditemukan

Kamu bisa menggabungkan beberapa aturan dengan koma: RUST_LOG=info,my_app::db=trace artinya “info untuk semuanya, tapi trace untuk modul db”. Ada satu jebakan kecil: filternya memakai nama crate dengan garis bawah. Paket bernama my-app mencatat log sebagai my_app.

Mengatur level default di kode

Section titled “Mengatur level default di kode”

Sering kali kamu ingin info tetap tampil walaupun RUST_LOG tidak diatur. Pakai env_logger::Builder sebagai ganti init(). Kamu juga bisa mematikan timestamp, yang praktis untuk tool kecil:

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


fn main() {
    // Tampilkan `info` ke atas, kecuali RUST_LOG bilang lain.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();


    info!("aplikasi dimulai");
    debug!("ini hanya terlihat dengan RUST_LOG=debug");


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

Output:

total = 55
▶ Coba sendiri

Tanpa timestamp, stderr asli dari cargo run jadi pendek dan bersih:

[INFO  my_app] aplikasi dimulai

Logging terstruktur dengan tracing

Section titled “Logging terstruktur dengan tracing”

log memberimu baris-baris teks. tracing memberimu event yang membawa data, dikelompokkan ke dalam span. Crate ini dibuat oleh tim Tokio, dan dipakai oleh framework web async seperti axum. Tambahkan seperti ini:

Terminal window
cargo add tracing tracing-subscriber

Ada tiga ide yang perlu dipelajari:

  • Event mirip baris log: info!, warn!, dan teman-temannya, dengan nama yang sama seperti di log.
  • Field melampirkan data dalam bentuk key = value: info!(user_id = 42, "berhasil login"). Tool lain bisa mencari dan memfilter berdasarkan field ini, tanpa harus mem-parse teks.
  • Span menggambarkan satu rentang pekerjaan, misalnya “memproses pesanan 7”. Setiap event di dalam span diberi tanda span tersebut.

Sama seperti log, tracing butuh sebuah subscriber untuk menampilkan apa pun. tracing_subscriber::fmt() adalah subscriber standarnya. Ada satu kejutan: secara default ia menulis ke stdout, jadi kita arahkan ke stderr dengan .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, "berhasil login");


    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, "total keranjang dihitung");


    if total > 2000 {
        warn!(total, limit = 2000, "pesanan perlu dicek manual");
    }


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

Output:

total pesanan: 2549
▶ Coba sendiri

Ini stderr dari program yang kami jalankan (timestamp diganti dengan …, warna dihapus):

…  INFO my_app: berhasil login user_id=42
…  INFO checkout{order_id=7}: my_app: total keranjang dihitung items=3 total=2549
…  WARN checkout{order_id=7}: my_app: pesanan perlu dicek manual total=2549 limit=2000

Lihat bagaimana dua baris terakhir diawali checkout{order_id=7}? Itulah span-nya. Selama _guard masih hidup, setiap event berada “di dalam” checkout. Menulis total saja adalah singkatan dari total = total.

#[instrument]: satu span untuk setiap pemanggilan

Section titled “#[instrument]: satu span untuk setiap pemanggilan”

Membuat span secara manual lama-lama melelahkan. Pasang #[instrument] di atas sebuah fungsi, dan tracing akan membuat span untuk setiap pemanggilan, dengan argumen-argumennya dicatat sebagai field (argumennya harus mengimplementasikan Debug):

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


#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "diskon dihitung");
    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, "selesai");
    println!("harga akhir: {final_price}");
}

Output:

harga akhir: 2250
▶ Coba sendiri

stderr dari program yang kami jalankan:

… DEBUG apply_discount{price=2500 percent=10}: my_app: diskon dihitung off=250
…  INFO my_app: selesai final_price=2250

Subscriber fmt() menampilkan info ke atas kecuali kamu bilang lain. Itu sebabnya kita menulis .with_max_level(tracing::Level::DEBUG). Kalau kamu ingin RUST_LOG bekerja seperti di env_logger, nyalakan fitur env-filter dan pakai 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();

Mana yang sebaiknya kamu pilih?

Section titled “Mana yang sebaiknya kamu pilih?”
  • Tool CLI kecil atau skrip? log + env_logger. Setup-nya sangat sedikit, teks biasa, beres.
  • Web server, kode async, atau banyak tugas sekaligus? tracing. Span mencatat sebuah pesan berasal dari request mana, bahkan saat ratusan request berjalan bersamaan.
  • Menulis library? Pakai makronya saja (log atau tracing) dan jangan pernah memanggil init(). Aplikasilah yang memutuskan bagaimana log ditampilkan.

Pilihanmu tidak harus untuk selamanya. Setup default tracing-subscriber juga menangkap pesan dari crate log, jadi library yang memakai salah satunya tetap muncul bersama-sama.

Kesalahan umum

Section titled “Kesalahan umum”

Lupa memasang logger. Kalau kamu tidak pernah memanggil env_logger::init() (atau init() milik subscriber tracing), makronya tetap ter-compile dengan lancar dan mencetak… tidak ada apa-apa. Tidak ada error, tidak ada peringatan. Kalau log-mu menghilang, periksa ini dulu, lalu periksa RUST_LOG.

Memanggil init() dua kali. Hanya boleh ada satu logger global. Pemanggilan kedua akan panic. Ini pesan aslinya (pesan Rust dan env_logger, jadi tetap dalam bahasa Inggris; intinya: init tidak boleh dipanggil setelah logger sudah dipasang):

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(())

Panggil sekali saja, di bagian paling atas main. Di test, pakai let _ = env_logger::builder().is_test(true).try_init();, yang mengembalikan error alih-alih panic.

Membuang span guard seketika. let _ = span.enter(); kelihatannya tidak berbahaya, tapi _ bukan nama variabel: guard-nya langsung di-drop di baris yang sama, jadi span-nya langsung berakhir. Program kami mencetak INFO my_app: menangani request tanpa span sama sekali. Beri nama pada guard-nya, misalnya let _guard = span.enter();, supaya ia hidup sampai akhir cakupan (scope).

Ringkasan

Section titled “Ringkasan”
  • Pakai crate logging alih-alih println!, supaya kamu bisa memfilter per level dan menyimpan log di stderr, terpisah dari output yang sebenarnya.
  • log memberimu error!, warn!, info!, debug!, trace!; env_logger::init() yang mencetaknya.
  • RUST_LOG mengatur apa yang kamu lihat: RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace.
  • tracing menambahkan field terstruktur (info!(user_id = 42, "berhasil login")) dan span; #[instrument] membuat satu span per pemanggilan fungsi.
  • Library hanya memakai makronya; aplikasi memasang logger satu kali.

Kuis singkat

Section titled “Kuis singkat”

Kuis singkat

1. Kamu menjalankan program yang memakai env_logger tanpa mengatur RUST_LOG. Baris log mana yang terlihat?

2. Ke mana env_logger menulis pesan log secara default?

3. Apa yang ditampilkan oleh RUST_LOG=warn?

4. Apa efek memasang #[instrument] pada sebuah fungsi?

5. Kamu sedang menulis crate library. Apa yang sebaiknya dilakukan soal logging?

Skor: 0 / 5

Bacaan lebih lanjut

Section titled “Bacaan lebih lanjut”