はじめに

こんにちは。株式会社エモーションテックのよしかわです。今回は Rust の tracing クレートを使った Actix Web 用のカスタム JSON ログの実装例を紹介いたします。

この記事はエモーションテック Advent Calendar 2022 の 10 日目の記事です。

動機

今回の実装を行った目的の一つは、Rust で書かれた API サーバーで文脈情報つきのログを出力する方法について学ぶことです。ここでは文脈情報としてどの API が呼ばれたか(例: URL)や誰に API を呼ばれたか(例: ユーザーエージェント)といったものを想定しています。ログにこうした文脈情報をつけることは難しいわけではありません。例えば log クレートを使って出力するメッセージに文脈情報も埋め込んでしまう実装もあり得ます。しかしそのような実装だと関数呼び出しの階層が深いとき文脈情報の受け渡しが少々煩雑に感じられます。そこでより簡便な方法の候補として tracing クレートの利用を選びました。

もう一つの目的はログ形式のカスタマイズ方法の把握です。tracing クレートを用いたログの出力自体は tracing_subscriber::fmt や tracing-bunyan-formatter などを使えば可能です。ただログの形式を社内の他言語で書かれたプロジェクトと合わせようとするとうまくいかない場合もあります。そこで好きな形式でログを出力する一手段として自前での実装を行いました。

主な利用クレート

今回の実装でとくに重要な下記の三つのクレートについて少しだけ説明します。

tracing は大雑把に言ってしまうとロガーを発展させたフレームワークのようなもので、以下の三つの概念を軸としています。詳細はドキュメント参照ください。

Span: 何らかの処理が行われた期間を表します。付加情報用のフィールドを持たせられます。
Event: 何らかの出来事が起きた瞬間を表します。こちらも付加情報用のフィールドを持たせられます。
Subscriber: Span や Event の情報が収集される先です。収集された情報は Subscriber の実装によって標準出力に書き込まれたり外部サービスに送られたりします。

tracing-subscriber はそのまま使える Subscriber の実装だけでなく、Subscriber を実装するための機能も提供してくれます。こちらも詳細はドキュメントを参照ください。今回とくに重要なのは Layer です。Layer も Subscriber のように Span や Event の情報が収集される先となります。複数の Layer を一つの Subscriber にまとめて使うのがよくあるパターンです。複数の Subscriber を一つにまとめることはできないので、ログの出力先を複数にしたいときなどは Layer が使われます。

tracing-actix-web は Actix Web で受け取ったリクエストに対応する Span を生成してくれます。この Span は Root Span と呼ばれており、呼び出し元のユーザーエージェントなどリクエストに関する情報が含まれます。やはり詳細はドキュメントを参照ください。

今回行う実装では、Root Span の情報と Event の情報を組み合わせて JSON に書き出すような処理を Layer として実装します。

実装例

実際のコードは下記の通りです。やや分かりにくい部分もありますがシーケンス図や出力例と一緒に見て頂ければ大まかな流れは追えるのではないかと思います。社内ではこれを発展させたような実装を開発中のサーバーに組み込んで評価中です。

ロガー

use std::{collections::BTreeMap, fmt::Debug, io};

use chrono::{DateTime, Utc};
use serde_derive::Serialize;
use serde_json::json;
use serde_with::{DisplayFromStr, serde_as};
use tracing::{Event, Id, Level, Metadata, Subscriber};
use tracing::field::{Field, Visit};
use tracing::span::{Attributes, Record};
use tracing_log::NormalizeEvent;
use tracing_subscriber::{fmt::MakeWriter, Layer, layer::Context, registry::LookupSpan};

// Layer の実装

pub struct JsonLogLayer<W> {
    make_writer: W,
}

impl<W> JsonLogLayer<W>
where
    W: for<'a> MakeWriter<'a> + 'static,
{
    pub fn new(make_writer: W) -> JsonLogLayer<W> {
        JsonLogLayer { make_writer }
    }
}

impl<S, W> Layer<S> for JsonLogLayer<W>
where
    S: Subscriber + for<'lookup> LookupSpan<'lookup>,
    W: for<'a> MakeWriter<'a> + 'static,
{
    // tracing-actix-web で生成された root span が渡されたら
    // その情報を SpanEntry に抽出して ExtensionsMut に保存する。
    fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
        if !is_root(attrs.metadata()) {
            return;
        }

        let Some(span) = ctx.span(id) else { return };

        let mut root_span_entry = SpanEntry::default();
        attrs.record(&mut root_span_entry);

        span.extensions_mut().insert(root_span_entry);
    }

    // ExtensionsMut から SpanEntry を取り出せた場合、すなわち引き数の id が指す Span が
    // tracing-actix-web で生成された root span の場合、 SpanEntry の中身を更新する。
    fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) {
        let Some(span) = ctx.span(id) else { return };
        let mut extensions = span.extensions_mut();
        let Some(root_span_entry) = extensions.get_mut::<SpanEntry>() else { return };

        values.record(root_span_entry);
    }

    // message 属性つきの Event が渡されたらログを書き出す。
    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        if !event.metadata().fields().field("message").is_some() {
            return;
        }

        let Some(span) = ctx.lookup_current() else { return };
        let Some(root_span) = span.scope().find(|span| is_root(span.metadata())) else { return };
        let extensions = root_span.extensions();
        let Some(root_span_entry) = extensions.get() else { return };

        let mut log_entry = LogEntry {
            timestamp: Utc::now(),
            severity: *event.metadata().level(),
            message: String::new(),
            exception: None,
            span: root_span_entry,
        };
        event.record(&mut log_entry);

        if log_entry.severity == Level::ERROR {
            log_entry.exception = Some(ExceptionEntry::new(event));
        }

        let _ = write_json_line(self.make_writer.make_writer(), &log_entry);
    }
}

fn is_root(metadata: &Metadata<'_>) -> bool {
    metadata.target() == "tracing_actix_web::root_span_builder"
}

fn write_json_line(mut w: impl io::Write, entry: &LogEntry) -> io::Result<()> {
    serde_json::to_writer(&mut w, &entry)?;
    w.write_all(&[b'\n'])
}

// ログの JSON を表す構造体

#[serde_as]
#[derive(Serialize)]
struct LogEntry<'a> {
    timestamp: DateTime<Utc>,
    #[serde_as(as = "DisplayFromStr")]
    severity: Level,
    message: String,
    exception: Option<ExceptionEntry>,
    span: &'a SpanEntry,
}

#[derive(Serialize)]
struct ExceptionEntry {
    stacktrace: String,
}

impl ExceptionEntry {
    fn new(event: &Event) -> Self {
        // event が log クレート由来の場合は normalized_metadata メソッドを
        // 使わないとファイルの場所などの情報が取得できない。
        //
        // 参考: https://docs.rs/tracing-log/0.1.3/tracing_log/trait.NormalizeEvent.html
        let normalized_metadata = event.normalized_metadata();

        let metadata = normalized_metadata
            .as_ref()
            .unwrap_or_else(|| event.metadata());

        Self {
            // ここでは簡単のため一行分しか取得していないが、
            // SpanRef::scope も使えば各 Span の行番号なども含められる。
            stacktrace: if let (Some(file), Some(line)) = (metadata.file(), metadata.line()) {
                format!("{}:{}", file, line)
            } else {
                "<unknown>".to_string()
            },
        }
    }
}

#[derive(Default, Serialize)]
struct SpanEntry(BTreeMap<&'static str, serde_json::Value>);

// Span や Event からフィールドを取り出すのに用いる Visit の実装
//
// 参考: https://docs.rs/tracing-core/0.1.30/tracing_core/field/trait.Visit.html

impl<'a> Visit for LogEntry<'a> {
    fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
        if field.name() == "message" {
            self.message = format!("{:?}", value);
        }
    }
}

impl Visit for SpanEntry {
    fn record_i64(&mut self, field: &Field, value: i64) {
        match field.name() {
            // 下記のフィールドの名前は Semantic conventions for HTTP spans に由来する。
            //
            // 参考: https://opentelemetry.io/docs/reference/specification/trace/semantic_conventions/http/
            "http.status_code" => {
                self.0.insert(field.name(), json!(value));
            }

            _ => {}
        }
    }

    fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
        match field.name() {
            // span! マクロによって静的に与えざるを得ない name よりも
            // 動的な情報も含められる otel.name を優先的に使用する。
            //
            // (tracing-actix-web クレートでの例)
            // name: HTTP Request
            // otel.name: HTTP POST /pet/{pet_id}
            //
            // otel.name は name の代替として tracing_opentelemetry で特別扱いされるので
            // このクレートを併用する場合の一貫性の観点でも都合が良い。
            //
            // 参考: https://docs.rs/tracing-opentelemetry/0.18.0/tracing_opentelemetry/index.html#special-fields
            "name" if !self.0.contains_key("name") => {
                self.0.insert("name", json!(format!("{:?}", value)));
            }
            "otel.name" => {
                self.0.insert("name", json!(format!("{:?}", value)));
            }

            // 下記のフィールドの名前は Semantic conventions for HTTP spans に由来する。
            //
            // 参考: https://opentelemetry.io/docs/reference/specification/trace/semantic_conventions/http/
            "http.method" | "http.route" | "http.flavor" | "http.scheme" | "http.host"
            | "http.client_ip" | "http.user_agent" | "http.target" => {
                self.0.insert(field.name(), json!(format!("{:?}", value)));
            }

            // tracing-actix-web が取得したトレース ID は trace_id フィールドに記録されている。
            //
            // 参考: https://github.com/LukeMathWalker/tracing-actix-web/blob/v0.6.2/src/otel.rs#L51-L71
            "trace_id" => {
                self.0.insert(field.name(), json!(format!("{:?}", value)));
            }

            _ => {}
        }
    }
}

アプリケーション

use std::io;

use actix_web::{App, error::InternalError, http::StatusCode, HttpRequest, HttpServer, web};
use opentelemetry::{sdk::propagation::TraceContextPropagator, trace::noop::NoopTracer};
use tracing_actix_web::TracingLogger;
use tracing_opentelemetry::OpenTelemetryLayer;
use tracing_subscriber::{layer::SubscriberExt, Registry, util::SubscriberInitExt};

use tracing_json_log_layer::JsonLogLayer;

async fn greet(req: HttpRequest) -> Result<String, InternalError<&'static str>> {
    match req.match_info().get("id") {
        Some(id) => {
            tracing::info!("greet from id {}", id);
            Ok(format!("Hello id {}!", &id))
        }
        None => {
            tracing::info!("greet from anonymous");
            Err(InternalError::new(
                "Something wrong",
                StatusCode::INTERNAL_SERVER_ERROR,
            ))
        }
    }
}

#[actix_web::main]
async fn main() -> std::io::Result<()> {
    // tracing-actix-web が W3C Trace Context の traceparent ヘッダから trace_id を
    // 抽出できるよう TraceContextPropagator と OpenTelemetryLayer を組み込んでいる。
    opentelemetry::global::set_text_map_propagator(TraceContextPropagator::new());
    let open_telemetry_layer = OpenTelemetryLayer::new(NoopTracer::new());

    Registry::default()
        .with(JsonLogLayer::new(io::stderr))
        .with(open_telemetry_layer)
        .init();

    HttpServer::new(|| {
        App::new()
            .wrap(TracingLogger::default())
            .route("/greet/{id}", web::get().to(greet))
            .route("/greet", web::get().to(greet))
    })
    .bind(("127.0.0.1", 8080))?
    .run()
    .await?;

    opentelemetry::global::shutdown_tracer_provider();

    Ok(())
}

依存クレート

actix-web = "4.2.1"
chrono = { version = "0.4.23", features = ["serde"] }
opentelemetry = "0.18.0"
serde = "1.0.149"
serde_derive = "1.0.149"
serde_json = "1.0.89"
serde_with = "2.1.0"
tracing = "0.1.37"
tracing-actix-web = { version = "0.6.2", features = ["opentelemetry_0_18"] }
tracing-log = "0.1.3"
tracing-opentelemetry = "0.18.0"
tracing-subscriber = "0.3.16"

シーケンス図

簡略化したものですがシーケンス図は下記の通りです。実際は actix-web や tracing の内部ではもっと複雑な処理が行われています。

エラーにならない場合

エラーになる場合

出力例

上記のコードを curl で呼び出すコマンドと、そのコマンドを実行して得られた出力を jq で整形したものが下記です。 stacktrace が1行しか取れないなど寂しい部分もありますが、traceparent ヘッダからトレース ID が取得できるなど便利な部分もあります。

エラーにならない場合

$ curl -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' \
  http://localhost:8080/greet/1
Hello id 1!

{
  "timestamp": "2022-12-08T10:59:00.969570Z",
  "severity": "INFO",
  "message": "greet from id 1",
  "exception": null,
  "span": {
    "http.client_ip": "127.0.0.1",
    "http.flavor": "1.1",
    "http.host": "localhost:8080",
    "http.method": "GET",
    "http.route": "/greet/{id}",
    "http.scheme": "http",
    "http.target": "/greet/1",
    "http.user_agent": "curl/7.79.1",
    "name": "HTTP GET /greet/{id}",
    "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736"
  }
}

エラーになる場合

$ curl -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' \
  http://localhost:8080/greet
Something wrong

{
  "timestamp": "2022-12-08T11:00:55.665130Z",
  "severity": "INFO",
  "message": "greet from anonymous",
  "exception": null,
  "span": {
    "http.client_ip": "127.0.0.1",
    "http.flavor": "1.1",
    "http.host": "localhost:8080",
    "http.method": "GET",
    "http.route": "/greet",
    "http.scheme": "http",
    "http.target": "/greet",
    "http.user_agent": "curl/7.79.1",
    "name": "HTTP GET /greet",
    "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736"
  }
}
{
  "timestamp": "2022-12-08T11:00:55.665325Z",
  "severity": "ERROR",
  "message": "Error encountered while processing the incoming HTTP request: \"Something wrong\"",
  "exception": {
    "stacktrace": "/Users/et-yoshikawa/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-actix-web-0.6.2/src/middleware.rs:258"
  },
  "span": {
    "http.client_ip": "127.0.0.1",
    "http.flavor": "1.1",
    "http.host": "localhost:8080",
    "http.method": "GET",
    "http.route": "/greet",
    "http.scheme": "http",
    "http.status_code": 500,
    "http.target": "/greet",
    "http.user_agent": "curl/7.79.1",
    "name": "HTTP GET /greet",
    "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736"
  }
}