深度分析 [go的HttpClient读取Body超时]

故障现场

本人负责的主备集群,发出的 HttpClient 请求有 30%概率超时， 报context deadline exceeded (Client.Timeout or context cancellation while reading body)
异常

Kibana 显示 Nginx 处理请求的耗时request_time在[5s-1min]区间波动， upstream_response_time在 2s 级别。

所以我们认定是 Nginx 向客户端回传 50M 的数据，发生了网络延迟。
于是将 HttpClient Timeout 从 30s 调整到 60s， 上线之后明显改善。

But 昨天又出现了一次同样的超时异常

time="2022-01-05T22:28:59+08:00" ....
time="2022-01-05T22:30:02+08:00" level=error msg="service Run error" error="region: sz,first load self allIns error:context deadline exceeded (Client.Timeout or context cancellation while reading body)"

线下复盘

Kibana 显示 Nginx 处理请求的耗时request_time才 32s, 远不到我们对于 Http 客户端设置的 60s 超时阈值。

从目前的信息看，Nginx 从接受请求到发送完响应流，总共耗时 32s。
那剩下的 28s，是在哪里消耗的。

三省吾身

这是我抽离的 HttpClient 的实践， 常规的不能再常规。

package main

import (
	"bytes"
	"encoding/json"
	"io/ioutil"
	"log"
	"net/http"
	"time"
)

func main() {
	  c := &http.Client{Timeout: 10 * time.Second}
	  body := sendRequest(c, http.MethodPost)
  	log.Println("response body length:", len(body))
}

func sendRequest(client *http.Client, method string) []byte {
	  endpoint := "http://mdb.qa.17usoft.com/table/instance?method=batch_query"
	  expr := "idc in (logicidc_hd1,logicidc_hd2,officeidc_hd1)"
	  jsonData, err := json.Marshal([]string{expr})
	  response, err := client.Post(endpoint, "application/json", bytes.NewBuffer(jsonData))
	  if err != nil {
		  log.Fatalf("Error sending request to api endpoint, %+v", err)
	  }
	  defer response.Body.Close()
	  body, err := ioutil.ReadAll(response.Body)
	  if err != nil {
		  log.Fatalf("Couldn't parse response body, %+v", err)
	  }
	  return body
}

核心就两个动作

• 调用Get、Post、Do方法发起 Http 请求， 如果无报错，则表示服务端已经处理了请求
• iotil.ReadAll表示客户端准备从网卡读取 Response Body (流式数据), 超时异常正是从这里爆出来的

HttpClient Timeout包括连接、重定向(如果有)、从Response Body读取的时间，内置定时器会在Get，Head、Post、Do 方法之后继续运行，直到读取完Response.Body.

报错内容："Client.Timeout or context cancellation while reading body" 读取 Response Body 超时，

潜台词是：服务器已经处理了请求，并且开始向客户端网卡写入数据。

根据我有限的网络原理/计算机原理，与此同时，客户端会异步从网卡读取 Response Body。

写入和读取互不干扰，但是时空有重叠。

所以[读取 Body 超时]位于图中的红框区域，这就有点意思了。

• 之前我们有 30%概率[读取 Body 超时]，确实是因为 Nginx 回传 50M 数据超时，这在 Nginx request_time 上能体现。

• 本次 Nginx 显示 request_time=32s, 却再次超时，推断 Nginx 已经写完数据，而客户端还没有读取完 Body。

---

为了模拟这个偶发的情况，我们可在Post、iotil.ReadAll前后加入时间日志。

$ go run main.go
2022/01/07 20:21:46 开始请求: 2022-01-07 20:21:46.010
2022/01/07 20:21:47 服务端处理结束: 2022-01-07 20:21:47.010
2022/01/07 20:21:52 客户端读取结束: 2022-01-07 20:21:52.010
2022/01/07 20:21:52 response body length: 50575756

可以看出，当读取大的响应体时候，客户端iotil.ReadAll的耗时并不算小，这块需要开发人员重视。

我们甚至可以iotil.ReadAll之前time.Sleep(xxx)， 就能轻松模拟出生产环境的读取 Body 超时。

我的收获

1. Nginx Access Log 的时间含义
2. go 的 HttpClient Timeout 包含了连接、请求、读取 Body 的耗时
3. 通过对[读取 Body 超时异常]的分析，我梳理了端到端的请求耗时、客户端的行为耗时的时空关系， 这个至关重要。