Rustで非同期ログを出力する（tracingクレート）

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

# ソースコード
* https://github.com/reichangbow/rust_tracing

# 実装例１
* [tracing](https://docs.rs/tracing/latest/tracing/), [tracing-appender](https://docs.rs/tracing-appender/latest/tracing_appender/#), [tracing-subscriber](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/)でとりあえず出力してみる
## toml
```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"
```
## ソースコード
```rust: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
}
```
## 出力例
```text: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
```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"
```

## ソースコード
```rust: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
}
```
## 出力例
```text
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](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/trait.FormatEvent.html)を使用してフォーマットを指定
    * （ほぼExampleをコピペしただけです）
    * 下の部分を変更することで好きなフォーマットに変更できます
```rust
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](https://docs.rs/file-rotate/latest/file_rotate/)を指定してローテート管理
    * 例:log.23043018
```rust
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でログが出力される仕組みを理解する](https://blog.ymgyt.io/entry/how-tracing-and-tracing-subscriber-write-events/)
    * tracing周りの理解に大変参考になりました。