Rust(Rocket)でtracingを使った詳細なエラーログ出力とエラーハンドリングの改善をしてみました

Rust の Web フレームワークのRocket で作っている Web アプリで、tracing を使った詳細なエラーログ出力とエラーハンドリングの改善をしてみました。

目次

• 前提
  • リポジトリ
• tracing を使った詳細なエラーログ出力
  • ログ出力例
  • コードサンプル
    • instrument 属性
    • log_into!マクロ
• エラーハンドリングの改善
  • ポイント ① DbRepoError でラップ
  • ポイント ② use_case で詳細をハンドリングしつつ AppError に自動変換
    • AppError のコード（一部）
    • use_case のコードサンプル
• 今後やりたいこと

前提

クリーンアーキテクチャっぽい構成を想定しています。controller, use_case, repository があります。repository では sqlx で PostgreSQL を使います。

リポジトリ

リポジトリは下記です。

https://github.com/edo1z/rust-rocket-sqlx-sample

tracing を使った詳細なエラーログ出力

エラー発生箇所のファイルパス、行番号、エラー発生までの経緯（どのファイルのどの関数を辿ったのか）などを、出力するために、tracing クレートを利用しました。

ログ出力例

結果的にこのようなログが出力されるようになりました。

2023-12-05T07:43:24.644738Z ERROR user_controller/update{id=12}:user_use_case/update{id=12}:user_repo/update{id=12}: rust_rocket_sqlx_sample::repositories::user_repo: [DbRepoError::SqlxError] no rows returned by a query that expected to return at least one row (src/repositories/user_repo.rs:85)

user_controllerのupdate関数（引数 id が 12）から、user_use_caseのupdate関数（引数が 12）に行き、そこから、user_repoのupdate関数（引数が 12）に行って、そこでエラーが発生しているということが分かりまっす。そして、エラー発生箇所は、user_repo.rs の 85 行目であり、エラーはDbRepoError::SqlxErrorであり、データがなかったことが分かります。分かりやすくなりました！

コードサンプル

repository の関数はこんな感じになっております。

#[instrument(name = "user_repo/update", skip_all, fields(id = %id))]
async fn update(
    &self,
    con: &mut PgConnection,
    id: i32,
    name: &String,
) -> Result<User, DbRepoError> {
    query_as!(
        User,
        "UPDATE users SET name = $1 WHERE id = $2 RETURNING *",
        name,
        id
    )
    .fetch_one(&mut *con)
    .await
    .map_err(|e| log_into!(e, DbRepoError))
}

instrument 属性

最初の行のinstrument属性は、tracing の機能で、これを書いておくと、エラーログ出力時に、ログ発生の経緯にこの関数の name や、引数が出力されます。controller, use_case, repository に全部書いておくと、全部順番に出力されるので、一目でログ出力時の実行順序が分かります。ただ、ログに引数の値を出力させるというのは、かなり危険な香りがしますので、基本的にはskip_allを設定して、表示させても問題なく、且つ、表示させたいものは、個別にfieldsで設定するという方針にしています。これは、危ないから使わないという選択肢もあるのかもなーとは思いました。どうもデフォルトで OFF には簡単にはできなそうだったのですが、もしデフォルト OFF ができると、より安心かなあと思っております。

log_into!マクロ

最後の行の、log_into!マクロは下記になっております。

#[macro_export]
macro_rules! log_into {
    ($error:expr, $target_type:ty) => {{
        let converted_error: $target_type = $error.into();
        tracing::error!("{} ({}:{})", converted_error, file!(), line!());
        converted_error
    }};
}

エラーをtarget_typeの別のエラーに変換して、そのエラーをファイルパスと行番号と共に、tracing のerror!を使ってログ出力するマクロになります。ただの関数ですと、ファイルパス・行番号はこの関数のファイルパス及び行番号になりますので、それもあって、マクロにしております。もしファイルパス・行番号が不要であれば、自動でエラーは変換できるので、このようなマクロを使う必要はありません。

エラーハンドリングの改善

use_case で repository 等で発生したエラーの詳細を把握し、細かくエラーハンドリングできるようにしつつ、なるべくシンプルにしたいと考えていまして、現状としては、結構いい感じな気がしてます。

ポイント ① DbRepoError でラップ

DbRepoErrorは下記です。thiserror クレートという便利ツールを使うことで、記述量が激減しました。fromアトリビュートを設定することで、sqlx::ErrorはDbRepoError::SqlxErrorに自動変換されます。これで、各エラーの詳細を残しつつ、DbRepoErrorとして use_case に渡せるようになりました。

use thiserror::Error;

#[derive(Debug, Error)]
pub enum DbRepoError {
    #[error("[DbRepoError::SerdeError] {0}")]
    SerdeError(#[from] serde_json::Error),
    #[error("[DbRepoError::SqlxError] {0}")]
    SqlxError(#[from] sqlx::Error),

    #[cfg(test)]
    #[error("Dummy error for testing")]
    DummyTestError,
}

ポイント ② use_case で詳細をハンドリングしつつ AppError に自動変換

AppErrorは現在こちら のようになっております。DbRepoErrorが自動的にAppError::DbErrorに変換されるようになっています。また、Rocket のResponderが実装されており、レスポンスにそのままAppErrorが使えるようになっております。そして、レスポンス時のステータスコードも紐づけされています。その他、anyhow を真似したapp_err関数と、app_err!, app_err_bail!, app_err_ensure!マクロを作成しました。

AppError のコード（一部）

#[derive(Debug, Error)]
pub enum AppError {
    #[error("Database Error")]
    DbError(#[from] DbRepoError),
    #[error("Bad Request")]
    BadRequest,
    #[error("Unauthorized")]
    Unauthorized,
    #[error("Forbidden")]
    Forbidden,
    #[error("Not Found")]
    NotFound,
    #[error("Internal Server Error")]
    InternalServerError,
    #[error("{message}")]
    CustomError { status_code: u16, message: String },
}

impl AppError {
    pub fn new(status_code: u16, message: &str) -> Self {
        AppError::CustomError {
            status_code,
            message: message.to_string(),
        }
    }

    pub fn status_code(&self) -> u16 {
        match self {
            AppError::DbError(_) => 500,
            AppError::BadRequest => 400,
            AppError::Unauthorized => 401,
            AppError::Forbidden => 403,
            AppError::NotFound => 404,
            AppError::InternalServerError => 500,
            AppError::CustomError { status_code, .. } => *status_code,
        }
    }
}

use_case のコードサンプル

下記のdeleteは、fromを使って自動変換させています。updateでは、対象データが存在しない場合は、BadRequestエラーを返すようにしています。このように、use_case で、細かいエラーハンドリングが出来るようになりました。

#[instrument(name = "user_use_case/update", skip_all, fields(id = %id))]
async fn update(
    &self,
    repos: &Repos,
    db_con: &mut DbCon,
    id: i32,
    name: &String,
) -> Result<User, AppError> {
    repos
        .user
        .update(&mut *db_con, id, name)
        .await
        .map_err(|e| {
            if let DbRepoError::SqlxError(sqlx::Error::RowNotFound) = &e {
                AppError::BadRequest
            } else {
                AppError::from(e)
            }
        })
}

#[instrument(name = "user_use_case/delete", skip_all, fields(id = %id))]
async fn delete(&self, repos: &Repos, db_con: &mut DbCon, id: i32) -> Result<(), AppError> {
    repos
        .user
        .delete(&mut *db_con, id)
        .await
        .map_err(|e| AppError::from(e))
}

今後やりたいこと

• メトリクスの収集
• Datadog で集計・グラフ表示
• Datadog 経由で Slack 通知
• レスポンスの json 化（今エラーメッセージがテキスト）