http请求超时的问题排查

问题描述

背景：生产环境中，服务间内网http调用，偶现超时。由于内网调用，网络开销理论较小，ToC服务偏重业务，请求响应延时有一定要求，所以服务间http请求超时时间设置为1秒钟，但是通过监控和告警发现，服务运行过程中，会偶尔出现请求超时的现象，需要将问题定位。

// 初始化http client
httpClient := &http.Client{
    Timeout: time.Duration(1) * time.Second,
}

// 网络调用
_, _ = httpClient.Do(request)

排查步骤

1. 首先请求超时，第一反应一定是下游处理慢了，于是根据traceId查看下游服务日志，发现服务根本没有收到。
2. 这就有了疑问，为啥没有收到请求呢。因为内网调用走的是域名（nginx），所以就申请了权限，看了下nginx日志，这时才发现，nginx是不记录http header了，所以为了排查问题，只好将traceId放在了query里，这样nginx就会在打印uri的时候，打印出请求的traceId了。这是很关键的一步，有助于我们将全链路打通。
3. 改动之后部署到qa环境，继续期待这个偶现问题的出现，果真出现了，我们发现nginx也没有收到这条请求，那只有两个可能，报文在网络传输的过程中被丢弃了，内网环境，带宽充足，这种概率实在太小。那还有另一个可能，那就是服务与nginx的链接没有建立成功，以至于无法传输报文。
4. 由于go http client设置超时后，会将错误统一封装成“context deadline exceeded (Client.Timeout exceeded while awaiting headers”，无法排查问题。于是，在初始化的时候，设置tcp链接的建立时间，使其略小于设置的超时时间，果然一段时间后，收到了如下告警“lookup xxx i/o timeout”，其大概率是dns解析过慢，无法获取ip port，所以无法建立tcp链接。至此，出现请求超时的问题，终于被我们找到了。

// 初始化http client & 增加tcp建立连接超时配置
httpClient := &http.Client{
    Transport: &http.Transport{
        DialContext: (&net.Dialer{
            Timeout: 900 * time.Millisecond, // 连接超时
        }).DialContext,
        DialTLSContext: (&net.Dialer{
            Timeout: 900 * time.Millisecond, // 连接超时
        }).DialContext,
        DisableKeepAlives:   true,
        ForceAttemptHTTP2:   true,
        TLSHandshakeTimeout: 900 * time.Millisecond,
    },
    Timeout: time.Duration(2) * time.Second,
}

解决建议

1. 配置本地dns
2. 可以上k8s，服务发现使用ip port，就没有dns这一步，而且k8s对微服务的运维部署都很友好，是一个互联网的趋势

总结

问题看似简单，其实整体耗费了不少时间，生产环境出现问题，还是要认真对待，既是对公司的业务负责，也是对自己的服务负责。仅此记录，与各位开发者共勉！