Rust tracing-subscriber の Layer をマスターする

Rustのtracingエコシステム、特にtracing-subscriberを使ってレイヤーを設定し活用する方法について見ていきましょう。この仕組みは、アプリケーションのトレースデータをどのように処理し出力するかをカスタマイズするための強力な手段です。

RustのTracingレイヤーを紐解く

Rustのtracingクレートは、構造化されたイベントベースの診断情報を収集するためにアプリケーションを計測するためのフレームワークを提供します。これは、単なるprintln!を拡張したものだと考えてください。より整理されていて、より多くの機能を持っています。tracing自体は、スパンやイベントを作成する方法を定義しますが、tracing-subscriberは、実際にこのデータを活用するためのクレートです。これは、トレースデータを収集および処理する責任を負うSubscriberトレイトの実装を提供します。

tracing-subscriberの最も柔軟な機能の一つは、Layerの概念です。Layerはモジュラーなコンポーネントであり、他のレイヤーと積み重ねてSubscriberを形成できます。各レイヤーは独立してトレースデータをフィルタリング、フォーマット、または転送できます。このコンポーザブルなアーキテクチャにより、高度にカスタマイズされたテレメトリパイプラインを構築できます。

例えば、コンソールに整形されたイベントをログ出力したいが、アプリケーションからのINFOレベル以上のイベントのみに制限したい、同時に特定のノイジーなライブラリからの全てのDEBUGイベントをファイルにログ出力したい、そしておそらくクリティカルなエラーはリモートサービスに送信したい、といった状況を想像してみてください。レイヤーを使用すると、このような洗練された設定を管理可能になります。

核となる概念

コードに入る前に、いくつかの用語を明確にしておきます。

Span: プログラムが特定のタスクを実行している期間を表します。スパンはネストしてサブタスクを表せます。
Event: エラーやログメッセージなど、特定の時点での発生を表します。
Subscriber: スパンとイベントを処理するエンティティです。tracing-subscriberは、スパンごとのデータを保存する一般的なSubscriber実装であるRegistryを提供します。
Layer: Subscriberを拡張またはラップできるコンポーネントです。レイヤーはイベントをフィルタリングしたり、フォーマットしたり、異なる出力先にディスパッチしたりできます。これらは複雑なサブスクライバーを作成するためのビルディングブロックです。
Dispatch: 現在のスレッドまたはアプリケーション全体に対してデフォルトのSubscriberをグローバルに設定するメカニズムです。

フォーマットレイヤーを使用した基本的なSubscriberの設定

標準出力に整形されたイベントをログ出力する基本的な例から始めましょう。これには、tracing-subscriberによって提供されるfmt（フォーマット）レイヤーを使用します。

まず、Cargo.tomlに必要な依存関係を追加してください。

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

次に、main.rsでシンプルなサブスクライバーを設定します。

use tracing::{info, instrument};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, fmt};

#[instrument]
fn an_instrumented_function(value: i32) {
    info!(input = value, "This function was called with an interesting value!");
    if value > 0 {
        another_function(value -1);
    }
}

#[instrument]
fn another_function(value: i32) {
    info!(input = value, "This is another function.");
}

fn main() {
    // Subscriberを初期化します
    // EnvFilterを使用して、RUST_LOG環境変数経由で詳細度を設定できます。
    // RUST_LOGが設定されていない場合、デフォルトで"info"になります。
    let filter_layer = EnvFilter::try_from_default_env()
        .or_else(|_| EnvFilter::try_new("info"))
        .unwrap();

    // `fmt::Layer`は、イベントとスパンのフォーマットを担当します。
    let fmt_layer = fmt::layer()
        .with_thread_names(true) // スレッド名をログ出力
        .with_target(true);      // ターゲット（モジュールパス）をログ出力

    // レイヤーを組み合わせて、グローバルなSubscriberを初期化します。
    // `SubscriberExt`はレイヤーを積み重ねるための`with`メソッドを提供します。
    // `SubscriberInitExt`はグローバルなデフォルトSubscriberを設定するための`init`を提供します。
    tracing_subscriber::registry()
        .with(filter_layer)
        .with(fmt_layer)
        .init();

    info!("Application started");
    an_instrumented_function(2);
    info!("Application finished");
}

仕組み:

EnvFilter::try_from_default_env()...: これはフィルタリングレイヤーを作成します。RUST_LOG環境変数（例: RUST_LOG=my_crate=debug,info）を読み込もうとし、どのトレースレベルとターゲットを有効にするかを決定します。RUST_LOGが設定されていない場合、全てのターゲットに対してデフォルトでinfoレベルになります。
fmt::layer(): これはフォーマットレイヤーを作成します。スレッド名 (.with_thread_names(true)) とイベントのターゲット（モジュールパス） (.with_target(true)) を含めるように設定しました。
tracing_subscriber::registry(): これはベースとなるSubscriber実装です。それ自体ではフォーマットやフィルタリングは行いませんが、レイヤーが動作するための基盤を提供します。
.with(filter_layer): filter_layerがレジストリに追加されます。イベントはまずこのフィルターを通過します。
.with(fmt_layer): 次にfmt_layerが追加されます。filter_layerを通過したイベントのみが、fmt_layerに到達してフォーマットされ、コンソールに出力されます。
.init(): 構築されたサブスクライバーをアプリケーションのグローバルなデフォルトとして設定します。これ以降のtracingの計測は全てこのサブスクライバーを使用します。

実行結果例（コンソール出力）:

このコードを実行すると（例: cargo run）、以下のような出力が表示されることがあります。

2023-10-27T10:30:01.123456Z INFO main: Application started
2023-10-27T10:30:01.123500Z  INFO tracing_subscriber_setup_layer::an_instrumented_function: an_instrumented_function{value=2}: tracing_subscriber_setup_layer: This function was called with an interesting value! input=2
2023-10-27T10:30:01.123550Z  INFO tracing_subscriber_setup_layer::another_function: an_instrumented_function{value=2}:another_function{value=1}: tracing_subscriber_setup_layer: This is another function. input=1
2023-10-27T10:30:01.123600Z  INFO tracing_subscriber_setup_layer::another_function: an_instrumented_function{value=2}:another_function{value=1}: exiting
2023-10-27T10:30:01.123650Z  INFO tracing_subscriber_setup_layer::an_instrumented_function: an_instrumented_function{value=2}: exiting
2023-10-27T10:30:01.123700Z INFO main: Application finished

タイムスタンプ、ログレベル、ターゲットパス（main、tracing_subscriber_setup_layer）、スパンコンテキスト（an_instrumented_function{value=2}）、そして実際のメッセージに注目してください。exiting行は、計測された関数が完了したときに自動的に生成されます。

RUST_LOG=debugを設定した場合、より詳細な出力が表示されます（debug!やtrace!マクロを使用している場合）。RUST_LOG=warnを設定した場合、warn!とerror!メッセージのみが表示されます。

複数のレイヤーを積み重ねる

複数のレイヤーを組み合わせることで、真の威力を発揮します。例えば、以下のことを行いたい場合があるでしょう。

RUST_LOGに基づいてイベントをフィルタリングする。
コンソールにログ出力する（上記のように）。
異なるフォーマットまたはフィルターでファイルにログ出力する。

tracing-appenderを使用してファイルに書き込むレイヤーを追加してみましょう。まず、Cargo.tomlに追加します。

[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["fmt", "env-filter", "json"] } # Added "json" for a different format
tracing-appender = "0.2"

次に、main.rsを変更します。

use tracing::{info, warn, instrument};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, fmt, Registry};
use tracing_appender::rolling; // For file logging

#[instrument]
fn complex_operation(id: String, count: u32) {
    info!(task_id = %id, "Starting complex operation");
    for i in 0..count {
        if i % 2 == 0 {
            info!(iteration = i, "Processing step");
        } else {
            warn!(iteration = i, "Encountered a minor issue, proceeding");
        }
    }
    info!(task_id = %id, "Complex operation finished");
}

fn main() {
    // 1. コンソールレイヤー（人間が読みやすい形式）
    let console_filter = EnvFilter::try_from_default_env()
        .or_else(|_| EnvFilter::try_new("info")) // コンソール向けにデフォルトでINFO
        .unwrap();
    let console_fmt_layer = fmt::layer()
        .with_thread_names(true)
        .with_target(true)
        .pretty(); // "pretty"な人間が読みやすい形式を使用

    // 2. ファイルレイヤー（JSON形式、より詳細になる可能性あり）
    //    これは、自分のクレートからの'debug'レベル以上のすべてのイベントをログ出力します。
    let file_appender = rolling::daily("./logs", "app.log"); // 毎日新しいログファイルを作成
    let (non_blocking_writer, _guard) = tracing_appender::non_blocking(file_appender);

    let file_filter = EnvFilter::new("tracing_subscriber_setup_layer=debug"); // ファイル向けに詳細度を高める
    let file_json_layer = fmt::layer()
        .json() // JSON形式で出力
        .with_writer(non_blocking_writer);

    // レイヤーを組み合わせてSubscriberを構築します。
    // 順序は重要です: イベントは追加された順序でレイヤーを流れます。
    let subscriber = Registry::default()
        .with(console_filter.and_then(console_fmt_layer)) // コンソール出力
        .with(file_filter.and_then(file_json_layer));     // ファイル出力

    tracing::subscriber::set_global_default(subscriber)
        .expect("Setting global default subscriber failed");

    // 使用例
    info!("Application starting with multi-layer logging");
    complex_operation("task-123".to_string(), 3);
    warn!("A global warning occurred");
    info!("Application shutting down");
}

主な変更点と説明:

tracing-appender::rolling::daily: これはローリングファイルアペンダーを設定します。これにより、./logsディレクトリに毎日新しいログファイルが作成され、ファイル名はapp.log（日付が先頭に付加されます）となります。
tracing_appender::non_blocking: これはファイルライターをノンブロッキングライターでラップします。ファイルへのログ出力は遅くなる可能性があり、これによりアプリケーションスレッドがI/O操作でブロックされるのを防ぎます。ログがドロップ時にフラッシュされることを保証するため、_guardはロガーの存続期間中スコープに保持する必要があります。
fmt::layer().json(): ファイルレイヤーには、ログエントリをJSONとしてフォーマットするためにjson()を使用しています。これは、ログ分析ツールで消費される構造化ロギングに役立つことが多いです。
with_writer(non_blocking_writer): これは、file_json_layerの出力をノンブロッキングファイルライターに送ります。
.with(console_filter.and_then(console_fmt_layer)): ここでは、and_thenを使用してフィルターとフォーマットレイヤーを組み合わせています。イベントは、console_fmt_layerによって処理される前にconsole_filterを通過する必要があります。これは、特定の出力にのみフィルターを適用するための一般的なパターンです。
.with(...)呼び出しの順序: Subscriberは、.with(...)経由で追加された各レイヤーにイベントを順番にディスパッチします。これは、イベントがそれぞれのフィルターを通過した場合、複数のレイヤーによって処理されることを意味します。console_filterはデフォルトで"info"、file_filterは自分のクレートに対して"debug"です。したがって、自分のクレートからのinfoイベントはコンソールとファイルの両方に表示されます。自分のクレートからのdebugイベントはファイルにのみ表示されます。

実行結果例:

コンソール出力（RUST_LOGが未設定またはRUST_LOG=infoの場合）:

2023-10-27T10:35:21.123456Z  INFO main: Application starting with multi-layer logging
2023-10-27T10:35:21.123500Z  INFO complex_operation{id="task-123" count=3}:tracing_subscriber_setup_layer: Starting complex operation task_id="task-123"
2023-10-27T10:35:21.123550Z  INFO complex_operation{id="task-123" count=3}:tracing_subscriber_setup_layer: Processing step iteration=0
2023-10-27T10:35:21.123600Z  WARN complex_operation{id="task-123" count=3}:tracing_subscriber_setup_layer: Encountered a minor issue, proceeding iteration=1
2023-10-27T10:35:21.123650Z  INFO complex_operation{id="task-123" count=3}:tracing_subscriber_setup_layer: Processing step iteration=2
2023-10-27T10:35:21.123700Z  INFO complex_operation{id="task-123" count=3}:tracing_subscriber_setup_layer: Complex operation finished task_id="task-123"
2023-10-27T10:35:21.123750Z  INFO complex_operation{id="task-123" count=3}:tracing_subscriber_setup_layer: exiting
2023-10-27T10:35:21.123800Z  WARN main: A global warning occurred
2023-10-27T10:35:21.123850Z  INFO main: Application shutting down

ファイル出力（例: ./logs/app.log.2023-10-27）:

以下のような行（JSON形式、tracing_subscriber_setup_layerのdebugレベルにより詳細になる可能性あり）が見つかるはずです。

{"timestamp":"2023-10-27T10:35:21.123456Z","level":"INFO","fields":{"message":"Application starting with multi-layer logging"},"target":"main"}
{"timestamp":"2023-10-27T10:35:21.123500Z","level":"INFO","span":{"name":"complex_operation","id":"task-123","count":3},"spans":[{"name":"complex_operation","id":"task-123","count":3}],"fields":{"message":"Starting complex operation","task_id":"task-123"},"target":"tracing_subscriber_setup_layer"}
{"timestamp":"2023-10-27T10:35:21.123550Z","level":"INFO","span":{"name":"complex_operation","id":"task-123","count":3},"spans":[{"name":"complex_operation","id":"task-123","count":3}],"fields":{"message":"Processing step","iteration":0},"target":"tracing_subscriber_setup_layer"}
{"timestamp":"2023-10-27T10:35:21.123600Z","level":"WARN","span":{"name":"complex_operation","id":"task-123","count":3},"spans":[{"name":"complex_operation","id":"task-123","count":3}],"fields":{"message":"Encountered a minor issue, proceeding","iteration":1},"target":"tracing_subscriber_setup_layer"}
{"timestamp":"2023-10-27T10:35:21.123650Z","level":"INFO","span":{"name":"complex_operation","id":"task-123","count":3},"spans":[{"name":"complex_operation","id":"task-123","count":3}],"fields":{"message":"Processing step","iteration":2},"target":"tracing_subscriber_setup_layer"}
{"timestamp":"2023-10-27T10:35:21.123700Z","level":"INFO","span":{"name":"complex_operation","id":"task-123","count":3},"spans":[{"name":"complex_operation","id":"task-123","count":3}],"fields":{"message":"Complex operation finished","task_id":"task-123"},"target":"tracing_subscriber_setup_layer"}
{"timestamp":"2023-10-27T10:35:21.123750Z","level":"INFO","span":{"name":"complex_operation","id":"task-123","count":3},"spans":[{"name":"complex_operation","id":"task-123","count":3}],"fields":{"message":"exiting"},"target":"tracing_subscriber_setup_layer"}
{"timestamp":"2023-10-27T10:35:21.123800Z","level":"WARN","fields":{"message":"A global warning occurred"},"target":"main"}
{"timestamp":"2023-10-27T10:35:21.123850Z","level":"INFO","fields":{"message":"Application shutting down"},"target":"main"}

（注: tracing_subscriber_setup_layer内にdebug!文がある場合、それらもファイルには表示されますが、デフォルトではコンソールには表示されません）。

`Option<L>`を使用した条件付きレイヤー

場合によっては、レイヤーを条件付きで有効にしたいことがあります。Layerトレイトは、Option<L>（ここでL: Layer）に対して実装されています。これは、レイヤーまたはNoneを含むOptionを持つことができることを意味します。Noneの場合、それは何もしないレイヤーとして動作します。

use tracing_subscriber::{layer::SubscriberExt, EnvFilter, fmt, Registry};
// ... 他のuseも必要かもしれません

fn main() {
    let verbose_logging_enabled = std::env::var("VERBOSE_LOGGING").is_ok();

    let detailed_debug_layer = if verbose_logging_enabled {
        Some(fmt::layer().with_ansi(false).with_line_number(true)) // 例: ANSIなし、行番号付き
    } else {
        None
    };

    let subscriber = Registry::default()
        .with(EnvFilter::new("info"))
        .with(fmt::layer().pretty()) // 基本的なprettyフォーマッター
        .with(detailed_debug_layer); // 条件付きで別のレイヤーを追加

    tracing::subscriber::set_global_default(subscriber).unwrap();

    tracing::info!("Standard log message.");
    if verbose_logging_enabled {
        tracing::info!("This shows up if VERBOSE_LOGGING is set, potentially with more detail.");
    }
    // 条件付きレイヤーの動作を確認するには、以下を実行します:
    // VERBOSE_LOGGING=true cargo run
}

VERBOSE_LOGGING環境変数が設定されている場合（例: VERBOSE_LOGGING=true cargo run）、detailed_debug_layerがアクティブになり、その出力に行番号を追加しANSIコードを無効にする可能性があります（ただし、この積み重ねられた設定では、複数のfmt::Layerインスタンスが異なるライターなしでアクティブな場合、そのフォーマットは上書きされるか、正確な相互作用に応じて組み合わされる可能性があります）。それ以外の場合はNoneとなり、実質的にスキップされます。

まとめ

tracing-subscriberのレイヤーは、Rustアプリケーションが診断データをどのように扱うかを構成するための堅牢で拡張可能な方法を提供します。フィルター、フォーマッター、ライターを組み合わせることで、ローカル開発、デバッグ、本番監視など、特定のニーズに合わせて調整された洗練されたテレメトリパイプラインを作成できます。レイヤーを自由に組み合わせる機能により、ロギングとトレースの設定において関心の分離が明確になり、アプリケーションの進化に合わせて管理と適応が容易になります。

参考資料

tracing: https://crates.io/crates/tracing
tracing-subscriber: https://crates.io/crates/tracing-subscriber
tracing-appender: https://crates.io/crates/tracing-appender
The Layer Trait Documentation: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/layer/trait.Layer.html
The fmt Module Documentation: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/index.html
EnvFilter Documentation: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html
Composing Layers (tracing book): https://tokio.rs/tokio/topics/tracing#composing-layers (このリンクはTokioのtracingセクションを指していますが、概念はtracing-subscriberに共通するものです。)

投稿者

Ito Moe

主にrust関係について、投稿していきます。