「深挖Rust」错误处理 — 3

「这是我参与2022首次更文挑战的第 4 天，活动详情查看：2022首次更文挑战」。

面向用户的错误报告

这部分我们从错误报告开始。目前我们遇到错误时，现有的错误记录工作实现的很好吗？

我们写一个快速测试开始：

//! tests/api/subscriptions.rs
// [...]

#[tokio::test]
async fn subscribe_fails_if_there_is_a_fatal_database_error() {
    // Arrange
    let app = spawn_app().await;
    let body = "name=le%20guin&email=ursula_le_guin%40gmail.com";
    // Sabotage the database
    sqlx::query!("ALTER TABLE subscription_tokens DROP COLUMN subscription_token;",)
        .execute(&app.db_pool)
        .await
        .unwrap();

    // Act
    let response =  app.post_subscriptions(body.into()).await;

    // Assert
    assert_eq!(response.status().as_u16(), 500);
}

测试直接通过。然后我们看看测试程序产生的日志：

确保你运行在 tracing-actix-web = 0.4.0-beta.8、tracing-bunyan-formatter = 0.2.4 和 actix-web 4.0.0-beta.8 !

# sqlx logs are a bit spammy, cutting them out to reduce noise
export RUST_LOG="sqlx=error,info"
export TEST_LOG=enabled
cargo t subscribe_fails_if_there_is_a_fatal_database_error | bunyan

输出结果如下：

INFO: [HTTP REQUEST - START]
 INFO: [ADDING A NEW SUBSCRIBER - START]
 INFO: [SAVING NEW SUBSCRIBER DETAILS IN THE DATABASE - START]
 INFO: [SAVING NEW SUBSCRIBER DETAILS IN THE DATABASE - END]
 INFO: [STORE SUBSCRIPTION TOKEN IN THE DATABASE - START]
ERROR: [STORE SUBSCRIPTION TOKEN IN THE DATABASE - EVENT] Failed to execute query:
        Database(PgDatabaseError {
          severity: Error,
          code: "42703",
          message:
              "column 'subscription_token' of relation
               'subscription_tokens' does not exist",
          ...
        })
    target=zero2prod::routes::subscriptions
 INFO: [STORE SUBSCRIPTION TOKEN IN THE DATABASE - END]
 INFO: [ADDING A NEW SUBSCRIBER - END]
ERROR: [HTTP REQUEST - EVENT] Error encountered while
        processing the incoming HTTP request: ""
    exception.details="",
    exception.message="",
    target=tracing_actix_web::middleware
 INFO: [HTTP REQUEST - END]
    exception.details="",
    exception.message="",
    target=tracing_actix_web::root_span_builder,
    http.status_code=500

你可以在大脑里面大致想想如何阅读这样的东西？理想情况下，你从结尾开始 → 在请求处理结束时产生的日志记录。

INFO: [HTTP REQUEST - END]
    exception.details="",
    exception.message="",
    target=tracing_actix_web::root_span_builder,
    http.status_code=500

这告诉我们什么？该请求返回了一个500状态代码 → 它失败了。我们没有从中获取到更多的信息：exception.details 和 exception.message 都是空的。

如果我们看下一个由 tracing_actix_web 发出的日志，日志情况不会好到哪里去。

ERROR: [HTTP REQUEST - EVENT] Error encountered while
        processing the incoming HTTP request: ""
    exception.details="",
    exception.message="",
    target=tracing_actix_web::middleware

没有任何可分析的信息。我们需要继续寻找。

ERROR: [STORE SUBSCRIPTION TOKEN IN THE DATABASE - EVENT] Failed to execute query:
        Database(PgDatabaseError {
          severity: Error,
          code: "42703",
          message:
              "column 'subscription_token' of relation
               'subscription_tokens' does not exist",
          ...
        })
    target=zero2prod::routes::subscriptions

当我们试图与数据库交互中出了问题：我们期望在 subscription_tokens 表中看到 subscription_tokem column，但由于某些原因，它不在那里。

这个信息其实是很有用的!但这是导致500的原因吗？光看日志很难说。开发人员必须检查一下代码，检查日志行来自哪里，并确保它确实是问题的原因。

这可以做到，但需要时间：如果 [HTTP REQUEST - END] 日志记录在 exception.details 和exception.message 中报告一些关于根本原因的有用信息，那就容易多了。