📓

Tracingを用いたRustのロギング理解の図とメモ

2024/04/18に公開

Rust

memo

tracing

tech

Rustでそれなりにちゃんとしたロギングをしようと思いtracingを調べた結果の理解図やサンプルコード等を備忘のため残しておきます。ただバージョンが1未満なので実装は色々変更されるかもしれません。[tracing 0.1.40, tracing-subscriber 0.3.18]

私の理解が解説のように書かれていますが、便利ツールとして使用するだけであればこの認識で問題なさそう、というような内容のため厳密性はありません。Quick startのコードがdocs.rsに載ってなかったり、必須コンポーネントのSubscriberが別クレートになってたり、色々な方法が提供されており逆に混乱したりでそれなりの理解にすらなかなか時間がかかりました。

概要

前提

Cargo.toml

[dependencies]
tracing = "0.1.40"
tracing-subscriber = "0.3.18"

Tracingの簡単な基本構成図

img_tracing_overview

基本構成図対応コード

use tracing::{event, span, Level};
fn main() {
    tracing_subscriber::fmt().init();   // 1. set Subscriber
    event!(Level::INFO, "Event_1");     // 2. log Event_1
    let _span1 = span!(Level::INFO, "Span_1").entered();     // 3. enter Span_1
    event!(Level::INFO, "Event_2");     // 4. log Event_2
    let span2 = span!(Level::INFO, "Span_2").entered();      // 5. enter Span_2
    event!(Level::INFO, "Event_3");     // 6. log Event_3
    span2.exit(); // 7. exit Span_2
    foo(); // {
//      let _span3 = span!(Level::INFO, "Span_3").entered(); // 8. enter Span_3
//      event!(Level::INFO, "Event_4"); // 9. log Event_4
//  } // 10. exit Span_3
}     // 11. exit Span_1

fn foo() {
    let _span3 = span!(Level::INFO, "Span_3").entered();
    event!(Level::INFO, "Event_4");
}

基本構成要素の理解メモ

Subscriber
- Spanの状態を管理しつつEventを記録するイベントリスナーのような存在
- 取り扱うログレベルや出力形式、出力先等を制御する
- 自由なカスタム実装が可能で、その一つがtracing-subscriberクレートという位置付け
  - そのため必須でありながら別クレートとなっており初学者にとって非常にややこしい
Span
- ある期間を表現しログに文脈を付与する存在
- その期間に発生するイベントに対して、期間の状態情報を付与する
- 期間の最後はexit()を明示しなくてもスコープを抜けると自動でexit()される
Event
- 通常のログ1行に相当する存在
- ログレベルの他にも色々情報を付与可能

少し詳しい内容

tracing-subscriberクレートのSubscriberを使用することを前提とした内容です。

ログレベル

サンプルコード

use tracing::Level;
use tracing_subscriber::filter::LevelFilter;
fn main() {
    let error = Level::ERROR;
    let warn = Level::WARN;
    let info = Level::INFO;
    let debug = Level::DEBUG;
    let trace = Level::TRACE;
    // Level is comparabled
    // error < warn < info < debug < trace
    assert!(error < warn);
    assert!(warn < info);
    assert!(info < debug);
    assert!(debug < trace);

    // similar enum LevelFilter has OFF means cut all level
    // off < error
    let off = LevelFilter::OFF;
    let error = LevelFilter::ERROR;
    let warn = LevelFilter::WARN;
    assert!(off < error);
    assert!(error < warn);
}

Record/Field

SpanやEventが持つことができるカスタム情報セット
- ログに残したい変数の内容等を指定する
key-valueの形で情報を保持する
- Fieldはkeyのこと
- Recordはkey-valueの形で保持している情報群のこと
- 厳密に使い分ける自信がないのでこの記事では以後 fields と記載する
SpanやEventに指定する際の書き方

サンプルコードと結果

use tracing::{event, span, Level, field};
#[derive(Debug)]
struct Foo {
    f1: Option<i32>,
    f2: String,
}
fn main() {
    tracing_subscriber::fmt().init();
    // you can add any fields at end of args, this sample line is hard coding.
        

    // if write only var, regard as "var = var" which displays as var="var_content"
    // if var is None, ignored such fields
    let value = 12;
    let foo = Foo { f1: None, f2: "foo".to_string() };
    event!(Level::INFO, value, foo.f1, foo.f2);

    // to control format, using '?' or '%' operator
    // '?' use fmt::Debug, '%' use fmt::Display
    event!(Level::INFO, ?foo, %value);

    // to use const value as key name, write with curly brace
    // to use reserved words, write with double quote
    // if specify field::Empty as value, the field regard as null
    const KEY_NAME: &str = "const_name";
    event!(Level::INFO, { KEY_NAME } = "KEY_NAME", "type" = 2.1, key3 = field::Empty);
}

vscode ➜ /workspaces/z_rust_sandbox (master) $ cargo run
    Compiling z_rust_sandbox v0.1.0 (/workspaces/z_rust_sandbox)
    Finished dev [unoptimized + debuginfo] target(s) in 0.32s
        Running `target/debug/z_rust_sandbox`
2024-04-17T09:24:35.078552Z  INFO span_name{key1="val1" key2="val2"}: z_rust_sandbox: value=12 foo.f2="foo"
2024-04-17T09:24:35.078589Z  INFO span_name{key1="val1" key2="val2"}: z_rust_sandbox: foo=Foo { f1: None, f2: "foo" } value=12
2024-04-17T09:24:35.078619Z  INFO span_name{key1="val1" key2="val2"}: z_rust_sandbox: const_name="KEY_NAME" type=2.1

Span

SpanはSubscriberによって振り出されたIDで個々を管理されている
関数に対してSpanを割り当てたい場合はattributeが使用できる

サンプルコードと結果

use tracing::{instrument, span, event, Level};
fn main() {
    tracing_subscriber::fmt().init();
    let _guard = span!(Level::INFO, "main").entered();
    event!(Level::INFO, "Event_1");
    foo();
}
#[instrument]
fn foo() {
    event!(Level::INFO, "Event_2");
}

vscode ➜ /workspaces/z_rust_sandbox (master) $ cargo run
    Compiling z_rust_sandbox v0.1.0 (/workspaces/z_rust_sandbox)
    Finished dev [unoptimized + debuginfo] target(s) in 0.33s
        Running `target/debug/z_rust_sandbox`
2024-04-17T10:51:03.332067Z  INFO main: z_rust_sandbox: Event_1
2024-04-17T10:51:03.332110Z  INFO main:foo: z_rust_sandbox: Event_2

上記までは1行でSpanを作成しているように見えるが、省略せずに書くと以下となる
- ただしこのコードは非同期関数の中ではうまく動作しない
```
use tracing::{span, Level};
fn main() {
    let span: span::Span = span!(Level::INFO, "span_name");
    let _guard: span::Entered<'_> = span.enter();
}
```
- 非同期関数で同様のことをする場合はattributeを使用するのが簡単
```
use tracing::{instrument, event, Level};
#[tokio::main()]
async fn main() {
    tracing_subscriber::fmt().init();
    foo().await;
}
#[instrument]
async fn foo() {
    event!(Level::INFO, "event");
}
```
  - attributeを使用したくない場合はここを参照
  - attributeでもspan!()のように情報付与したい場合はここを参照
SpanのログレベルはEventと全く何の関係もない
- カスタムSubscriberなら関係性を持たせることも可能(のはず)
- デフォルト形式、JSON形式ではSpanのログレベルは出力されない
- そのためあまり意味のない指定になっている印象を受ける
span!()の代わりにログレベルを固定してSpanを作成する以下マクロもある
- trace_span!()
- debug_span!()
- info_span!()
- warn_span!()
- error_span!()
各Spanは親Spanを持ち、ツリー構造を構成する
- 作成タイミングで親Spanを指定しなければ直近のSpanが親となる
- 直近のSpanがない場合、そのSpanがルートノードとなる

span!()では以下のように指定する気持ちでいれば大体問題ない

あくまでもイメージのため正式には公式を参照

span!(
    target: "target", // optional, default is name of [package] in Cargo.toml
    parent: &span,    // optional, default is most recent Span
    Level::INFO,
    "this is span name",
    fields            // optional
);

Spanはある期間を表現するが、4つのタイミングも持つ
- new : 作成タイミング
- enter : 期間開始タイミング
- exit : 期間終了タイミング
- drop : 削除タイミング
これらのタイミングでログ出力することも可能
- デフォルトではこれらのタイミングでログ出力されない
- これらのタイミングのログにはSpanのログレベルが出力される
dropしていなければexit()した後に再度enter()することも可能
follows_from()を使用することで別のSpanと弱い関連性を持たせることができる
- 具体的な用途など詳細は公式を参照

Event

event!()の代わりにログレベルを固定してEventを作成する以下マクロもある
- trace!()
- debug!()
- info!()
- warn!()
- error!()
各Eventは親Spanを持ち、ツリー構造のリーフノードとなる
- 作成タイミングで親Spanを指定しなければ直近のSpanが親となる
- 直近のSpanがない場合、Span情報のない単体のEventとして記録される

event!()では以下のように指定する気持ちでいれば大体問題ない

あくまでもイメージのため正式には公式を参照

event!(
    name: "event name", // optional, not appeared in default
    target: "target",   // optional, default is name of [package] in Cargo.toml
    parent: &span,      // optional, default is most recent Span
    Level::INFO,
    fields,
    msg_literal,        // optional
    literal_args        // optional
);

msg_literal はprint!マクロで指定する "this is {}" のような文字列のこと
literal_args は msg_literal の {} に対応させる引数のこと

Subscriber

内部構成概略図
- 大まかには以下で構成される
  - Registry : Spanの管理
  - LevelFilter : ログレベルの取捨選択
  - Formatter : 出力内容の整形と出力
- これらは層構造として柔軟に変化させられるような設計になっている
  - 実装によってはSubscriberの合成も可能に見える
- tracing-subscriberクレートではこのように構成されている、というだけに過ぎない
init()の中でset_global_default()が呼ばれSubscriberがグローバル変数にセットされる
- そのためどこでEventを作成してもそれがSubscriberに届く

色々な場合の出力サンプル

サンプルコードと結果

use tracing::{event, instrument, span, Level};
use tracing_subscriber::fmt::format::FmtSpan;
#[derive(Debug)]
enum Foo {
    Var1{f1: i32, f2: String},
    Var2,
}
fn main() {
    tracing_subscriber::fmt()
        .with_max_level(Level::DEBUG)      // set recorded log level
        .with_span_events(FmtSpan::ACTIVE) // enable record span timing
        .init();

    let foo = Foo::Var1 { f1: 777, f2: "sss".to_string() };
    let bar = Foo::Var2;

    let relevant_span = span!(Level::WARN, "relevant");
    let _guard2 = span!(Level::INFO, "main").entered();
    event!(name: "event_name", target: "event_target", parent: &relevant_span, Level::DEBUG, ?bar, "literal {} string", 333);

    func1(&foo);
    func3("result_err");
    event!(Level::TRACE, "trace is not appeared");
}

fn func1(foo: &Foo) {
    let _guard = span!(Level::DEBUG, "func1", fn1="val1").entered();
    event!(Level::INFO, ?foo);
    if let Foo::Var1 { f1, f2 } = foo {
        func2(f1, f2);
    }
}

#[instrument]
fn func2(int: &i32, string: &String) {
    event!(Level::WARN, txt="func2_txt");
}

#[instrument(name = "func3_name", target = "span_target", level = "error", skip(err_str))]
fn func3(err_str: &str) {
    let err: Result<(), &str> = Err(err_str);
    event!(Level::ERROR, ?err);
}

vscode ➜ /workspaces/z_rust_sandbox (master) $ cargo run
   Compiling z_rust_sandbox v0.1.0 (/workspaces/z_rust_sandbox)
    Finished dev [unoptimized + debuginfo] target(s) in 0.33s
     Running `target/debug/z_rust_sandbox`
2024-04-17T14:09:02.589753Z  INFO main: z_rust_sandbox: enter
2024-04-17T14:09:02.589790Z DEBUG relevant: event_target: literal 333 string bar=Var2
2024-04-17T14:09:02.589810Z DEBUG main:func1{fn1="val1"}: z_rust_sandbox: enter
2024-04-17T14:09:02.589816Z  INFO main:func1{fn1="val1"}: z_rust_sandbox: foo=Var1 { f1: 777, f2: "sss" }
2024-04-17T14:09:02.589828Z  INFO main:func1{fn1="val1"}:func2{int=777 string="sss"}: z_rust_sandbox: enter
2024-04-17T14:09:02.589836Z  WARN main:func1{fn1="val1"}:func2{int=777 string="sss"}: z_rust_sandbox: txt="func2_txt"
2024-04-17T14:09:02.589846Z  INFO main:func1{fn1="val1"}:func2{int=777 string="sss"}: z_rust_sandbox: exit
2024-04-17T14:09:02.589861Z DEBUG main:func1{fn1="val1"}: z_rust_sandbox: exit
2024-04-17T14:09:02.589870Z ERROR main:func3_name: span_target: enter
2024-04-17T14:09:02.589875Z ERROR main:func3_name: z_rust_sandbox: err=Err("result_err")
2024-04-17T14:09:02.589881Z ERROR main:func3_name: span_target: exit
2024-04-17T14:09:02.589887Z  INFO main: z_rust_sandbox: exit

こうしたい時

出力するログレベルを変更したい

use tracing::Level;
fn main() {
    tracing_subscriber::fmt()
        .with_max_level(Level::DEBUG) // default=Level::INFO, if sets LevelFilter::OFF, no record logs
        .init();
}

出力する時間をローカルにしたい

公式のFeature Flagsにchronoが載っていないため近いうちに使用できなくなるかもしれない
- その場合は local-time feature を使用すれば同じことができる

サンプルコード

Cargo.toml

[dependencies]
tracing-subscriber = {version = "0.3", features = ["chrono"]}

use tracing_subscriber::fmt::time::ChronoLocal;
fn main() {
    tracing_subscriber::fmt()
        .with_timer(ChronoLocal::rfc_3339()) // specify time format using "chrono" feature
        .init();
}

ファイルに出力したい

サンプルコード

fn main() {
    let error_log = std::sync::Arc::new(std::fs::File::create("./log/error.log").unwrap());
    tracing_subscriber::fmt()
        .with_ansi(false) // default=true; to avoid text garbling
        .with_writer(error_log)
        .init();
}

JSONで出力したい

json出力時しか設定できないオプションがある (詳細)

サンプルコード

Cargo.toml

[dependencies]
tracing-subscriber = {version = "0.3", features = ["json"]}

fn main() {
    tracing_subscriber::fmt()
        .json()
        .init();
}

ファイル名やコード行を出力したい

サンプルコード

fn main() {
    tracing_subscriber::fmt()
        .with_file(true) // default=false
        .with_line_number(true) // default=false
        .init();
}

スレッド情報を出力したい

サンプルコード

fn main() {
    tracing_subscriber::fmt()
        .with_thread_names(true) // default=false
        .with_thread_ids(true) // default=false
        .init();
}

環境変数で出力を制御したい

今のところ使用する予定がないためほぼ未調査
- features env-filter を使用する必要がある (詳細)
- Subscriberを構築する際に.with_filter_reloading()を使用すると実行時に環境変数を取得するようになる

`Span`のタイミングでログ出力したい

その他のタイミングは公式参照

サンプルコード

use tracing_subscriber::fmt::format::FmtSpan;
fn main() {
    tracing_subscriber::fmt()
        .with_span_events(FmtSpan::ACTIVE) // default=FmtSpan::NONE
        .init();
}

レベルに応じて出力場所を変えたい

サンプルコードは以下の出力を実行する
- ログレベルERRORは error.log と info.log に出力される
- ログレベルWARNとINFOは info.log に出力される
- ログレベルDEBUGとTRACEは標準出力に出力される
  - ただしtarget名が"foo"でないものに限る
writerの組み合わせ順は順番によってはコンパイルエラーとなるため気を付ける
詳細は公式を参照

サンプルコード

use tracing::Level;
use tracing_subscriber::fmt::writer::MakeWriterExt;
fn main() {
    let info_log = std::sync::Arc::new(std::fs::File::create("./log/info.log").unwrap());
    let error_log = std::sync::Arc::new(std::fs::File::create("./log/error.log").unwrap());

    let error_writer = error_log.with_max_level(Level::ERROR);
    let info_writer = info_log.with_max_level(Level::INFO);
    let else_writer = std::io::stdout.with_filter(|meta| meta.target() != "foo");
    let writer = error_writer
        .and(
            info_writer.or_else(else_writer)
        );

    tracing_subscriber::fmt()
        .with_ansi(false) // default=true
        .with_max_level(Level::TRACE)
        .with_writer(writer)
        .init();
}

出力場所に応じて出力フォーマットを変更したい

面倒そうだったので深く調査していない
- tracing-subscriberクレートのSubscriberを使用している限り簡単にはできなさそう
  - カスタムSubscriberを実装すればたぶん簡単にできるが、実装が面倒すぎる
- tracing::subscriber::set_default()で都度Subscriberを切り替えれば可能かも
  - そんなコードを書くのは面倒すぎる
  - 設計的にもSubscriberは基本的に一つの思想になっているようなので微妙
- 現実的にJSONで出せれば表示はどうとでもなるのでニーズも不明

詳細な出力フォーマットを自由に変更したい

tracing-subscriberクレートではできないと思われる
- カスタムSubscriberを実装すればできると思われる (詳細)
- 現実的にはfieldsで出力内容を制御し、JSONで出力後に取り扱うのが良さそう

`Subscriber`の出力フォーマット変更メソッド一覧を見たい

詳細は公式を参照
使っても大体この辺かなの一覧は以下
- default値などはバージョンによって変更になる可能性が高い

サンプルコード

use tracing::Level;
use tracing_subscriber::fmt::{time::ChronoLocal, format::FmtSpan};
fn main() {
    let writer = || { std::io::stderr() };
    tracing_subscriber::fmt()
        .with_max_level(Level::DEBUG) // default=Level::INFO, if sets LevelFilter::OFF, no record logs
        .with_span_events(FmtSpan::ACTIVE) // default=FmtSpan::NONE
        .with_timer(ChronoLocal::rfc_3339()) // required "chrono" feature
        .with_target(false) // default=true
        .with_file(true) // default=false
        .with_line_number(true) // default=false
        .with_level(false) // default=true
        .with_thread_names(true) // default=false
        .with_thread_ids(true) // default=false
        .with_ansi(false) // default=true; to avoid text garbling
        .json() // required "json" feature
        .with_writer(writer)
        .init();
}

現時点を含む直近`Span`を取得したい

Span::current()を使用する

`Span`のfieldsを途中で変更したい

record()を使用する (詳細)

外部クレートの関数呼び出しを`Span`に含めたい

in_scope()の中で関数を呼び出すことで強制的にそのSpanに含めることができる
- 詳細は公式を参照

所感

やはり色々できる分複雑ですね。Tracingをもうちょっと高機能にした？標準規格？なOpenTelemetryも面白そうですね。

Tracingを用いたRustのロギング理解の図とメモ

概要

前提

Tracingの簡単な基本構成図

基本構成図対応コード

基本構成要素の理解メモ

少し詳しい内容

ログレベル

Record/Field

Span

Event

Subscriber

色々な場合の出力サンプル

こうしたい時

出力するログレベルを変更したい

出力する時間をローカルにしたい

ファイルに出力したい

JSONで出力したい

ファイル名やコード行を出力したい

スレッド情報を出力したい

環境変数で出力を制御したい

`Span`のタイミングでログ出力したい

レベルに応じて出力場所を変えたい

出力場所に応じて出力フォーマットを変更したい

詳細な出力フォーマットを自由に変更したい

`Subscriber`の出力フォーマット変更メソッド一覧を見たい

現時点を含む直近`Span`を取得したい

`Span`のfieldsを途中で変更したい

外部クレートの関数呼び出しを`Span`に含めたい

所感

参考文献

Discussion

概要

前提

Tracingの簡単な基本構成図

基本構成図対応コード

基本構成要素の理解メモ

少し詳しい内容

ログレベル

Record/Field

Span

Event

Subscriber

色々な場合の出力サンプル

こうしたい時

出力するログレベルを変更したい

出力する時間をローカルにしたい

ファイルに出力したい

JSONで出力したい

ファイル名やコード行を出力したい

スレッド情報を出力したい

環境変数で出力を制御したい

Spanのタイミングでログ出力したい

レベルに応じて出力場所を変えたい

出力場所に応じて出力フォーマットを変更したい

詳細な出力フォーマットを自由に変更したい

Subscriberの出力フォーマット変更メソッド一覧を見たい

現時点を含む直近Spanを取得したい

Spanのfieldsを途中で変更したい

外部クレートの関数呼び出しをSpanに含めたい

所感

参考文献

Discussion

`Span`のタイミングでログ出力したい

`Subscriber`の出力フォーマット変更メソッド一覧を見たい

現時点を含む直近`Span`を取得したい

`Span`のfieldsを途中で変更したい

外部クレートの関数呼び出しを`Span`に含めたい