“This is my fourth day of participating in the First Challenge 2022. For more details: First Challenge 2022.”

User-oriented error reporting

This section starts with error reporting. Is the current error logging working well when we encounter errors?

Let’s write a quick test to start:

/ /! 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 databasesqlx::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);
}
Copy the code

The test passed straight away. Then let’s look at the log generated by the test program:

Make sure you are running tracing- Actix-Web = 0.4.0-beta.8, tracing-bunyan-formatter = 0.2.4, and 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
Copy the code

The following output is displayed:

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 encounteredwhile
        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
Copy the code

You can sort of figure out in your head how to read something like that, right? Ideally, you start at the end → the log generated at the end of the request processing.

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

What does that tell us? The request returned a 500 status code → it failed. We don’t get any more information from this: Exception. details and exception.message are empty.

If we look at the next log issued by tracing_actix_web, the log situation is not much better.

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

There is no information that can be analyzed. We need to keep looking.

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::subscriptionsCopy the code

Something went wrong when we tried to interact with the database: We expected to see the Subscription_tokem column in the Subscription_tokens table, but for some reason it wasn’t there.

This information is actually very useful! But is that what caused 500? It’s hard to tell by looking at the logs. The developer must take a look at the code, check where the log line is coming from, and ensure that it is indeed the cause of the problem.

This can be done, but it takes time: it would be much easier if the [HTTP Request-end] logging reported some useful information about the root cause in exception.details and exception.message.