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

I'm using async-graphql and axum.

This is a reproduction of the issue: GitHub - 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()
}

SO question: rust - Is tracing intended to be used as I am using it? How can I trace errors chain? - Stack Overflow

It doesn't really have anything to do with your setup, async_graphql is calling info! and not error!

1 Like

Wow! I was loosing my mind! I'll create an issue for this! Thanks!

Can I tag you on github?

I created Use `tracinglib::error! instead of `tracinglib::info!` by frederikhors · Pull Request #1091 · async-graphql/async-graphql · GitHub.

1 Like

This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.