async-graphql与axum错误追踪疑问：日志级别与内部错误丢失

问题背景 #

我正在使用async-graphql和axum，问题复现步骤：

• 执行cargo run启动服务
• 打开http://localhost:8000的GraphiQL客户端，执行以下mutation查询：

mutation {
  mutateWithError
}

后端返回响应符合预期，但日志追踪存在疑问，日志内容如下：

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

疑问点 #

针对日志中INFO async_graphql::graphql:146: error, error: I cannot mutate now, sorry!这一行，有两个核心问题：

1. 为何该错误是INFO级别而非ERROR级别？
2. 内部错误信息“this is a DB error”为何未显示？

同时咨询：

• 当前的追踪用法是否符合预期？
• 如何追踪完整的错误链？

相关代码 #

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

问题解答 #

1. 错误为INFO级别的原因 #

async-graphql 默认将业务错误（即通过async_graphql::Result返回的错误）归类为INFO级别日志，因为这类错误属于预期内的业务异常，而非程序崩溃级别的系统错误。框架认为这类错误是GraphQL请求处理流程中的正常分支，因此用INFO级别记录。

如果需要将这类错误改为ERROR级别，可以通过自定义Logger扩展实现，在处理错误时手动输出ERROR级别日志。

2. 内部错误信息未显示的原因 #

当anyhow::Error转换为async_graphql::Error时，默认仅提取最外层的context信息（即你添加的"I cannot mutate now, sorry!"），不会自动展开错误链。这是框架的默认设计，目的是避免将内部实现细节暴露给外部请求。

3. 当前追踪用法是否符合预期 #

从日志来看，当前的追踪流程符合async-graphql的默认行为：框架自动记录了请求的parse、validation、execute等各个阶段的耗时和状态，这是框架内置的追踪能力，属于正常用法。

4. 如何追踪完整错误链 #

要完整追踪错误链，需要手动处理anyhow::Error的展开，常见方式有两种：

方式一：自定义错误转换

在将anyhow::Result转换为async_graphql::Result时，手动拼接错误链的所有信息：

use anyhow::Context;

async fn mutate_with_error() -> async_graphql::Result<String> {
    can_i_mutate_on_db()
        .await
        .context("I cannot mutate now, sorry!")
        .map_err(|e| {
            let full_error = e.chain()
                .map(|s| s.to_string())
                .collect::<Vec<_>>()
                .join(": ");
            async_graphql::Error::new(full_error)
        })
}

修改后日志会显示完整错误链：I cannot mutate now, sorry!: this is a DB error!

方式二：利用错误扩展附加链信息

通过ErrorExtensions trait将错误链附加到扩展字段，既可以在日志中记录，也可以按需返回给客户端（注意不要泄露敏感信息）：

use async_graphql::ErrorExtensions;

async fn mutate_with_error() -> async_graphql::Result<String> {
    can_i_mutate_on_db()
        .await
        .context("I cannot mutate now, sorry!")
        .map_err(|e| {
            let full_error = e.chain()
                .map(|s| s.to_string())
                .collect::<Vec<_>>()
                .join(": ");
            async_graphql::Error::new(full_error)
                .extend_with(|_, ext| ext.set("error_chain", full_error))
        })
}

另外，也可以自定义Logger扩展，在日志回调中自动展开错误链并输出。

内容的提问来源于stack exchange，提问作者Fred Hors