Rust(Rocket)でtracingを使った詳細なエラーログ出力とエラーハンドリングの改善をしてみました
Tags: rust, rocket, tracing, sqlx
Published: 2023-12-06 13:14:12

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

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

### リポジトリ
リポジトリは下記です。
https://github.com/edo1z/rust-rocket-sqlx-sample

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

エラー発生箇所のファイルパス、行番号、エラー発生までの経緯（どのファイルのどの関数を辿ったのか）などを、出力するために、[tracing](https://github.com/tokio-rs/tracing/tree/v0.1.x)クレートを利用しました。

### ログ出力例

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

```log
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の関数はこんな感じになっております。

```rust
#[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](https://github.com/tokio-rs/tracing/tree/v0.1.x)の機能で、これを書いておくと、エラーログ出力時に、ログ発生の経緯にこの関数のnameや、引数が出力されます。controller, use_case, repositoryに全部書いておくと、全部順番に出力されるので、一目でログ出力時の実行順序が分かります。ただ、ログに引数の値を出力させるというのは、かなり危険な香りがしますので、基本的には`skip_all`を設定して、表示させても問題なく、且つ、表示させたいものは、個別に`fields`で設定するという方針にしています。これは、危ないから使わないという選択肢もあるのかもなーとは思いました。どうもデフォルトでOFFには簡単にはできなそうだったのですが、もしデフォルトOFFができると、より安心かなあと思っております。

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

```rust
#[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](https://github.com/dtolnay/thiserror)クレートという便利ツールを使うことで、記述量が激減しました。`from`アトリビュートを設定することで、`sqlx::Error`は`DbRepoError::SqlxError`に自動変換されます。これで、各エラーの詳細を残しつつ、`DbRepoError`としてuse_caseに渡せるようになりました。

```rust
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`は現在[こちら](https://github.com/edo1z/rust-rocket-sqlx-sample/blob/v0.2.0/src/error/app_error.rs)のようになっております。`DbRepoError`が自動的に`AppError::DbError`に変換されるようになっています。また、Rocketの`Responder`が実装されており、レスポンスにそのまま`AppError`が使えるようになっております。そして、レスポンス時のステータスコードも紐づけされています。その他、anyhowを真似した`app_err`関数と、`app_err!`, `app_err_bail!`, `app_err_ensure!`マクロを作成しました。

#### AppErrorのコード（一部）

```rust
#[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で、細かいエラーハンドリングが出来るようになりました。

```rust
#[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化（今エラーメッセージがテキスト）