Rustのログ出力（log と tracing）

プログラムで何か問題が起きたとき、知りたいのは「その直前に何をしていたか」です。それを教えてくれるのがログ（log）です。ログは船の航海日誌のようなものです。時刻と重要度のついた短いメモが並んでいて、あとから読み返すと何が起きたのかがわかります。

あちこちに println! を書くこともできますが、すぐに限界にぶつかります。コードを書き換えないとオフにできません。「警告だけ見せて」とも言えません。しかも、デバッグ用のメモがプログラムの本当の出力に混ざってしまいます。Rustのログ用クレートを使えば、この3つの問題をすべて解決できます。このページでは、特によく使われる2つ、log（と env_logger）と tracing を学びます。

`println!` ではだめなの？

違いを1つの表にまとめると、こうなります。

	`println!`	ログ用クレート
再コンパイルせずにオン・オフできる	いいえ	はい（`RUST_LOG` 環境変数で）
レベル（error、warn、info など）	なし	あり
メッセージがどこから来たかわかる	いいえ	はい（モジュール名）
出力先	stdout	標準では stderr（env_logger）

最後の行は、見た目以上に大切です。stdout（標準出力）は、プログラムの本当の結果です。誰かがファイルや別のプログラムにパイプで渡すかもしれないものです。stderr（標準エラー出力）は、実行についてのメッセージのための別の通り道です。ログは stderr に出すべきものです。そうすれば my_app > result.txt としたときに結果だけが保存され、ログはそのままターミナルに表示されます。

logファサードとenv_logger

log クレートには、レベルごとに1つずつ、5つのマクロがあります。重要なものから順に、error!、warn!、info!、debug!、trace! です。使い方は println! とまったく同じで、{} による書式指定もそのまま使えます。

ただし、log だけでは何も表示されません。log はファサード（窓口）です。メッセージをどう表示するかは決めずに、どのライブラリでも使える標準のマクロだけを提供します。実際にメッセージを書き出すロガーは、アプリケーションの側で選びます。いちばんシンプルなのが env_logger です。2つともプロジェクトに追加しましょう。

cargo add log env_logger

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

あとは main の最初で env_logger::init() を1回呼べば、ログを出せるようになります。

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

fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide が呼ばれました: a={a}, b={b}");
    if b == 0.0 {
        warn!("{a} をゼロで割ることはできません");
        return None;
    }
    Some(a / b)
}

fn main() {
    env_logger::init();
    info!("電卓を起動します");

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

    error!("エラーの行はこのように表示されます");
}

実行結果:

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

▶ 実際に試してみよう

上の実行結果は stdout だけ、つまりプログラムの本当の結果です。ログの行は stderr に出ます。Playgroundでは「Standard Error」という別の欄に表示されます。

ここで気づいてほしいことがあります。env_loggerは、標準ではエラーだけを表示します。もっと見たいときは、プログラムを実行するときに RUST_LOG 環境変数を設定します。ターミナルで RUST_LOG=debug cargo run として実行したときの、stderrとstdoutを合わせた表示は次のとおりです（タイムスタンプは … に置き換えています。実際には現在の日付と時刻が表示されます）。

[… INFO  my_app] 電卓を起動します
[… DEBUG my_app] divide が呼ばれました: a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide が呼ばれました: a=1, b=0
[… WARN  my_app] 1 をゼロで割ることはできません
1 / 0 = None
[… ERROR my_app] エラーの行はこのように表示されます

ログの各行には、レベルと、そのログを出したモジュール（クレート名の my_app）が表示されます。角かっこのない行は println! の出力です。

`RUST_LOG` で表示するものを選ぶ

レベルを指定すると、そのレベルと、それより重要なものすべてが表示されます。つまり RUST_LOG=warn なら警告とエラーが、RUST_LOG=trace ならすべてが表示されます。

RUST_LOG=debug cargo run     # debug、info、warn、error
RUST_LOG=warn cargo run      # warn と error だけ
RUST_LOG=off cargo run       # ログをまったく出さない

WindowsのPowerShellでは、先に変数を設定します。$env:RUST_LOG="debug"; cargo run のように書きます。

モジュールごとに絞り込むこともできます。ライブラリのログが多すぎるときや、コードの一部分だけを見たいときに便利です。db モジュールを持つプログラムで試してみましょう。

use log::{debug, info};

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

    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("ユーザー {id} を検索します");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("検索結果: {name:?}");
        name
    }
}

fn main() {
    env_logger::init();
    info!("サーバーを起動します");

    for id in [1, 3] {
        match db::find_user(id) {
            Some(name) => println!("ユーザー {id}: {name}"),
            None => println!("ユーザー {id}: 見つかりません"),
        }
    }

    debug!("すべての検索が終わりました");
}

実行結果:

ユーザー 1: Ada
ユーザー 3: 見つかりません

▶ 実際に試してみよう

いくつかのフィルタを試したときの、stderrへの表示です（タイムスタンプは … に置き換えています）。

$ RUST_LOG=my_app=trace cargo run       # 自分のクレートのログをすべて
[… INFO  my_app] サーバーを起動します
[… TRACE my_app::db] ユーザー 1 を検索します
[… DEBUG my_app::db] 検索結果: Some("Ada")
ユーザー 1: Ada
[… TRACE my_app::db] ユーザー 3 を検索します
[… DEBUG my_app::db] 検索結果: None
ユーザー 3: 見つかりません
[… DEBUG my_app] すべての検索が終わりました

$ RUST_LOG=my_app::db=debug cargo run   # db モジュールだけ、debug 以上
[… DEBUG my_app::db] 検索結果: Some("Ada")
ユーザー 1: Ada
[… DEBUG my_app::db] 検索結果: None
ユーザー 3: 見つかりません

カンマでルールを組み合わせることもできます。RUST_LOG=info,my_app::db=trace は「全体は info、ただし db モジュールは trace」という意味です。小さな落とし穴が1つあります。フィルタでは、アンダースコアを使ったクレート名を書きます。my-app という名前のパッケージは、my_app としてログを出します。

コードで標準のレベルを決める

RUST_LOG を設定していなくても info は表示したい、ということはよくあります。そんなときは init() の代わりに env_logger::Builder を使います。タイムスタンプを消すこともでき、ちょっとしたツールには便利です。

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

fn main() {
    // RUST_LOG で指定がなければ `info` 以上を表示する
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();

    info!("アプリを起動しました");
    debug!("これは RUST_LOG=debug のときだけ表示されます");

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

実行結果:

合計 = 55

▶ 実際に試してみよう

タイムスタンプがないので、cargo run での実際のstderrは短くすっきりしています。

[INFO  my_app] アプリを起動しました

tracingで構造化ログを出す

log が出すのはテキストの行です。tracing が出すのはデータつきのイベントで、それがスパン（span）にまとめられます。tracingはTokioチームが作ったもので、axumのような非同期（async）のWebフレームワークでも使われています。次のように追加します。

cargo add tracing tracing-subscriber

覚えておきたい考え方は3つです。

イベントはログの行のようなものです。info!、warn! などがあり、名前は log と同じです。
フィールドは key = value の形でデータをくっつけます。info!(user_id = 42, "ログインしました") のように書きます。ツールはテキストを解析しなくても、このフィールドで検索や絞り込みができます。
スパンは「注文7を処理中」のような、ひとまとまりの作業の期間を表します。スパンの中で起きたイベントには、すべてそのスパンの印がつきます。

log と同じように、tracingも何かを表示するにはサブスクライバー（subscriber）が必要です。標準的なのは tracing_subscriber::fmt() です。1つ意外な点があります。これは標準では stdout に書き出すので、.with_writer(std::io::stderr) で stderr に送るようにしています。

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

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

    info!(user_id = 42, "ログインしました");

    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, "カートの合計を計算しました");

    if total > 2000 {
        warn!(total, limit = 2000, "注文は手動での確認が必要です");
    }

    println!("注文の合計: {total}");
}

実行結果:

注文の合計: 2549

▶ 実際に試してみよう

実行したときのstderrは次のとおりです（タイムスタンプは … に置き換え、色は取り除いています）。

…  INFO my_app: ログインしました user_id=42
…  INFO checkout{order_id=7}: my_app: カートの合計を計算しました items=3 total=2549
…  WARN checkout{order_id=7}: my_app: 注文は手動での確認が必要です total=2549 limit=2000

最後の2行が checkout{order_id=7} で始まっているのがわかりますか？これがスパンです。_guard が生きている間は、すべてのイベントが checkout の「中」にあります。total とだけ書くのは、total = total の省略形です。

`#[instrument]`：呼び出しごとにスパンを作る

スパンを手で作るのは面倒になってきます。関数に #[instrument] を付けると、tracingが呼び出しのたびにスパンを作り、引数をフィールドとして記録してくれます（引数は Debug を実装している必要があります）。

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

#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "割引額を計算しました");
    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, "完了");
    println!("最終価格: {final_price}");
}

実行結果:

最終価格: 2250

▶ 実際に試してみよう

実行したときのstderrです。

… DEBUG apply_discount{price=2500 percent=10}: my_app: 割引額を計算しました off=250
…  INFO my_app: 完了 final_price=2250

fmt() サブスクライバーは、特に指定しなければ info 以上を表示します。.with_max_level(tracing::Level::DEBUG) を設定したのはそのためです。env_loggerと同じように RUST_LOG を使いたいときは、env-filter フィーチャーを有効にして 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();

どちらを選べばいい？

小さなCLIツールやスクリプトなら、log + env_logger。準備はほんの少しで、ただのテキストで済みます。
Webサーバー、非同期のコード、たくさんのタスクを同時に動かすなら、tracing。何百ものリクエストが同時に動いていても、メッセージがどのリクエストのものなのかをスパンが追いかけてくれます。
ライブラリを書いているなら、マクロ（log か tracing）だけを使い、init() は絶対に呼ばないでください。ログをどう表示するかはアプリケーションが決めます。

一度選んだら変えられない、というわけではありません。tracing-subscriberの標準の設定は log クレートからのメッセージも拾うので、どちらを使っているライブラリのログも一緒に表示されます。

よくある間違い

ロガーの準備を忘れる。env_logger::init()（やtracingのサブスクライバーの init()）を一度も呼ばないと、マクロは問題なくコンパイルできるのに、何も表示されません。エラーも警告も出ません。ログが消えてしまったら、まずここを確認し、次に RUST_LOG を確認しましょう。

init() を2回呼ぶ。グローバルなロガーは1つしか持てません。2回目の呼び出しはパニックします。実際のメッセージは次のとおりです。

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

「ロガーが初期化されたあとに env_logger::init を呼んではいけない」という意味です。main のいちばん最初で、1回だけ呼びましょう。テストの中では let _ = env_logger::builder().is_test(true).try_init(); を使います。こちらはパニックせずにエラーを返します。

スパンのガードをすぐに捨ててしまう。let _ = span.enter(); は問題なさそうに見えますが、_ は変数名ではありません。ガードは同じ行ですぐに破棄され、スパンもすぐに終わってしまいます。実際に試すと、スパンなしの INFO my_app: リクエストを処理しています が表示されました。let _guard = span.enter(); のようにガードに名前を付けて、スコープの終わりまで生きるようにしましょう。

まとめ

println! の代わりにログ用クレートを使いましょう。レベルで絞り込めて、ログを本当の出力から離して stderr に出せます。
log には error!、warn!、info!、debug!、trace! があり、env_logger::init() でそれらが表示されるようになります。
何を表示するかは RUST_LOG で決めます。RUST_LOG=debug、RUST_LOG=my_app=trace、RUST_LOG=info,my_app::db=trace のように書きます。
tracing を使うと、構造化されたフィールド（info!(user_id = 42, "ログインしました")）とスパンが使えます。#[instrument] は関数の呼び出しごとにスパンを作ります。
ライブラリはマクロだけを使い、ロガーの準備はアプリケーションが1回だけ行います。

理解度チェック

1. env_loggerを使うプログラムを、RUST_LOG を設定せずに実行しました。どのログの行が表示されますか？

2. env_loggerは、標準ではログのメッセージをどこに書き出しますか？

3. RUST_LOG=warn では何が表示されますか？

4. 関数に #[instrument] を付けると、何が起きますか？

5. ライブラリクレートを書いています。ログについて、どうするべきですか？

スコア: 0 / 5

さらに詳しく

log クレートのドキュメント（英語）：5つのマクロとファサードのしくみが、ライブラリ作者へのアドバイスも含めて書かれています。
env_logger のドキュメント（英語）：RUST_LOG の書き方のすべてと、Builder のすべてのオプションが載っています。
tracing のドキュメント（英語）：スパン、イベント、フィールド、#[instrument] をくわしく解説しています。
tracing-subscriber のドキュメント（英語）：表示形式のオプション、EnvFilter、JSONでの出力について書かれています。
Getting started with Tracing — Tokio（英語）：tracingを開発しているチームによる、わかりやすい入門ガイドです。

Rustのログ出力（log と tracing）

println! ではだめなの？

logファサードとenv_logger

RUST_LOG で表示するものを選ぶ

コードで標準のレベルを決める

tracingで構造化ログを出す

#[instrument]：呼び出しごとにスパンを作る

どちらを選べばいい？

よくある間違い

まとめ

理解度チェック

さらに詳しく

`println!` ではだめなの？

`RUST_LOG` で表示するものを選ぶ

`#[instrument]`：呼び出しごとにスパンを作る