Is tracing intended to be used as I am using it? How can I trace errors chain?

[frederikhors]

I'm using async-graphql and axum.

This is a reproduction of the issue: https://github.com/frederikhors/iss-async-graphql-error-handling.

To start:

• cargo run

If you open the GraphiQL client at http://localhost:8000, you can use the below query to simulate what I'm trying to understand:

mutation {
  mutateWithError
}

The backend response is:

{
  "data": null,
  "errors": [
    {
      "message": "I cannot mutate now, sorry!",
      "locations": [
        /*...*/
      ],
      "path": ["mutateWithError"]
    }
  ]
}

I like this, but what I don't understand is the tracing part:

2022-09-29T17:01:14.249236Z  INFO async_graphql::graphql:84: close, time.busy: 626µs, time.idle: 14.3µs
  in async_graphql::graphql::parse
  in async_graphql::graphql::request

2022-09-29T17:01:14.252493Z  INFO async_graphql::graphql:108: close, time.busy: 374µs, time.idle: 8.60µs
  in async_graphql::graphql::validation
  in async_graphql::graphql::request

2022-09-29T17:01:14.254592Z  INFO async_graphql::graphql:146: error, error: I cannot mutate now, sorry!
  in async_graphql::graphql::field with path: mutateWithError, parent_type: Mutation, return_type: String!
  in async_graphql::graphql::execute
  in async_graphql::graphql::request

2022-09-29T17:01:14.257389Z  INFO async_graphql::graphql:136: close, time.busy: 2.85ms, time.idle: 30.8µs
  in async_graphql::graphql::field with path: mutateWithError, parent_type: Mutation, return_type: String!
  in async_graphql::graphql::execute
  in async_graphql::graphql::request

2022-09-29T17:01:14.260729Z  INFO async_graphql::graphql:122: close, time.busy: 6.31ms, time.idle: 7.80µs
  in async_graphql::graphql::execute
  in async_graphql::graphql::request

2022-09-29T17:01:14.264606Z  INFO async_graphql::graphql:56: close, time.busy: 16.1ms, time.idle: 22.6µs
  in async_graphql::graphql::request

Do you see the INFO async_graphql::graphql:146: error, error: I cannot mutate now, sorry!?

1. Why is it an INFO event? I would expect it to be an ERROR event.

2. And where is the innter error this is a DB error?

Code

The code is very simple:

pub struct Mutation;

#[Object]
impl Mutation {
    async fn mutate_with_error(&self) -> async_graphql::Result<String> {
        let new_string = mutate_with_error().await?;

        Ok(new_string)
    }
}

async fn mutate_with_error() -> anyhow::Result<String> {
    match can_i_mutate_on_db().await {
        Ok(s) => Ok(s),
        Err(err) => Err(err.context("I cannot mutate now, sorry!")),
    }
}

async fn can_i_mutate_on_db() -> anyhow::Result<String> {
    bail!("this is a DB error!")
}

async fn graphql_handler(
    schema: Extension<Schema<Query, Mutation, EmptySubscription>>,
    req: GraphQLRequest,
) -> GraphQLResponse {
    schema.execute(req.into_inner()).await.into()
}

[hawkw]

I'm not familiar with the async-graphql library, but it looks like the tracing event is being emitted by that library in this case. The event is at the INFO level rather than the ERROR level because that library's authors chose to record the event at INFO: https://github.com/async-graphql/async-graphql/blob/ad05baf79aea55a0827291abf55af5ce7cc8d386/src/extensions/tracing.rs#L146-L148

Similarly, the reason the tracing event includes only the top-level error message is because the async-graphql authors chose to write

error = %err.message(),

when emitting the tracing event I linked above. That code is saying "record a field named error whose value is err.message(), formatted using fmt::Display.

If the error type in this code implements std::error::Error, it should instead be possible to use the tracing::Value implementation for dyn Error trait objects, in which case, the tracing subscriber would receive the value as a &dyn Error + 'static. This would allow it to record the error chain as well as the top-level error's message, which many tracing::Subscriber implementations (such as the fmt subscriber you're using) will do.

To summarize, it's possible to record errors the way you want using tracing, but the code in async-graphql isn't recording the error the way you want to. It's possible that crate's maintainers would accept a pull request and/or issue to change how the error event is recorded. I think all that's necessary should be to change the code I linked above to something like this:

                tracinglib::error!(target: "async_graphql::graphql",
                                   error = &err
                                   "error");

or, if the compiler doesn't like that, you may need to explicitly cast to dyn Error:

                tracinglib::error!(target: "async_graphql::graphql",
                                   error = &err as &(dyn std::error::Error + 'static)
                                   "error");

If the maintainers aren't interested in accepting a PR to change how the event is recorded, you could probably use a modified version of their TracingExtension that changes how errors are recorded in your own code...but, again, I'm not personally familiar with that crate, so I'm not totally sure if it's possible to implement extensions in user code.

[frederikhors]

I think this doesn't print because of these lines: https://github.com/async-graphql/async-graphql/blob/master/src/error.rs#L59-L68.

[hawkw]

I tried the code you suggested:

async fn resolve(
    //...
    next.run(ctx, info)
        .map_err(|err| {
            tracinglib::error!(target: "async_graphql::graphql",
                              error = %err,
                              "error");
            err
        })
        .instrument(span)
        .await
}

the event now is an ERROR one but I still can't get my errors chain:

... snip ...

2022-09-29T19:59:20.354956Z ERROR async_graphql::graphql:146: error, error: I cannot mutate now, sorry!
  in async_graphql::graphql::field with path: mutateWithError, parent_type: Mutation, return_type: String!
  in async_graphql::graphql::execute
  in async_graphql::graphql::request

... snip ...

I see nowhere this is a DB error!.

Why?

You are still recording the error using its std::fmt::Display implementation, rather than its std::error::Error implementation. The % sigil tells tracing to record the error as a &dyn fmt::Display trait object. If you look at the code I suggested, you'll see that I didn't use the % sigil in either suggestion.

When the error is recorded using the Error trait, the tracing subscriber will format the rest of the error chain.

[frederikhors]

Oh!

Now the error is:

147 | ...                   error = &err as &(dyn std::error::Error + 'static),
    |                               ^^^^ the trait `StdError` is not implemented for `ServerError`
    |
    = note: required for the cast from `ServerError` to the object type `dyn StdError`

Using:

                tracinglib::error!(target: "async_graphql::graphql",
                                error = &err as &(dyn std::error::Error + 'static),
                                "error");

[hawkw]

Looking at the documentation for async-graphql, it looks like the ServerError type does not implement the std::error::Error trait. So, you cannot record it as an Error trait object. I'm actually quite surprised that it doesn't implement std::error::Error, but again, I've never actually used that crate before. Perhaps the contributors to the crate have more insight.

I do notice that it has a number of fields that are publicly exposed, including a source field. So, perhaps you could modify the tracing event to manually include those fields.

[hawkw]

Sorry I gave you a totally wrong suggestion that you could record this error using std::error::Error, by the way --- I assumed that the trait would be implemented, as implementing it for library error types like this is a pretty common practice in the ecosystem, and it's generally the case that public error types will have an Error implementation. But again, I've never actually used the async-graphql crate. Sorry about that!