Go http client 连接池不复用的问题-巨人网络通讯

Go http client 连接池不复用的问题

当 http client 返回值为不为空，只读取 response header，但不读 body 内容就执行 response.Body.Close()，那么连接会被主动关闭，得不到复用。

测试代码如下：

// xiaorui.cc
 
func HttpGet() {
 for {
 fmt.Println("new")
 resp, err := http.Get("http://www.baidu.com")
 if err != nil {
  fmt.Println(err)
  continue
 }
 
 if resp.StatusCode == http.StatusOK {
  continue
 }
 
 resp.Body.Close()
  
 fmt.Println("go num", runtime.NumGoroutine())
 }
}

正如大家所想，除了 HEAD Method 外，很少会有只读取 header 的需求吧。

话说，golang httpclient 需要注意的地方着实不少。

如没有 response.Body.Close()，有些小场景造成 persistConn 的 writeLoop 泄露。
如 header 和 body 都不管，那么会造成泄露的连接干满连接池，后面的请求只能是短连接。

上下文

由于某几个业务系统会疯狂调用各区域不同的 k8s 集群，为减少跨机房带来的时延、兼容新老 k8s 集群 api、减少k8s api-server 的负载，故而开发了 k8scache 服务。在部署运行后开始对该服务进行监控，发现 metrics 呈现的 QPS 跟连接数不成正比，qps 为 1500，连接数为 10 个。开始以为触发 idle timeout 被回收，但通过历史监控图分析到连接依然很少。????

按照对 k8scache 调用方的理解，他们经常粗暴的开启不少协程来对 k8scache 进行访问。已知默认的 golang httpclient transport 对连接数是有默认限制的，连接池总大小为 100，每个 host 连接数为 2。当并发对某 url 进行请求时，无法归还连接池，也就是超过连接池大小的连接会被主动clsoe()。所以，我司的 golang 脚手架中会对默认的 httpclient 创建高配的 transport，不太可能出现连接池爆满被 close 的问题。

如果真的是连接池爆了? 谁主动挑起关闭，谁就有 tcp time-wait 状态，但通过 netstat 命令只发现少量跟 k8scache 相关的 time-wait。

排查问题

已知问题, 为隐藏敏感信息，索性使用简单的场景设立问题的 case

tcpdump抓包分析问题?

包信息如下，通过最后一行可以确认是由客户端主动触发 RST连接重置。触发RST的场景有很多，但常见的有 tw_bucket 满了、tcp 连接队列爆满且开启 tcp_abort_on_overflow、配置 so_linger、读缓冲区还有数据就给 close。

通过 linux 监控和内核日志可以确认不是内核配置的问题，配置 so_linger 更不可能。???? 大概率就一个可能，关闭未清空读缓冲区的连接。

22:11:01.790573 IP (tos 0x0, ttl 64, id 29826, offset 0, flags [DF], proto TCP (6), length 60)
  host-46.54550 > 110.242.68.3.http: Flags [S], cksum 0x5f62 (incorrect -> 0xb894), seq 1633933317, win 29200, options [mss 1460,sackOK,TS val 47230087 ecr 0,nop,wscale 7], length 0
22:11:01.801715 IP (tos 0x0, ttl 43, id 0, offset 0, flags [DF], proto TCP (6), length 52)
  110.242.68.3.http > host-46.54550: Flags [S.], cksum 0x00a0 (correct), seq 1871454056, ack 1633933318, win 29040, options [mss 1452,nop,nop,sackOK,nop,wscale 7], length 0
22:11:01.801757 IP (tos 0x0, ttl 64, id 29827, offset 0, flags [DF], proto TCP (6), length 40)
  host-46.54550 > 110.242.68.3.http: Flags [.], cksum 0x5f4e (incorrect -> 0xb1f5), seq 1, ack 1, win 229, length 0
22:11:01.801937 IP (tos 0x0, ttl 64, id 29828, offset 0, flags [DF], proto TCP (6), length 134)
  host-46.54550 > 110.242.68.3.http: Flags [P.], cksum 0x5fac (incorrect -> 0xb4d6), seq 1:95, ack 1, win 229, length 94: HTTP, length: 94
 GET / HTTP/1.1
 Host: www.baidu.com
 User-Agent: Go-http-client/1.1
 
22:11:01.814122 IP (tos 0x0, ttl 43, id 657, offset 0, flags [DF], proto TCP (6), length 40)
  110.242.68.3.http > host-46.54550: Flags [.], cksum 0xb199 (correct), seq 1, ack 95, win 227, length 0
22:11:01.815179 IP (tos 0x0, ttl 43, id 658, offset 0, flags [DF], proto TCP (6), length 4136)
  110.242.68.3.http > host-46.54550: Flags [P.], cksum 0x6f4e (incorrect -> 0x0e70), seq 1:4097, ack 95, win 227, length 4096: HTTP, length: 4096
 HTTP/1.1 200 OK
 Bdpagetype: 1
 Bdqid: 0x8b3b62c400142f77
 Cache-Control: private
 Connection: keep-alive
 Content-Encoding: gzip
 Content-Type: text/html;charset=utf-8
 Date: Wed, 09 Dec 2020 14:11:01 GMT
 ...
22:11:01.815214 IP (tos 0x0, ttl 64, id 29829, offset 0, flags [DF], proto TCP (6), length 40)
  host-46.54550 > 110.242.68.3.http: Flags [.], cksum 0x5f4e (incorrect -> 0xa157), seq 95, ack 4097, win 293, length 0
22:11:01.815222 IP (tos 0x0, ttl 43, id 661, offset 0, flags [DF], proto TCP (6), length 4136)
  110.242.68.3.http > host-46.54550: Flags [P.], cksum 0x6f4e (incorrect -> 0x07fa), seq 4097:8193, ack 95, win 227, length 4096: HTTP
22:11:01.815236 IP (tos 0x0, ttl 64, id 29830, offset 0, flags [DF], proto TCP (6), length 40)
  host-46.54550 > 110.242.68.3.http: Flags [.], cksum 0x5f4e (incorrect -> 0x9117), seq 95, ack 8193, win 357, length 0
22:11:01.815243 IP (tos 0x0, ttl 43, id 664, offset 0, flags [DF], proto TCP (6), length 5848)
  ...
  host-46.54550 > 110.242.68.3.http: Flags [.], cksum 0x5f4e (incorrect -> 0x51ba), seq 95, ack 24165, win 606, length 0
22:11:01.815369 IP (tos 0x0, ttl 64, id 29834, offset 0, flags [DF], proto TCP (6), length 40)
  host-46.54550 > 110.242.68.3.http: Flags [R.], cksum 0x5f4e (incorrect -> 0x51b6), seq 95, ack 24165, win 606, length 0

通过 lsof 找到进程关联的 TCP 连接，然后使用 ss 或 netstat 查看读写缓冲区。信息如下，recv-q 读缓冲区确实是存在数据。这个缓冲区字节一直未读，直到连接关闭引发了 rst。

$ lsof -p 54330
COMMAND  PID USER  FD   TYPE  DEVICE SIZE/OFF    NODE NAME
...
aaa   54330 root  1u   CHR   136,0   0t0     3 /dev/pts/0
aaa   54330 root  2u   CHR   136,0   0t0     3 /dev/pts/0
aaa   54330 root  3u a_inode   0,10    0    8838 [eventpoll]
aaa   54330 root  4r   FIFO    0,9   0t0 223586913 pipe
aaa   54330 root  5w   FIFO    0,9   0t0 223586913 pipe
aaa   54330 root  6u   IPv4 223596521   0t0    TCP host-46:60626->110.242.68.3:http (ESTABLISHED)
 
$ ss -an|egrep "68.3:80"
State   Recv-Q   Send-Q    Local Address:Port    Peer Address:Port 
ESTAB   72480    0      172.16.0.46:60626     110.242.68.3:80

strace 跟踪系统调用

通过系统调用可分析出，貌似只是读取了 header 部分了，还未读到 body 的数据。

[pid 8311] connect(6, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("110.242.68.3")}, 16 unfinished ...>
[pid 195519] epoll_pwait(3, unfinished ...>
[pid 8311] ... connect resumed>)   = -1 EINPROGRESS (操作现在正在进行)
[pid 8311] epoll_ctl(3, EPOLL_CTL_ADD, 6, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=2350546712, u64=140370471714584}} unfinished ...>
[pid 195519] getsockopt(6, SOL_SOCKET, SO_ERROR, unfinished ...>
[pid 192592] nanosleep({tv_sec=0, tv_nsec=20000}, unfinished ...>
[pid 195519] getpeername(6, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("110.242.68.3")}, [112->16]) = 0
[pid 195519] getsockname(6, unfinished ...>
[pid 195519] ... getsockname resumed>{sa_family=AF_INET, sin_port=htons(47746), sin_addr=inet_addr("172.16.0.46")}, [112->16]) = 0
[pid 195519] setsockopt(6, SOL_TCP, TCP_KEEPINTVL, [15], 4) = 0
[pid 195519] setsockopt(6, SOL_TCP, TCP_KEEPIDLE, [15], 4 unfinished ...>
[pid 8311] write(6, "GET / HTTP/1.1\r\nHost: www.baidu.com\r\nUser-Agent: Go-http-client/1.1\r\nAccept-Encoding: gzip\r\n\r\n", 94 unfinished ...>
[pid 192595] read(6, unfinished ...>
[pid 192595] ... read resumed>"HTTP/1.1 200 OK\r\nBdpagetype: 1\r\nBdqid: 0xc43c9f460008101b\r\nCache-Control: private\r\nConnection: keep-alive\r\nContent-Encoding: gzip\r\nContent-Type: text/html;charset=utf-8\r\nDate: Wed, 09 Dec 2020 13:46:30 GMT\r\nExpires: Wed, 09 Dec 2020 13:45:33 GMT\r\nP3p: CP=\" OTI DSP COR IVA OUR IND COM \"\r\nP3p: CP=\" OTI DSP COR IVA OUR IND COM \"\r\nServer: BWS/1.1\r\nSet-Cookie: BAIDUID=996EE645C83622DF7343923BF96EA1A1:FG=1; expires=Thu, 31-Dec-37 23:55:55 GMT; max-age=2147483647; path=/; domain=.baidu.com\r\nSet-Cookie: BIDUPSID=99"..., 4096) = 4096
[pid 192595] close(6 unfinished ...>

逻辑代码

那么到这里，可以大概猜测问题所在，找到业务方涉及到 httpclient 的逻辑代码。伪代码如下，跟上面的结论一样，只是读取了header，但并未读取完response body数据。

还以为是特殊的场景，结果是使用不当，把请求投递过去后只判断 http code？真正的业务 code 是在 body 里的。????

urls := []string{...}
for _, url := range urls {
 resp, err := http.Post(url, ...)
 if err != nil {
  // ...
 }
 if resp.StatusCode == http.StatusOK {
  continue
 }
 
 // handle redis cache
 // handle mongodb
 // handle rocketmq
 // ...
 
 resp.Body.Close()
}

如何解决

不细说了，把 header length 长度的数据读完就可以了。

分析问题

先不管别人使用不当，再分析下为何出现短连接，连接不能复用的问题。

为什么不读取 body 就出问题？其实 http.Response 字段描述中已经有说明了。当 Body 未读完时，连接可能不能复用。

 // The http Client and Transport guarantee that Body is always
 // non-nil, even on responses without a body or responses with
 // a zero-length body. It is the caller's responsibility to
 // close Body. The default HTTP client's Transport may not
 // reuse HTTP/1.x "keep-alive" TCP connections if the Body is
 // not read to completion and closed.
 //
 // The Body is automatically dechunked if the server replied
 // with a "chunked" Transfer-Encoding.
 //
 // As of Go 1.12, the Body will also implement io.Writer
 // on a successful "101 Switching Protocols" response,
 // as used by WebSockets and HTTP/2's "h2c" mode.
 Body io.ReadCloser

众所周知，golang httpclient 要注意 response Body 关闭问题，但上面的 case 确实有关了 body，只是非常规地没去读取 reponse body 数据。这样会造成连接异常关闭，继而引起连接池不能复用。

一般 http 协议解释器是要先解析 header，再解析 body，结合当前的问题开始是这么推测的，连接的 readLoop 收到一个新请求，然后尝试解析 header 后，返回给调用方等待读取 body，但调用方没去读取，而选择了直接关闭 body。那么后面当一个新请求被 transport roundTrip 再调度请求时，readLoop 的 header 读取和解析会失败，因为他的读缓冲区里有前面未读的数据，必然无法解析 header。按照常见的网络编程原则，协议解析失败，直接关闭连接。

想是这么想的，但还是看了 golang net/http 的代码，结果不是这样的。????

分析源码

httpclient 每个连接会创建读写协程两个协程，分别使用 reqch 和 writech 来跟 roundTrip 通信。上层使用的response.Body 其实是经过多次封装的，一次封装的 body 是直接跟 net.conn 进行交互读取，二次封装的 body 则是加强了 close 和 eof 处理的 bodyEOFSignal。

当未读取 body 就进行 close 时，会触发 earlyCloseFn() 回调，看 earlyCloseFn 的函数定义，在 close 未见 io.EOF 时才调用。自定义的 earlyCloseFn 方法会给 readLoop 监听的 waitForBodyRead 传入 false, 这样引发 alive 为 false 不能继续循环的接收新请求，只能是退出调用注册过的 defer 方法，关闭连接和清理连接池。

// xiaorui.cc
 
func (pc *persistConn) readLoop() {
 closeErr := errReadLoopExiting // default value, if not changed below
 defer func() {
 pc.close(closeErr)   // 关闭连接
 pc.t.removeIdleConn(pc) // 从连接池中删除
 }()
 
 ...
 
 alive := true
 for alive {
   ...
 
 rc := -pc.reqch // 从管道中拿到请求，roundTrip 对该管道进行输入
 trace := httptrace.ContextClientTrace(rc.req.Context())
 
 var resp *Response
 if err == nil {
  resp, err = pc.readResponse(rc, trace) // 更多的是解析 header
 } else {
  err = transportReadFromServerError{err}
  closeErr = err
 }
  ...
 
 waitForBodyRead := make(chan bool, 2)
 body := bodyEOFSignal{
  body: resp.Body,
  // 提前关闭 !!! 输出false
  earlyCloseFn: func() error {
  waitForBodyRead - false
  ...
  },
  // 正常收尾 !!!
  fn: func(err error) error {
  isEOF := err == io.EOF
  waitForBodyRead - isEOF
  ...
  },
 }
 
 resp.Body = body
 
 select {
 case rc.ch - responseAndError{res: resp}:
 case -rc.callerGone:
  return
 }
 
 select {
 case bodyEOF := -waitForBodyRead:
  replaced := pc.t.replaceReqCanceler(rc.cancelKey, nil) // before pc might return to idle pool
  // alive 为 false, 不能继续 continue
  alive = alive 
  bodyEOF 
  !pc.sawEOF 
  pc.wroteRequest() 
  replaced  tryPutIdleConn(trace)
  ...
 case -rc.req.Cancel:
  alive = false
  pc.t.CancelRequest(rc.req)
 case -rc.req.Context().Done():
  alive = false
  pc.t.cancelRequest(rc.cancelKey, rc.req.Context().Err())
 case -pc.closech:
  alive = false
 }
 }
}

bodyEOFSignal 的 Close()：

// xiaorui.cc
 
func (es *bodyEOFSignal) Close() error {
 es.mu.Lock()
 defer es.mu.Unlock()
 if es.closed {
 return nil
 }
 es.closed = true
 if es.earlyCloseFn != nil  es.rerr != io.EOF {
 return es.earlyCloseFn()
 }
 err := es.body.Close()
 return es.condfn(err)
}

最终会调用 persistConn 的 close(), 连接关闭并关闭closech：

// xiaorui.cc
 
func (pc *persistConn) close(err error) {
 pc.mu.Lock()
 defer pc.mu.Unlock()
 pc.closeLocked(err)
}
 
func (pc *persistConn) closeLocked(err error) {
 if err == nil {
 panic("nil error")
 }
 pc.broken = true
 if pc.closed == nil {
 pc.closed = err
 pc.t.decConnsPerHost(pc.cacheKey)
 if pc.alt == nil {
  if err != errCallerOwnsConn {
  pc.conn.Close() // 关闭连接
  }
  close(pc.closech) // 通知读写协程
 }
 }
}