RustのAPIサーバーでCloud Loggingにいい感じにログを出す旅

本記事は ミクシィグループ Advent Calendar 2021 の25日目の記事です。

はじめに

私が現在所属しているプロジェクトで、とある社内ツールのAPIサーバーをRustで書くという運びにし、現在絶賛開発中です。
APIサーバーのデプロイ先はGoogle Cloudのいずれかのサービスの上で走ることは決まっているという状況です。
というわけで必要になってくるのがCloud Loggingでいい感じなログを出すという工程なわけですが適当にググっても良さそうなのが出なかったので自分で作ってみることにしました。(あれば知りたい

やっていく

まず現状のAPIの構成としてaxumというwebフレームワークを使っています。
本稿ではこのWebフレームワークと連携したログを出していきます。

Logの形式

まずドキュメントを確認し必要なパラメータと出したいパラメータを合わせた構造体を作ります。
https://cloud.google.com/logging/docs/agent/logging/configuration

#[derive(Serialize)]
struct Log {
    severity: String,
    message: Payload,
    timestamp: String,
    trace: String,
}

#[derive(Serialize, Deserialize)]
pub struct Payload {
    pub x_request_id: Option<String>,
    pub host: Option<String>,
    pub user_agent: Option<String>,
    pub method: Option<String>,
    pub uri: Option<String>,
    pub status: Option<String>,
    pub latency: Option<Duration>,
    pub kind: LogKind,
    pub error_message: Option<ErrorMessage>,
}

#[derive(Serialize, Deserialize)]
pub enum LogKind {
    Request,
    Response,
    Err,
}

#[derive(Serialize, Deserialize)]
pub struct ErrorMessage {
    pub r#type: String,
    pub title: String,
    pub detail: String,
}

※この記事を書いている途中でmessageは文字列とJSONどちらでも大丈夫なんだっけという不安がよぎる

ロガーのセットアップ

ログ出力にはenv_logger等のクレートがありますが本稿ではfernクレートを使います。
formatの中でserde_json::json!を使い、先ほど紹介したLog構造体をJSON形式に変換しログとして出力します。
match payloadではPayload構造体の形式でない文字列がtracing::info!等で出力された場合Payload構造体の形式で整形しています。これは別クレートのログが流れてくるときに対処しているものです。

fern::Dispatch::new()
    .format(|out, message, record| {
        let ts = chrono::Utc::now().format("%Y/%m/%dT%H:%M:%S%z");
        let payload: Result<Payload, serde_json::Error> =
            serde_json::from_str(&message.to_string());
        out.finish(format_args!(
            "{}",
            serde_json::json!(Log {
                severity: record.level().to_string(),
                message: match payload {
                    Ok(payload) => payload,
                    Err(_) => Payload {
                        x_request_id: None,
                        host: None,
                        user_agent: None,
                        method: None,
                        uri: None,
                        status: None,
                        latency: None,
                        kind: LogKind::Err,
                        error_message: Some(ErrorMessage {
                            r#type: "primitive".to_string(),
                            title: "primitive error".to_string(),
                            detail: message.to_string()
                        })
                    },
                },
                timestamp: ts.to_string(),
                trace: match record.level().as_str() {
                    "TRACE" =>
                        record.file().unwrap_or("unknown").to_string()
                            + ":"
                            + &record.line().unwrap_or(0).to_string(),
                    _ => "".to_string(),
                }
            })
            .to_string()
        ))
    })
    .chain(std::io::stdout())
    .level(log::LevelFilter::Error)
    .level_for("api", log::LevelFilter::Debug)
    .apply()
    .unwrap();

実際に出力されたもの

ターミナルでcurl localhost:3000/usersを実行した結果が以下になります。
Serdeとserde_jsonで簡単に構造体をJSONに変換できるのでとても便利です。

{"message":{"error_message":null,"host":"localhost:3000","kind":"Request","latency":null,"method":"GET","status":null,"uri":"/users","user_agent":"curl/7.64.1","x_request_id":"c41bc62f-7fe1-4376-a239-e34aa0602ebe"},"severity":"INFO","timestamp":"2021/12/24T10:47:32+0000","trace":""}
{"message":{"error_message":null,"host":null,"kind":"Response","latency":{"nanos":45582600,"secs":0},"method":null,"status":"200","uri":null,"user_agent":null,"x_request_id":"c41bc62f-7fe1-4376-a239-e34aa0602ebe"},"severity":"INFO","timestamp":"2021/12/24T10:47:32+0000","trace":""}

requestのログを整形したもの

{
    "message": {
        "error_message": null,
        "host": "localhost:3000",
        "kind": "Request",
        "latency": null,
        "method": "GET",
        "status": null,
        "uri": "/users",
        "user_agent": "curl/7.64.1",
        "x_request_id": "c41bc62f-7fe1-4376-a239-e34aa0602ebe"
    },
    "severity": "INFO",
    "timestamp": "2021/12/24T10:47:32+0000",
    "trace": ""
}

axumのトレースから出力する

axumのRouter生成部分からの抜粋です。on_requestとon_responseで受け取った値をtracing::info!でPayload構造体の形式のものを流しています。

Router::new()
    .route("/users", get(handlers::users::get))
    .layer(
        ServiceBuilder::new()
            .set_x_request_id(MakeRequestUuid)
            .layer(AddExtensionLayer::new(app_state))
            .layer(
                TraceLayer::new_for_http()
                    .on_request(|request: &Request<_>, _span: &Span| {
                        tracing::info!(
                            "{}",
                            serde_json::json!(Payload {
                                x_request_id: Some(
                                    request.headers()["x-request-id"]
                                        .to_str()
                                        .unwrap()
                                        .to_string()
                                ),
                                host: Some(
                                    request.headers()["host"].to_str().unwrap().to_string()
                                ),
                                user_agent: Some(
                                    request.headers()["user-agent"]
                                        .to_str()
                                        .unwrap()
                                        .to_string()
                                ),
                                method: Some(request.method().to_string()),
                                uri: Some(request.uri().to_string()),
                                status: None,
                                latency: None,
                                kind: LogKind::Request,
                                error_message: None
                            })
                            .to_string()
                        )
                    })
                    .on_response(|response: &Response<_>, latency: Duration, _span: &Span| {
                        tracing::info!(
                            "{}",
                            serde_json::json!(Payload {
                                x_request_id: Some(
                                    response.headers()["x-request-id"]
                                        .to_str()
                                        .unwrap()
                                        .to_string()
                                ),
                                status: Some(response.status().as_str().to_string()),
                                latency: Some(latency),
                                host: None,
                                user_agent: None,
                                method: None,
                                uri: None,
                                kind: LogKind::Response,
                                error_message: None
                            })
                            .to_string()
                        )
                    })
                    .on_body_chunk(())
                    .on_eos(()),
            )
            .propagate_x_request_id(),
    )

結果

ログの出力形式をカスタマイズしてCloud Loggingに認識してもらえそうなログの出力ができた。

おわりに

アドベントカレンダー前日にネタを考えて実装までやりきりました。
もうすこし工夫すればより簡単にログが吐けるはずなので修正を重ねていきたいです。