概要

Rustで非同期ログ（tracing)を出力するための個人的メモ
crateも更新され続けているため、最新情報はドキュメントを確認した方がいい（戒め）
- 古い記事を参考にすると仕様が変更となっている部分もありハマります
Rust初めて4ヶ月程度なので間違いなどあれば指摘いただけると助かります

ソースコード

https://github.com/reichangbow/rust_tracing

実装例１

tracing, tracing-appender, tracing-subscriberでとりあえず出力してみる

toml

Cargo.toml

[package]
name = "tracing_logger"
version = "0.1.0"
edition = "2021"

[dependencies]
tokio = {version="1.28.0", features=["full"]}
tracing = "0.1.37"
tracing-appender = "0.2.2"
tracing-subscriber = "0.3.17"

ソースコード

main.rs

#[tokio::main]
pub async fn main() {
    let _guard = init_tracing();
    tracing::debug!("Debug");
    tracing::info!("Info");
    tracing::warn!("Warn");
    tracing::error!("Error");
    drop(_guard);
}
fn init_tracing() -> tracing_appender::non_blocking::WorkerGuard {
    let log_writer = tracing_appender::rolling::minutely("./Log", "prefix.log");
    let (non_blocking, guard) = tracing_appender::non_blocking(log_writer);
    tracing_subscriber::fmt()
        .with_writer(non_blocking)
        .with_max_level(tracing::Level::DEBUG)
        .init();
    guard
}

出力例

prefix.log

[2m2023-04-30T09:18:42.865149Z[0m [34mDEBUG[0m [2mtracing_logger[0m[2m:[0m Debug
[2m2023-04-30T09:18:42.865204Z[0m [32m INFO[0m [2mtracing_logger[0m[2m:[0m Info
[2m2023-04-30T09:18:42.865218Z[0m [33m WARN[0m [2mtracing_logger[0m[2m:[0m Warn
[2m2023-04-30T09:18:42.865231Z[0m [31mERROR[0m [2mtracing_logger[0m[2m:[0m Error

う〜む、見にくい...
このままだと出力内容、ローテート時のファイル名ともにUTCで表示されてしまいます
- 例:prefix.log.2023-04-30-09-08
  - 18:09 JST

課題

見やすいフォーマットにする
JSTでログ出力&ローテートする

実装例2

toml

Cargo.toml

[package]
name = "tracing_logger"
version = "0.1.0"
edition = "2021"

[dependencies]
chrono = "0.4.24"
file-rotate = "0.7.3"
thread-id = "4.0.0"
tokio = {version="1.28.0", features=["full"]}
tracing = "0.1.37"
tracing-appender = "0.2.2"
tracing-core = "0.1.30"
tracing-subscriber = "0.3.17"

ソースコード

main.rs

use file_rotate::{
    compression::Compression,
    suffix::{AppendTimestamp, FileLimit},
    ContentLimit, FileRotate,
};
use std::fmt;
use tracing_core::{Event, Subscriber};
use tracing_subscriber::fmt::{
    format::{self, FormatEvent, FormatFields},
    FmtContext, FormattedFields,
};
use tracing_subscriber::registry::LookupSpan;

struct MyFormatter;
// MyFormatter
impl<S, N> FormatEvent<S, N> for MyFormatter
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
{
    fn format_event(
        &self,
        ctx: &FmtContext<'_, S, N>,
        mut writer: format::Writer<'_>,
        event: &Event<'_>,
    ) -> fmt::Result {
        // Format values from the event's's metadata:
        let metadata = event.metadata();
        write!(
            &mut writer,
            "{:<5} {} {} [{}({})] ",
            metadata.level(),
            thread_id::get(),
            chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f%Z"),
            metadata.target(),
            metadata.line().unwrap_or_default()
        )?;

        // Format all the spans in the event's span context.
        if let Some(scope) = ctx.event_scope() {
            for span in scope.from_root() {
                write!(writer, "{}", span.name())?;

                // `FormattedFields` is a formatted representation of the span's
                // fields, which is stored in its extensions by the `fmt` layer's
                // `new_span` method. The fields will have been formatted
                // by the same field formatter that's provided to the event
                // formatter in the `FmtContext`.
                let ext = span.extensions();
                let fields = &ext
                    .get::<FormattedFields<N>>()
                    .expect("will never be `None`");

                // Skip formatting the fields if the span had no fields.
                if !fields.is_empty() {
                    write!(writer, "{{{}}}", fields)?;
                }
                write!(writer, ": ")?;
            }
        }

        // Write fields on the event
        ctx.field_format().format_fields(writer.by_ref(), event)?;

        writeln!(writer)
    }
}

#[tokio::main]
pub async fn main() {
    let _guard = init_tracing();
    tracing::debug!("Debug");
    tracing::info!("Info");
    tracing::warn!("Warn");
    tracing::error!("Error");
    drop(_guard);
}
fn init_tracing() -> tracing_appender::non_blocking::WorkerGuard {
    let log_writer = FileRotate::new(
        "./Log/log",
        AppendTimestamp::with_format(
            "%y%m%d%H",
            FileLimit::Age(chrono::Duration::days(14)),
            file_rotate::suffix::DateFrom::Now,
        ),
        ContentLimit::Time(file_rotate::TimeFrequency::Hourly),
        Compression::None,
        None,
    );
    let (non_blocking, guard) = tracing_appender::non_blocking(log_writer);
    tracing_subscriber::fmt()
        .with_writer(non_blocking)
        .with_max_level(tracing::Level::DEBUG)
        .event_format(MyFormatter)
        .init();
    guard
}

出力例

DEBUG 8182979392 2023-04-30 18:47:28.792+09:00 [tracing_logger(73)] Debug
INFO  8182979392 2023-04-30 18:47:28.793+09:00 [tracing_logger(74)] Info
WARN  8182979392 2023-04-30 18:47:28.793+09:00 [tracing_logger(75)] Warn
ERROR 8182979392 2023-04-30 18:47:28.793+09:00 [tracing_logger(76)] Error

ポイント

tracing_subscriber::fmt::FormatEventを使用してフォーマットを指定
- （ほぼExampleをコピペしただけです）
- 下の部分を変更することで好きなフォーマットに変更できます

let metadata = event.metadata();
write!(
    &mut writer,
    "{:<5} {} {} [{}({})] ",
    metadata.level(),
    thread_id::get(),
    chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f%Z"),
    metadata.target(),
    metadata.line().unwrap_or_default()
)?;

witerにfile-rotateを指定してローテート管理
- 例:log.23043018

let log_writer = FileRotate::new(
        "./Log/log",
        AppendTimestamp::with_format(
            "%y%m%d%H",
            FileLimit::Age(chrono::Duration::days(14)),
            file_rotate::suffix::DateFrom::Now,
        ),
        ContentLimit::Time(file_rotate::TimeFrequency::Hourly),
        Compression::None,
        #[cfg(unix)]
        None,
    );

まとめ

少し工夫をすればある程度のログ出力は可能っぽい
実際に業務に取り入れて活用してみます！
- AXUMを使用してAPIサーバー構築中です
少し前に取り組んで詳細を忘れちゃってるところがあるので、思い出したら付け足します

参考

tracing/tracing-subscriberでログが出力される仕組みを理解する
- tracing周りの理解に大変参考になりました。