Go 服务出现偶发请求超时，如何用 context 链路定位未结束的下游调用

订单详情接口平时几十毫秒就能返回，偶尔却拖到网关超时。日志里只看到“request timeout”，看不出是库存查询、会员查询，还是最后的 JSON 编码卡住了。排查这类问题时，先别急着把全局超时时间调大：把同一个 context.Context 沿调用链传下去，再记录每一跳开始、结束和取消状态，通常能很快找到没有及时收尾的下游调用。

可复用的判断标准是：入口只负责设定请求边界，下游函数只接收并继续传递 context；当 ctx.Done() 先于下游返回时，日志必须明确指出哪一跳被取消。

先看超时发生在哪一跳

假设接口由 Handler 调用 QueryOrder，再由它依次读取库存和会员信息。最有价值的第一步不是打印一整段请求对象，而是给每一跳统一带上订单号和请求截止时间。下面的最小代码把超时边界放在入口，调用链上的每个函数都复用同一个 ctx。

func Handler(w http.ResponseWriter, r *http.Request) {
    ctx, cancel := context.WithTimeout(r.Context(), 800*time.Millisecond)
    defer cancel()

    order, err := QueryOrder(ctx, r.PathValue("id"))
    if err != nil {
        http.Error(w, err.Error(), http.StatusGatewayTimeout)
        return
    }
    writeJSON(w, order)
}

func QueryOrder(ctx context.Context, id string) (Order, error) {
    stock, err := loadStock(ctx, id)
    if err != nil {
        return Order{}, fmt.Errorf("load stock: %w", err)
    }
    member, err := loadMember(ctx, id)
    if err != nil {
        return Order{}, fmt.Errorf("load member: %w", err)
    }
    return Order{ID: id, Stock: stock, Member: member}, nil
}

这段代码有一个可核对的链路：Handler 设置 800 毫秒边界，QueryOrder 接收并传递 ctx，然后进入 loadStock 和 loadMember。如果只有入口日志，超时只能定位到接口；如果在两个下游调用前后打点，就能知道具体停在哪个节点。

把日志变成可以判断的信号

建议给下游调用包一层很薄的计时函数。完成日志和取消日志不要混成一条，否则慢调用在返回后会被误判成普通错误。

func loadStock(ctx context.Context, id string) (Stock, error) {
    started := time.Now()
    log.Printf("loadStock start order_id=%s", id)

    value, err := stockClient.Get(ctx, id)
    elapsed := time.Since(started)
    if err != nil {
        if errors.Is(ctx.Err(), context.DeadlineExceeded) {
            log.Printf("loadStock canceled order_id=%s elapsed=%s cause=deadline", id, elapsed)
        } else {
            log.Printf("loadStock failed order_id=%s elapsed=%s err=%v", id, elapsed, err)
        }
        return Stock{}, err
    }
    log.Printf("loadStock done order_id=%s elapsed=%s", id, elapsed)
    return value, nil
}

重点看三件事：loadStock start 是否出现、loadStock done 是否缺失、cause=deadline 是否紧跟请求超时。若 start 有而 done 没有，且 cause 是 deadline，说明取消信号已经到达这一跳；若下游仍无返回，问题就在客户端实现或它调用的驱动没有响应取消。

让取消信号真正抵达下游

仅仅把 ctx 作为参数传递还不够，实际 I/O 必须调用带 context 的接口。以 HTTP 客户端为例，使用 http.NewRequestWithContext 后，请求在上下文结束时才有机会被取消；如果改成 http.NewRequest，外层虽然知道超时，底层请求却可能继续占用连接。

func fetchMember(ctx context.Context, id string) (Member, error) {
    req, err := http.NewRequestWithContext(ctx, http.MethodGet,
        memberURL+"/members/"+url.PathEscape(id), nil)
    if err != nil {
        return Member{}, err
    }
    resp, err := http.DefaultClient.Do(req)
    if err != nil {
        return Member{}, err
    }
    defer resp.Body.Close()
    if resp.StatusCode != http.StatusOK {
        return Member{}, fmt.Errorf("member status: %s", resp.Status)
    }
    var member Member
    return member, json.NewDecoder(resp.Body).Decode(&member)
}

这里的关系很具体：fetchMember 把入口的 ctx 交给 NewRequestWithContext，再由 http.DefaultClient.Do 执行。不要在函数内部用 context.Background() 替换它，也不要把取消错误一律改成“服务器异常”，否则告警会失去区分度。

处理步骤：先确认，再改动

1. 确认入口边界。 在 Handler 记录请求开始时间和 deadline，检查是否所有请求都使用同一类超时策略。不要先改网关配置。
2. 确认调用链。 沿 QueryOrder、loadStock、loadMember 的 start/done 日志对齐同一个 order_id，找出缺少 done 的节点。
3. 确认 I/O 接口。 HTTP 使用 NewRequestWithContext，数据库使用带 context 的查询方法；对每个返回值检查 ctx.Err()。
4. 确认退出。 用一个延迟 2 秒的测试下游调用，入口设置 100 毫秒超时，检查取消日志是否出现，以及请求处理 goroutine 是否回收。

修复不理想时如何回滚

如果改动涉及公共客户端，先保留旧实现的配置开关，只把一个接口接入带 context 的路径。出现错误率上升时，关闭开关即可回到旧调用；但回滚只解决发布风险，不解决连接泄漏，所以仍要保留 start/done/canceled 三类日志，方便继续取证。

不要通过无条件延长 800 毫秒来“修复”问题。它可能让网关更晚失败，却把连接、goroutine 和下游并发一起推高。只有当日志证明业务确实允许更长处理时间，才应调整边界，并同步修改压测和告警阈值。

告警确认与复盘项

修复上线后至少观察请求超时率、下游取消率、HTTP 客户端连接数和 goroutine 数量。一次成功请求不代表链路已经健康：需要让慢下游连续触发超时，确认取消路径仍然有效；再恢复正常下游，确认后续请求能完成且连接池回到稳定区间。

相关问题

为什么调用方超时了，下游日志还在继续打印？

通常是下游没有使用带 context 的 I/O 方法，或中间函数用新的背景上下文覆盖了原来的 ctx。先从入口沿参数传递检查，再看真正发起网络或数据库操作的那一行。

应该在每个函数里创建新的超时吗？

一般不应该。入口设定总边界，必要时才为明确的子操作建立更短的子 context，并确保它仍然继承父 context；层层创建独立超时会让剩余时间难以判断。

小结

偶发超时的关键不是一味增加等待时间，而是让超时边界、调用链和取消信号保持同一条路径。入口用 WithTimeout，中间函数原样传递 ctx，真正的 I/O 使用带 context 的接口，再用 start/done/canceled 日志验证，问题才能从“偶发”变成可复现、可回滚的工程信号。