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

394 views Asked by At

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()
}
0

There are 0 answers