actix-web に request_id 付きロガーを導入する

ふとしです。

request_id 付きログは調査に欠かせません。

必ず欲しいですよねえ。

後日知った tracing というクレートを使うと全てが簡単になり、以下のような色々は不要になりました。使いましょう。

前置き

Rails のようにどこからでも Rails.logger.error("Ah!") というように呼べるのが理想だったのですが、actix-web は 1 リクエストが 1 スレッドを専有するということはないので、スレッドローカルストレージ類を用いた request_id 共有ができません。

というわけで request_id を持つなんらかを各所にバケツリレーすることになりました。

[追記] tokio::task_local を使うことでバケツリレー不要にできる (他の手間はある) ので追記しました。

概要

「なんらか」として横断的関心事を取り扱う SharedContext を用意し、request_id およびそれをうまくロギングしてくれるロガーの slog::Logger オブジェクトを持たせます。

SharedContext 作成からハンドラーまでの注入は actix-web の web::Data もしくはミドルウェアで注入する web::ReqData を使います。

ハンドラーから主要なメソッド・関数へのバケツリレーは第一引数に必ず SharedContext 参照を取るというコード規約で対応します。(Go でよくみるやつですね)

Cargo.toml

[dependencies]
actix-web = { version = "4.5.1" }
slog = { version = "2.7.0" }
slog-async = { version = "2.8.0" }
slog-term = { version = "2.9.1" }
uuid = { version = "1.7.0", features = ["v4"] }

SharedContext を用意する

まず持たせるロガーがどんな感じか把握し、それから入れ物である SharedContext を実装します。

ロガーには slog を使う

request_id を前もって設定しておけば全てのログに挿入してくれる slog を使います。

slog は log クレートと違いログを書き出す際に書式などを設定した slog::Logger インスタンスを引数に取ります。今回は request_id を設定した slog::Logger をリクエストごとに作成し、SharedContext に持たせます。

slog::Logger は既にあるインスタンスから、新たに値を加えたインスタンスを作成できます。そこで、まず基本設定をした root_logger を作成し、そこから request_id を設定した子ロガーを作成する戦略をとります。

簡単に書くと以下。

use slog::Drain;

let drain = slog_term::FullFormat::new(slog_term::TermDecorator::new().build())
    .use_file_location()
    .build()
    .fuse();
let drain = slog_async::Async::new(drain).build().fuse();

// 基本設定済みのロガー
let root_logger = slog::Logger::root(drain, slog::o!())

// 実際に使うロガー
let logger = root_logger
    .new(slog::o!("request_id" => uuid::Uuid::new_v4().to_string()));

ログの書き出し。

slog::info!(logger, "Ah!");

ログ。

Feb 26 02:29:03.088 INFO[src/ah.rs:17:5] Ah!, request_id: 71557c08-bcf7-47b2-8488-fac9d006442f

SharedContext 実装

Go では context.Context という標準ライブラリを使用して似たようなことをしますが、Rust にはそのようなものはないので、最小限のものを用意します。

主要なメソッド・関数に渡されることになるので、差し替え可能なように trait にします。

pub trait SharedContext {
    /// 新しい request_id を発行した SharedContext オブジェクトインスタンスを作成する。
    /// リクエストごとに作成する。
    fn new(request_id: String, root_logger: &slog::Logger) -> Self;
    /// 単体でリクエストを識別するための request_id が必要な場合に使う
    fn request_id(&self) -> &str;
    /// ロガー
    fn logger(&self) -> &slog::Logger;
}

実装も用意。

#[derive(Clone)]
pub struct SharedContextImpl {
    request_id: String,
    logger: slog::Logger,
}

impl SharedContext for SharedContextImpl {
    fn new(request_id: String, root_logger: &slog::Logger) -> Self {
        Self {
            request_id: request_id.clone(),
            logger: root_logger.new(slog::o!("request_id" => request_id)),
        }
    }

    fn request_id(&self) -> &str {
        &self.request_id
    }

    fn logger(&self) -> &slog::Logger {
        &self.logger
    }
}

actix-web からハンドラーへの受け渡し

actix-web で任意のオブジェクトをリクエストごとにハンドラーに渡す方法として以下の二つがあるので、それぞれ紹介します。

• web::Data を使う
• ミドルウェアで挿入する (web::ReqData)

いずれも SharedContext trait のために型引数 C を引き回す必要があるのがちょっとだけ手間ですね。

web::Data 方式

作成・注入

use crate::foo_handler::foo_handler;
use crate::shared_context::{SharedContext, SharedContextImpl};

pub async fn start_server(root_logger: slog::Logger) -> Result<(), Box<dyn std::error::Error>> {
    _start_server::<SharedContextImpl>(root_logger).await
}

/// 型引数を表出させないために関数を分けただけで深い意味はない。
async fn _start_server<C>(root_logger: slog::Logger) -> Result<(), Box<dyn std::error::Error>>
where
    C: SharedContext + 'static,
{
    actix_web::HttpServer::new(move || {
        actix_web::App::new()
            .app_data(actix_web::web::Data::new(C::new(
                uuid::Uuid::new_v4().to_string(),
                &root_logger,
            )))
            .route("/foo", actix_web::web::get().to(foo_handler::<C>))
    })
    .bind(("127.0.0.1", 3333))?
    .run()
    .await?;

    Ok(())
}

ハンドラー

pub async fn foo_handler<C>(ctx: actix_web::web::Data<C>) -> actix_web::HttpResponse
where
    C: SharedContext,
{
    slog::info!(ctx.logger(), "foo_handler");

    match foo_use_case(ctx.as_ref()).await {
        Ok(_) => actix_web::HttpResponse::Ok().body("Ah!"),
        Err(e) => {
            slog::error!(ctx.logger(), "foo_use_case failed: {}", e);
            actix_web::HttpResponse::InternalServerError().finish()
        }
    }
}

ミドルウェアで挿入する方式

作成・注入

middleware 実装

root_logger コピー避けのために Arc を使う。

use std::future::{ready, Ready};
use std::sync::Arc;

use crate::SharedContext;
use actix_web::{
    dev::{forward_ready, Service, ServiceRequest, ServiceResponse, Transform},
    Error,
};

pub struct AddSharedContextMiddleware<C: SharedContext + 'static> {
    _c: std::marker::PhantomData<C>,
    root_logger: Arc<slog::Logger>,
}

impl<C: SharedContext + 'static> AddSharedContextMiddleware<C> {
    pub fn new(root_logger: Arc<slog::Logger>) -> Self {
        Self {
            _c: std::marker::PhantomData,
            root_logger,
        }
    }
}

impl<S, B, C> Transform<S, ServiceRequest> for AddSharedContextMiddleware<C>
where
    S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = actix_web::Error>,
    C: SharedContext + 'static,
{
    type Response = ServiceResponse<B>;
    type Error = Error;
    type Future = Ready<Result<Self::Transform, Self::InitError>>;
    type Transform = Transformed<S, C>;
    type InitError = ();

    fn new_transform(&self, service: S) -> Self::Future {
        ready(Ok(Transformed {
            service,
            root_logger: self.root_logger.clone(),
            _c: std::marker::PhantomData,
        }))
    }
}

pub struct Transformed<S, C> {
    service: S,
    root_logger: Arc<slog::Logger>,
    _c: std::marker::PhantomData<C>,
}

impl<S, B, C> Service<ServiceRequest> for Transformed<S, C>
where
    S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = actix_web::Error>,
    C: SharedContext + 'static,
{
    type Response = ServiceResponse<B>;
    type Error = Error;
    type Future = S::Future;

    forward_ready!(service);

    fn call(&self, req: ServiceRequest) -> Self::Future {
        use actix_web::HttpMessage;

        req.extensions_mut().insert(C::new(
            uuid::Uuid::new_v4().to_string(),
            self.root_logger.as_ref(),
        ));

        self.service.call(req)
    }
}

middleware 追加

pub async fn start_server(root_logger: slog::Logger) -> Result<(), Box<dyn std::error::Error>> {
    _start_server2::<SharedContextImpl>(root_logger).await
}


/// 型引数を表出させないために関数を分けただけで深い意味はない。
async fn _start_server2<C>(root_logger: slog::Logger) -> Result<(), Box<dyn std::error::Error>>
where
    C: SharedContext + Clone + 'static,
{
    let root_logger = Arc::new(root_logger);

    actix_web::HttpServer::new(move || {
        actix_web::App::new()
            .wrap(crate::middleware::AddSharedContextMiddleware::<C>::new(
                root_logger.clone(),
            ))
            .route(
                "/foo",
                actix_web::web::get().to(foo_handler_for_middleware::<C>),
            )
    })
    .bind(("127.0.0.1", 3333))?
    .run()
    .await?;

    Ok(())
}

ハンドラー以下の実装

主要な関数・メソッドでは SharedContext オブジェクトを必ず第一引数に取る、というコード規約を定めて運用します。

pub async fn foo_handler<C>(ctx: actix_web::web::Data<C>) -> actix_web::HttpResponse
where
    C: SharedContext,
{
    slog::info!(ctx.logger(), "foo_handler");

    match foo_use_case(ctx.as_ref()).await {
        Ok(_) => actix_web::HttpResponse::Ok().body("Ah!"),
        Err(e) => {
            slog::error!(ctx.logger(), "foo_use_case failed: {}", e);
            actix_web::HttpResponse::InternalServerError().finish()
        }
    }
}

pub async fn foo_use_case<C>(ctx: &C) -> Result<(), Box<dyn std::error::Error>>
where
    C: SharedContext,
{
    slog::info!(ctx.logger(), "foo_use_case");
    fetch_foo(ctx).await?;
    Ok(())
}

pub async fn fetch_foo<C>(ctx: &C) -> Result<(), Box<dyn std::error::Error>>
where
    C: SharedContext,
{
    slog::info!(ctx.logger(), "fetch_foo");
    Ok(())
}

起動

use actix_web_request_id_logging::start_server;

#[actix_web::main]
async fn main() -> Result<(), Box<dyn std::error::Error>> {
    start_server(create_root_logger()).await
}

fn create_root_logger() -> slog::Logger {
    use slog::Drain;

    let drain = slog_term::FullFormat::new(slog_term::TermDecorator::new().build())
        .use_file_location()
        .build()
        .fuse();
    let drain = slog_async::Async::new(drain).build().fuse();
    slog::Logger::root(drain, slog::o!())
}

おわりに

これでひとまず request_id つきのログが問題なく発行できるようになりました。

インスタンスバケツリレーしかなさそうとなったときはどうしようかと思いましたが、ロギングは横断的関心事で誰もが知ってて良い -> 必ず第一引数に SharedContext を取るという規約にすれば良い、と決めた後は普通でした。

production 環境では slog-term のかわりに slog-json を使って構造化ログにするとか細かいあれこれはまた別の話なので、よしなに。

[追記] tokio::task_local 方式

tokio::task_local は、スコープ内で同じ値を参照できるタスクローカルストレージを作成します。

メモ

SharedContext の実体が欲しいので、middleware 方式のハンドラー部分のみ書き換えます。また Box<dyn SharedContext> を使おうとしたところ error[E0391]: cycle detected when checking effective visibilities が発生したので、とりあえず実装した構造体を直で指定します。

ハンドラーの実装

task_local! でタスクローカルストレージを定義し、設定した値を foo_use_case2 内の全てで使えるように、SHARED_CONTEXT.scope で処理全体をブロックで囲みます。

task_local! {
  pub  static SHARED_CONTEXT: SharedContextImpl;
}

pub async fn foo_handler_for_lk(
    ctx: actix_web::web::ReqData<SharedContextImpl>,
) -> actix_web::HttpResponse {
    let ctx = ctx.into_inner();
    slog::info!(ctx.logger(), "foo_handler_for_lk");

    SHARED_CONTEXT
        // 値の設定とスコープの作成
        .scope(ctx, async {
            // この内部でしか ctx は有効にならない
            match foo_use_case2().await {
                Ok(_) => actix_web::HttpResponse::Ok().body("Ah!"),
                Err(e) => {
                    // タスクローカルストレージ内の値を使うには、必ず with 経由になる
                    SHARED_CONTEXT.with(|ctx| {
                        slog::error!(&ctx.logger(), "foo_use_case failed: {}", e);
                    });
                    actix_web::HttpResponse::InternalServerError().finish()
                }
            }
        })
        .await
}

ハンドラー以下

ctx を使いたいときは SHARED_CONTEXT.with を呼びます。

pub async fn foo_use_case2() -> Result<(), Box<dyn std::error::Error>> {
    SHARED_CONTEXT.with(|ctx| {
        slog::info!(ctx.logger(), "foo_use_case2");
    });
    fetch_foo2().await?;
    Ok(())
}

pub async fn fetch_foo2() -> Result<(), Box<dyn std::error::Error>> {
    SHARED_CONTEXT.with(|ctx| {
        slog::info!(ctx.logger(), "fetch_foo2");
    });
    Ok(())
}

おわりに 2

調査不足でしたが、このように tokio::task_local を使えばバケツリレー不要になることがわかりました。

必ず SHARED_CONTEXT.with が必要になる、新たなタスクを spawn した場合は、あらためて SHARED_CONTEXT.scope が必要になるなど、バケツリレーとはちがった手間がありますが、リレーが途切れても使用できるという利点があります。