Rustのロギングについて解説とデモ

こんにちは、エンジニアの松本です。この記事はShinjuku.rs #14 において『Rustでロギングってどうすればいいんですか？』というタイトルでデモを中心に発表した内容をブログ記事としてまとめ直したものです。

Rustの標準的なロギングの仕組みとそれを実現するクレート群の使い方を解説します。

※クレート：他のプログラミング言語でいうところの「ライブラリ」に相当する概念。ある機能を提供する再利用可能なコード群のこと。

ロギングは大切

アプリケーションを運用していくにあたって、様々な場面でアプリケーションの動作を確認したくなることがあります。処理はいつ終了したか、どの処理に時間がかかっているか、異常終了した原因は何でどこまでは正しく実行できたかを調べたいといった場面があります。

こういった場面で適切な場所に適切なログが記録されていれば、ソースコードを読んだり再現実験をしたりする前に状況を把握し、調査に必要な時間を大幅に短縮することができます。

そこでアプリケーションを実装する際に、処理の経過をどこかに出力できるようにするのですが、何が起こっているかを把握するためには、「統一的なフォーマットで」「時刻をつけて」「重要度がわかるように」「何が起こったか」「書き出す」必要があります。これを各関数など処理内容に注目したい箇所で実装するとなると、常に時刻のフォーマットや書き出し先のファイルなどが付いて回ることになり、非常に読みにくいソースコードになってしまいそうです。

またロギングの仕組みを様々な開発者が独自に実装すると、インターフェイスが統一されず、すべての依存ライブラリごとに指定される異なるインターフェイスでログのフォーマットや書き出し先を指定することになり、これも辛そうです。

標準的なロギングAPIのファサードを提供するlogクレート

そこでRustには標準的なロギングの仕組みが用意されています。多くのクレートがこの仕組みを利用して開発されています。

Rustの標準的なロギングの仕組みはlogクレートを中心に作られています。
logクレートはcrates.ioにおいて歴代ダウンロード数が10位のメジャーなクレートです。

logクレートは、アプリケーション・ライブラリ向けには5種類のログレベルに応じたロギング用のマクロを、ロガーを実装するクレート向けには実装すべきtrait Logを、それぞれ提供しています。ロギングに必要なAPIを定義しつつも、ロガーの実装は他のクレートに委ねるファサードの振る舞いをしています。

※ファサードパターンは共通のインターフェイスを提供して、どの実装を使うかによらず、利用者から簡単に利用できるようにするデザインパターンです。

logクレートにはNopLoggerという何もしないロガーが定義されています。他のクレートから log::set_logger() が呼ばれるまでは、このNopLoggerが設定されており、メッセージに対して何もしません。
多くの場合、ロガークレートの init という関数から log::set_logger() が呼び出され、ロガーの切り替えができるようになっています。ロガーの切り替えはプログラム中、一度しかできないようになっています。普段このような処理を書かない私にとっては学びがありました。ソースコードはこちらです。

ロガー開発者はlogクレートのLogトレイトを自身のロガーに実装する必要があります。

一方、ロギングを行いたいアプリケーション開発者は何らかのロガーを選択し、logクレートによって定義されているinfo!などのマクロを利用してロギングを行うことになります。ログレベルはErrorが最も重大で、Traceが最も詳細です。

具体的なロガーを実装しているクレートたち

続いて、実際に動かしながら、ロガーを実装しているクレートのうち有名なもの(env_logger, simplelog, fern)を紹介します。

それぞれ次のようなメリット・デメリットがあります。

クレート	メリット	デメリット
env_logger	環境変数で出力するログレベルを変更できる/記述が簡潔	出力先が標準エラーに固定
simplelog	出力先の制御が可能/記述が簡潔	ログのフォーマットを変更できない
fern	出力先やフォーマット・ログレベルを柔軟に設定可能	比較的設定が複雑

デモコードの準備

logクレートを使ったデモコードを示します。
log_sampleというクレートをRustの標準的なディレクトリ構成で作成します。

# ディレクトリ構成
log_sample/
├── Cargo.toml
└── src
    ├── lib.rs
    └── main.rs

3つのファイルを準備します。

# Cargo.toml
[package]
name = "log_sample"
version = "0.1.0"
authors = ["matsumoto"]
edition = "2018"

[dependencies]
log = "0.4.0"
env_logger = "0.8.3"
simplelog = "0.9.0"
fern = "0.6.0"
chrono = "0.4.19"

lib.rsにfibonacci, tribonacciという2つのモジュールを定義します。

// lib.rs
pub mod fibonacci {
    pub fn fibonacci(n: usize) -> usize {
        log::debug!("fibonacci({})", n);
        if n == 0 {
            log::trace!("n==0 => 0");
            0
        } else if n == 1 {
            log::trace!("n==1 => 1");
            1
        } else {
            log::trace!("n>=2 => fibonacci(n - 2) + fibonacci(n - 1)");
            fibonacci(n - 2) + fibonacci(n - 1)
        }
    }
}
pub mod tribonacci {
    pub fn tribonacci(n: usize) -> usize {
        log::debug!("tribonacci({})", n);
        if n < 2 {
            log::trace!("n<2 => 0");
            0
        } else if n == 2 {
            log::trace!("n==2 => 1");
            1
        } else {
            log::trace!("n>=3 => tribonacci(n - 3) + tribonacci(n - 2) + tribonacci(n - 1)");
            tribonacci(n - 3) + tribonacci(n - 2) + tribonacci(n - 1)
        }
    }
}

main.rsから上記のモジュールを呼び出します。
init_loggerはロガーの初期化を行う関数で、各クレートを紹介する際に実装を上書きします。

// main.rs
use log_sample::{fibonacci, tribonacci};
use std::fs::File;

fn init_logger(){
    env_logger::init();
}

fn main(){
    // ロガーを初期化
    init_logger();

    // 5種類のエラーレベル
    log::trace!("some trace log");
    log::debug!("some debug log");
    log::info!("some information log");
    log::warn!("some warning log");
    log::error!("some error log");

    // フィボナッチ数列、トリボナッチ数列の第4項を計算する。
    let n = 4;
    log::info!("try to calculate fibonacci({})", n);
    let fib = fibonacci::fibonacci(n);
    println!("fib[{}] = {}", n, fib);
    log::info!("try to calculate tribonacci({})", n);
    let trib = tribonacci::tribonacci(n);
    println!("trib[{}] = {}", n, trib);
}

cargo run を実行すると 下記のような結果が出力されるはずです。

[2021-03-17T14:20:05Z ERROR log_sample] some error log
fib[4] = 3
trib[4] = 2

環境変数に応じて出力するログレベルを変更するenv_logger

env_loggerは環境変数で出力するログレベルを変更できることが特徴である、Rust界で最も有名なロガーです。
出力先は標準エラーに固定されていますが、簡単に導入できます。

ロガーの初期化は非常に簡潔です。

fn init_logger(){
    env_logger::init();
}

実行時に環境変数を指定することで、コンパイルをやり直すことなく出力するログレベルが切り替えられていることがわかります。

$ cargo build --release

$ RUST_LOG=info ./target/release/log_sample 
[2021-03-17T14:28:13Z INFO  log_sample] some information log
[2021-03-17T14:28:13Z WARN  log_sample] some warning log
[2021-03-17T14:28:13Z ERROR log_sample] some error log
[2021-03-17T14:28:13Z INFO  log_sample] try to calculate fibonacci(4)
fib[4] = 3
[2021-03-17T14:28:13Z INFO  log_sample] try to calculate tribonacci(4)
trib[4] = 2

$ RUST_LOG=trace,log_sample::fibonacci=debug,log_sample::tribonacci=warn ./target/release/log_sample 
[2021-03-17T14:28:14Z TRACE log_sample] some trace log
[2021-03-17T14:28:14Z DEBUG log_sample] some debug log
[2021-03-17T14:28:14Z INFO  log_sample] some information log
[2021-03-17T14:28:14Z WARN  log_sample] some warning log
[2021-03-17T14:28:14Z ERROR log_sample] some error log
[2021-03-17T14:28:14Z INFO  log_sample] try to calculate fibonacci(4)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(4)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(2)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(0)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(1)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(3)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(1)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(2)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(0)
[2021-03-17T14:28:14Z DEBUG log_sample::fibonacci] fibonacci(1)
fib[4] = 3
[2021-03-17T14:28:14Z INFO  log_sample] try to calculate tribonacci(4)
trib[4] = 2

簡単にファイル書き出しをするsimplelog

env_loggerではファイルにログを書き出すことができませんでした。
simplelogでは書き出し先を制御することができます。

init_logger を書き換えます。

fn init_logger(){
    simplelog::CombinedLogger::init(vec![
        // 標準出力にはWarn以上を表示する。
        simplelog::TermLogger::new(
            simplelog::LevelFilter::Warn,
            simplelog::Config::default(),
            simplelog::TerminalMode::Mixed,
        ),
        // ファイルsimplelog.logにはInfo以上を表示する。
        simplelog::WriteLogger::new(
            simplelog::LevelFilter::Info,
            simplelog::Config::default(),
            File::create("simplelog.log").unwrap(),
        ),
    ])
    .unwrap();
}

実行するとターミナルにはWarn以上、simple.logにはInfo以上のログが書き出されていることが確認できます。

14:33:59 [WARN] some warning log
14:33:59 [ERROR] some error log
fib[4] = 3
trib[4] = 2

$ cat simple.log
14:33:59 [INFO] some information log
14:33:59 [WARN] some warning log
14:33:59 [ERROR] some error log
14:33:59 [INFO] try to calculate fibonacci(4)
14:33:59 [INFO] try to calculate tribonacci(4)

モジュール単位の制御をするfern

ログのフォーマットを自由に設定したり、モジュールごとのログレベルを柔軟に設定したい場合はfernが便利です。特に実務では自分が書いたコードのログは詳しく見たいが、利用しているOSSのログはWarn以上でよい場合があり使いやすいです。

ファイルには年月日のついたWarn以上のログを、ターミナルには時分秒からのログをモジュールごとにレベル制御をして出力するサンプルです。

fn init_logger(){
    let base_config = fern::Dispatch::new();

    let file_config = fern::Dispatch::new()
        .level(log::LevelFilter::Warn)
        .format(|out, message, record| {
            out.finish(format_args!(
                "{}[{}][{}] {}",
                chrono::Local::now().format("[%Y-%m-%d][%H:%M:%S]"),
                record.level(),
                record.target(),
                message
            ))
        })
        .chain(fern::log_file("fern.log").unwrap());

    let stdout_config = fern::Dispatch::new()
        .level(log::LevelFilter::Info)
        .level_for("fibonacci", log::LevelFilter::Trace)
        .level_for("tribonacci", log::LevelFilter::Debug)
        .format(|out, message, record| {
            out.finish(format_args!(
                "{}[{}][{}] {}",
                chrono::Local::now().format("[%H:%M:%S]"),
                record.level(),
                record.target(),
                message
            ))
        })
        .chain(std::io::stdout());

    base_config
        .chain(file_config)
        .chain(stdout_config)
        .apply().unwrap();
}

configごとに枝分かれしている様子を植物のシダ(fern)に見立てているようです。

実行すると下記のような結果が得られます。

[23:48:50][INFO][log_sample] some information log
[23:48:50][WARN][log_sample] some warning log
[23:48:50][ERROR][log_sample] some error log
[23:48:50][INFO][log_sample] try to calculate fibonacci(4)
fib[4] = 3
[23:48:50][INFO][log_sample] try to calculate tribonacci(4)
trib[4] = 2

$ cat fern.log
[2021-03-17][23:48:50][WARN][log_sample] some warning log
[2021-03-17][23:48:50][ERROR][log_sample] some error log

chronoを使ってローカルのタイムゾーンで表示したので、夜な夜な原稿を書いていることがばれてしまいました。

分散トレーシングのためのtracing

最後にtracingというクレートを紹介します。
tracingクレートは非同期処理のロギングのために開発されたクレートで、logクレートと同じマクロ群を独自に実装しています。

アプリケーション内で log::info!() などとしていた箇所を tracing:info!() などの対応するマクロに置き換える必要があります。

main.rsは下記のように修正しましょう。

fn main() {
    // tracingの初期化
    let subscriber = tracing_subscriber::FmtSubscriber::builder()
        .with_max_level(tracing::Level::DEBUG)
        .finish();
    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");

    // 5つのログレベル
    tracing::trace!("some trace log");
    tracing::debug!("some debug log");
    tracing::info!("some information log");
    tracing::warn!("some warning log");
    tracing::error!("some error log");

    // fib[0]からfib[4]を別スレッドで計算する
    let mut children = vec![];
    let NTHREADS = 5;
    for i in 0..NTHREADS {
        children.push(thread::spawn(move || {
            let fib = call_fib(i);
            println!("fib[{}] = {}", i, fib);
        }));
    }

    for child in children {
        let _ = child.join();
    }
}

関数の呼び出しをわかりやすくするためにmain.rsに次の関数を追加します。

#[tracing::instrument]
fn call_fib(n: usize) -> usize {
    let fib = fibonacci::fibonacci(n);
    tracing::info!(n);
    println!("fib[{}] = {}", n, fib);
    fib
}

実行すると次のようなログがターミナルに出力されます。

Mar 18 00:10:17.914 DEBUG log_sample: some debug log
Mar 18 00:10:17.915  INFO log_sample: some information log
Mar 18 00:10:17.915  WARN log_sample: some warning log
Mar 18 00:10:17.915 ERROR log_sample: some error log
Mar 18 00:10:17.915 DEBUG call_fib{n=0}: log_sample::fibonacci: fibonacci(0)
Mar 18 00:10:17.915 DEBUG call_fib{n=2}: log_sample::fibonacci: fibonacci(2)
Mar 18 00:10:17.915 DEBUG call_fib{n=1}: log_sample::fibonacci: fibonacci(1)
Mar 18 00:10:17.915 DEBUG call_fib{n=3}: log_sample::fibonacci: fibonacci(3)
Mar 18 00:10:17.915  INFO call_fib{n=0}: log_sample: n=0
fib[0] = 0
fib[0] = 0
Mar 18 00:10:17.915 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(4)
Mar 18 00:10:17.915 DEBUG call_fib{n=2}: log_sample::fibonacci: fibonacci(0)
Mar 18 00:10:17.915  INFO call_fib{n=1}: log_sample: n=1
Mar 18 00:10:17.916 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(2)
Mar 18 00:10:17.915 DEBUG call_fib{n=3}: log_sample::fibonacci: fibonacci(1)
Mar 18 00:10:17.916 DEBUG call_fib{n=2}: log_sample::fibonacci: fibonacci(1)
fib[1] = 1
Mar 18 00:10:17.916 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(0)
Mar 18 00:10:17.916 DEBUG call_fib{n=3}: log_sample::fibonacci: fibonacci(2)
Mar 18 00:10:17.916  INFO call_fib{n=2}: log_sample: n=2
fib[2] = 1
fib[1] = 1
fib[2] = 1
Mar 18 00:10:17.916 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(1)
Mar 18 00:10:17.916 DEBUG call_fib{n=3}: log_sample::fibonacci: fibonacci(0)
Mar 18 00:10:17.916 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(3)
Mar 18 00:10:17.916 DEBUG call_fib{n=3}: log_sample::fibonacci: fibonacci(1)
Mar 18 00:10:17.916 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(1)
Mar 18 00:10:17.916 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(2)
Mar 18 00:10:17.916  INFO call_fib{n=3}: log_sample: n=3
fib[3] = 2
Mar 18 00:10:17.916 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(0)
fib[3] = 2
Mar 18 00:10:17.916 DEBUG call_fib{n=4}: log_sample::fibonacci: fibonacci(1)
Mar 18 00:10:17.917  INFO call_fib{n=4}: log_sample: n=4
fib[4] = 3
fib[4] = 3

注目すべきはfibonacciのログにcall_fib{n=0}、call_fib{n=4}など、どの変数で呼び出した文脈でそのログが出力されたのかが記録されているところです。 #[tracing::instrument] というアトリビュートをつけるだけで自動で行ってくれます。

まとめ

本記事ではRustの標準的なロギングの仕組みを解説し、ロガーを実装している3つのクレート(env_logger, simplelog, fern)についてコードを示しながら紹介しました。また非同期処理のためのロギングの仕組みであるtracingクレートを紹介しました。
Rustユーザーの皆様のお役に立てば幸いです。

お知らせ

フォルシアでは定期的にエンジニア向けのイベントをオンラインで開催しています。
本記事のベースになったLTはShinjuku.rsというイベントで行いました。次回は4/27(火)を予定しています。

また、来週3/23(火)には「FORCIA Meetup #2 2020年度にエンジニアが取り組んだこと」と題しまして、フォルシアのエンジニアの働き方・考え方・仕事の内容がわかるLT会を企画しています。

少しでもご興味のある方は下記URLからご参加ください。
https://forcia.connpass.com/event/206140/