当 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)
// 通知读写协程
-
}
-
}
-
}
总之
同事的 httpclient 使用方法有些奇怪,除了 head method 之外,还真想不到有不读取 body 的请求。所以,大家知道 httpclient 有这么一回事就行了。
另外,一直觉得 net/http 的代码太绕,没看过一些介绍直接看代码很容易陷进去,有时间专门讲讲 http client 的实现。
转载:https://blog.csdn.net/qcrao/article/details/111570114