Rustでログってどう取るの？

はじめに

実社会にサービスをデプロイするためにはアプリケーションのロギングは必要不可欠です。ということで今回はRustの非同期アプリケーションにおけるデファクト?のロギングクレートであるtracingについて紹介します。

この記事を読まなくともドキュメントを読めばすべてが事足りますが、自分の勉強を兼ねて書いてます。あと英語なんで読む気が起きない人もいるかもしれないですし。。

なぜログをとるのか？

そもそもなぜ、ログを取るのかという話ですが、それは何かあったときのために手がかりを残したいからだと思います。例えば、ログを取っていない状態で、自分がデプロイしているサービスを使っている顧客に「このサービス動かないんだけど？」と言われたらどうでしょう。他の人達はなんの問題もなく使えているようです。このような状況に陥ったら、あなたがどんなにスーパーなエンジニアでも問題解明にはかなり苦労するかもしれません。。

ログに求めるもの

なにかあったときの手がかりを残したいと考えると以下に挙げるようの情報は欲しいと思います。

1. 時間
   これに関してはあまり異論はないと思います。それが起こったのはいつなのかというのは知りたいですよね。
2. 重大さのレベル
   これはいわゆるinfo、warn、errorとかそういうのです。これを使い分けることで知りたい情報をフィルタリングできます。
3. リクエストID
   これは各リクエストに振られる一意のIDです。前述の「このサービス動かないんだけど？」というクレームが合った場合は、その顧客が送ったリクエストを特定できればそのリクエストIDでフィルタリングすることで、該当するログを見つけることができます。
4. ユーザーID
   これは誰の操作に起因して発生したログなのかを示すためのものです。
5. アプリケーションインスタンスID
   これはクラウドで同じサービスを複数のインスタンスが走らせているときに、どのインスタンスで発生したログなのかを識別するためのものです。

さらにタスクには終わりと始まりがあります(HTTPリクエスト、DBへのクエリ発行等)。さらにタスクはしばしば入れ子になっています。この作業単位で共有されている情報というのがあります。例えばHTTPリクエストなら、GETなのかPOSTなのか、クライアントのIPアドレスはなにか、HTTPのバージョンは？などです。このような情報もログに残したいです。解析しやすいフォーマットだとなお良いですね。

logクレートの問題点

Rustにはlogクレートという公式が開発しているクレートがあるのですが、非同期アプリケーションで使うには少々力不足です。理由は以下の二点があります。

1. タスクの継続期間の表現が難しい。
   Rustのログクレートにはそういった概念はありません。
2. 構造化されたログを出力できない。
   Rustのログクレートで出力できるのは単なる文字列です。

tracingクレート

tracingクレートは上記のlogクレートの問題を解消しています。まずtracingクレートはspanという概念を用いて、タスクの継続期間を表現できます。またJSON等の構造化されたフォーマットでログを出力することができます。

tracingの使用例

これはWebアプリケーションの断片です。subscribeというのはハンドラです。subscribe関数の中でinsert_subscriberを呼んでいます。insert_subscriberはフォームデータをテーブルに挿入します。

use actix_web::{web, HttpResponse};
use chrono::Utc;
use serde::Deserialize;
use sqlx::PgPool;
use uuid::Uuid;

#[derive(Deserialize)]
pub struct FormData {
    name: String,
    email: String,
}

// #[tracing::instrument]で"Adding a new subscriber"という名前のスパンを開始します。
#[tracing::instrument(
    name = "Adding a new subscriber", 
    skip(form, pool),
    fields(
        request_id = %Uuid::new_v4(),
        subscriber_email = %form.email,
        subscriber_name = %form.name
    )    
)]
pub async fn subscribe(form: web::Form<FormData>, pool: web::Data<PgPool>) -> HttpResponse {
    match insert_subscirber(&pool, &form).await
    {
        Ok(_) => HttpResponse::Ok().finish(),
        Err(e) => {
	    // errorイベント
            tracing::error!("Failed to execute query: {:?}", e);
            HttpResponse::InternalServerError().finish()
        }
    }
}

// #[tracing::instrument]で"Saving new subscriber details in the database"という名前のスパンを開始します。
// subscribe関数の中で呼ばれているので入れ子になっています。
#[tracing::instrument(
    name = "Saving new subscriber details in the database", 
    skip(form, pool)
)]
pub async fn insert_subscirber(
    pool: &PgPool,
    form: &FormData,
) -> Result<(), sqlx::Error> {
    sqlx::query!(
        r#"
        INSERT INTO subscriptions (id, email, name, subscribed_at)
        VALUES ($1, $2, $3, $4)
        "#,
        Uuid::new_v4(),
        form.email,
        form.name,
        Utc::now()
    )
    .execute(pool)
    .await
    .map_err(|e| {
    　　// errrorイベント
        tracing::error!("Failed to execute query: {:?}", e);
        e
    })?;
    Ok(())
}

(https://github.com/LukeMathWalker/zero-to-production から一部内容を変更して引用)

リクエストを投げたときに出力されたログ

[2021-10-13T10:22:19.704Z]  INFO: xxxxx/625 on LAPTOP-yyyyyyyyy: [ADDING A NEW SUBSCRIBER - START] (file=src/routes/subscriptions.rs,http.client_ip=127.0.0.1:46788,http.flavor=1.1,http.host=127.0.0.1:8000,http.method=POST,http.route=/subscriptions,http.scheme=http,http.target=/subscriptions,http.user_agent=HTTPie/1.0.3,line=13,otel.kind=server,request_id=332b488c-3956-4582-8db3-de850b80a762,subscriber_email=[e-mail],subscriber_name=dean,target=xxxxx::routes::subscriptions)
[2021-10-13T10:22:19.704Z]  INFO: xxxxx/625 on LAPTOP-yyyyyyyyy: [SAVING NEW SUBSCRIBER DETAILS IN THE DATABASE - START] (file=src/routes/subscriptions.rs,http.client_ip=127.0.0.1:46788,http.flavor=1.1,http.host=127.0.0.1:8000,http.method=POST,http.route=/subscriptions,http.scheme=http,http.target=/subscriptions,http.user_agent=HTTPie/1.0.3,line=32,otel.kind=server,request_id=332b488c-3956-4582-8db3-de850b80a762,subscriber_email=[e-mail],subscriber_name=dean,target=xxxxx::routes::subscriptions)
[2021-10-13T10:22:19.707Z]  INFO: xxxxx/625 on LAPTOP-yyyyyyyyy: [SAVING NEW SUBSCRIBER DETAILS IN THE DATABASE - EVENT] /* SQLx ping */; rows: 0, elapsed: 1.863ms (file=null,http.client_ip=127.0.0.1:46788,http.flavor=1.1,http.host=127.0.0.1:8000,http.method=POST,http.route=/subscriptions,http.scheme=http,http.target=/subscriptions,http.user_agent=HTTPie/1.0.3,line=null,log.module_path=sqlx::query,log.target=sqlx::query,otel.kind=server,request_id=332b488c-3956-4582-8db3-de850b80a762,subscriber_email=[e-mail],subscriber_name=dean,target=log)
[2021-10-13T10:22:19.719Z]  INFO: xxxxx/625 on LAPTOP-yyyyyyyyy: [SAVING NEW SUBSCRIBER DETAILS IN THE DATABASE - EVENT] INSERT INTO subscriptions (id, …; rows: 0, elapsed: 6.975ms

INSERT INTO
  subscriptions (id, email, name, subscribed_at)
VALUES
  ($1, $2, $3, $4)
 (file=null,http.client_ip=127.0.0.1:46788,http.flavor=1.1,http.host=127.0.0.1:8000,http.method=POST,http.route=/subscriptions,http.scheme=http,http.target=/subscriptions,http.user_agent=HTTPie/1.0.3,line=null,log.module_path=sqlx::query,log.target=sqlx::query,otel.kind=server,request_id=332b488c-3956-4582-8db3-de850b80a762,subscriber_email=[e-mail],subscriber_name=dean,target=log)
[2021-10-13T10:22:19.719Z]  INFO: xxxxx/625 on LAPTOP-yyyyyyyyy: [SAVING NEW SUBSCRIBER DETAILS IN THE DATABASE - END] (elapsed_milliseconds=14,file=src/routes/subscriptions.rs,http.client_ip=127.0.0.1:46788,http.flavor=1.1,http.host=127.0.0.1:8000,http.method=POST,http.route=/subscriptions,http.scheme=http,http.target=/subscriptions,http.user_agent=HTTPie/1.0.3,line=32,otel.kind=server,request_id=332b488c-3956-4582-8db3-de850b80a762,subscriber_email=[e-mail],subscriber_name=dean,target=xxxxx::routes::subscriptions)
[2021-10-13T10:22:19.720Z]  INFO: xxxxx/625 on LAPTOP-yyyyyyyyy: [ADDING A NEW SUBSCRIBER - END] (elapsed_milliseconds=15,file=src/routes/subscriptions.rs,http.client_ip=127.0.0.1:46788,http.flavor=1.1,http.host=127.0.0.1:8000,http.method=POST,http.route=/subscriptions,http.scheme=http,http.target=/subscriptions,http.user_agent=HTTPie/1.0.3,line=13,otel.kind=server,request_id=332b488c-3956-4582-8db3-de850b80a762,subscriber_email=[e-mail],subscriber_name=dean,target=xxxxx::routes::subscriptions)

(JSONフォーマットで出力されているのですが、bunyanコマンドで整形しています。また、一部内容を改変しています。)

"Adding a new subscriber"、"Saving new subscriber details in the database"というスパンが始まったときと終わったとき、イベントが起こったときなどがログから読み取れると思います。

tracingの3つの主要概念

ここでtracingについての簡単な説明をします。tracingには3つの主要な概念Span、Event、Subscriberがあります。

Span

spanはタスクの始まりと終わりを示す概念です。span!マクロでスパンを生成し、enter関数でスパンのコンテクストを開始します。スパンがドロップされたとき、そのコンテクストは終了します。#[instrumet]アトリビュートを用いても、関数に対してコンテクストを開始できます。詳しくはドキュメントを参照ください。

let span = tracing::span!(tracing::Level::TRACE, "my_span");

let _guard = span.enter();

#[tracing::instrument(name="my span")]
pub fn my_func() {
  tracing::info!("Hello!");
}

Event

Eventは発生するログのことです。これも詳しくはドキュメントをご覧ください。

Subscriber

Subscriberは色々なことを担っていますが、例えば、イベントが発生したときや、spanのコンテクストに入ったときや出たときを観察しています。その事象をどう扱うかはSubscriberの実装次第です。最も一般的なのはログとして出力させることでしょう。tracingクレートはSubscriberトレイトを提供していて実装はしていません（いくつかのメソッドはデフォルト実装を持っています）。詳しくはドキュメントをご覧ください。
以下のような感じでSubscriberを使います。

use tracing::{subscriber::set_global_default, Subscriber};
use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
use tracing_subscriber::{layer::SubscriberExt, EnvFilter, Registry};
use tracing_subscriber::fmt::MakeWriter

pub fn get_subscriber(name: String, env_filter: String, sink: impl MakeWriter + Send + Sync + 'static) -> impl Subscriber + Send + Sync {
    let env_filter =
        EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(env_filter));
    let formatting_layer = BunyanFormattingLayer::new(name, sink);
    // subscriberを生成
    Registry::default()
        .with(env_filter)
        .with(JsonStorageLayer)
        .with(formatting_layer)
}

pub fn init_subscriber(subscriber: impl Subscriber + Send + Sync) {
    // subsriberをセット
    set_global_default(subscriber).expect("Failed to set subscriber");
}

(https://github.com/LukeMathWalker/zero-to-production から一部内容を変更して引用)

終わりに

本記事ではtracingクレートを紹介しました。ロギングはどんなアプリケーションでも必須の機能だと思うので、tracingという、とても優秀なライブラリがRustにあって嬉しいです。安心して実務で使えますね！(暗黒微笑

参考文献

• https://docs.rs/tracing/0.1.29/tracing/
• https://betterprogramming.pub/production-grade-logging-in-rust-applications-2c7fffd108a6
• https://github.com/LukeMathWalker/zero-to-production