共计 9939 个字符,预计需要花费 25 分钟才能阅读完成。
问题引入
生产环境 Golang 服务有时会产生 502 报警,排查发现大多是以下三种起因造成的:
- http.Server 配置了 WriteTimeout,申请解决超时,Golang 断开连接;
- http.Server 配置了 IdleTimeout,且网关和 Golang 之间应用长连贯,Golang 断开连接;
- Golang 服务呈现了 panic 造成服务重启。
第三种 case 非常简单,本文将重点剖析前两种 case 背地的深层起因。
注:申请链路为 客户端 ===> Nginx ===> Golang
WriteTimeout
Golang sdk 的正文阐明为 “WriteTimeout is the maximum duration before timing out writes of the response”。http.Server 在读取客户端申请实现时,设置了写超时工夫:
func (c *conn) readRequest(ctx context.Context) (w *response, err error) {
if d := c.server.WriteTimeout; d != 0 {defer func() {c.rwc.SetWriteDeadline(time.Now().Add(d))
}()}
}
显然,当申请解决工夫超过 WriteTimeout,会产生超时景象。为什么超时后会呈现 502 呢?
一个小小的试验
咱们先模仿以下申请解决超时的景象:
package main
import (
"net/http"
"time"
)
type GinHandler struct {
}
func (* GinHandler) ServeHTTP(w http.ResponseWriter, r *http.Request){time.Sleep(time.Duration(5) * time.Second)
w.Write([]byte("hello golang"))
}
func main() {
server := &http.Server{
Addr:"0.0.0.0:8080",
Handler: &GinHandler{},
ReadTimeout: time.Second * 3,
WriteTimeout: time.Second *3,
}
server.ListenAndServe()}
申请后果如下:
time curl http://127.0.0.1/test -H "Host:test.xueersi.com"
502 Bad Gateway
real 0m5.011s
查看 Nginx 的谬误日志,能够看到是上游被动敞开连贯造成的:
2020/08/12 21:18:07 [error] 30217#0: *8105 upstream prematurely closed connection while reading response header from upstream, client: 127.0.0.1, server: test.xueersi.com, request: "GET /test HTTP/1.1", upstream: "http://127.0.0.1:8080/test", host: "test.xueersi.com"
看到这里有个纳闷。curl 命令执行工夫为 5 秒,阐明是 5 秒后 Golang 服务才断开连接的,咱们不是设置了 WriteTimeout= 3 秒吗?为什么 3 秒超时一直开,而是 5 秒后才断开?
WriteTimeout 到底做了什么
咱们从这一行程序去切入寻找答案,c.rwc.SetWriteDeadline。这里的 rwc 类型为 net.Conn,是一个接口。真正的对象是由 l.Accept() 返回的,而 l 是对象 TCPListener。往下追踪能够发现创立的是 net.TCPConn 对象,而该对象继承了 net.conn,net.conn 又实现了 net.Conn 接口(留神大小写)。
type TCPConn struct {conn}
type conn struct {fd *netFD}
func (c *conn) SetReadDeadline(t time.Time) error {if err := c.fd.SetReadDeadline(t); err != nil {}}
再持续往下跟踪,调用链是这样的:
net.(c *conn).SetWriteDeadline()
net.(fd *netFD).SetWriteDeadline()
poll.(fd *FD).SetWriteDeadline()
poll.setDeadlineImpl()
poll.runtime_pollSetDeadline()
追到这,你会发现追不上来了,runtime_pollSetDeadline 的实现逻辑是什么呢?咱们全局搜素 pollSetDeadline,能够找到在 runtime/netpoll.go 文件。
//go:linkname poll_runtime_pollSetDeadline internal/poll.runtime_pollSetDeadline
func poll_runtime_pollSetDeadline(pd *pollDesc, d int64, mode int) {}
pollDesc 用于封装一个网络描述符,次要有这几个字段须要关注:
type pollDesc struct {
fd uintptr
rg uintptr // pdReady, pdWait, G waiting for read or nil
rt timer // read deadline timer (set if rt.f != nil)
rd int64 // read deadline
wg uintptr // pdReady, pdWait, G waiting for write or nil
wt timer // write deadline timer
wd int64 // write deadline
}
rt 是以后描述符上的读定时器,rt 为以后描述符已设置读定时器的超时工夫。rg 可取三个值:1)pdReady,示意该描述符处于可读状态;2)pdWait,示意有一个协程因为该描述符阻塞筹备换出;3)G,指针,指向阻塞的协程对象。
函数 poll_runtime_pollSetDeadline 次要依据读 / 写超时工夫增加定时器,同时设置回调回调函数:
// 写超时回调函数
pd.wt.f = netpollWriteDeadline
// 定时器到期后,调用回调函数的传入参数
pd.wt.arg = pd
咱们的问题行将上不着天; 下不着地,只须要剖析回调函数 netpollWriteDeadline(对立由 netpolldeadlineimpl 实现)做了什么,即可明确 WriteTimeout 到底是什么。
func netpolldeadlineimpl(pd *pollDesc, seq uintptr, read, write bool) {
if write {
pd.wd = -1
atomic.StorepNoWB(unsafe.Pointer(&pd.wt.f), nil)
wg = netpollunblock(pd, 'w', false)
}
if wg != nil {netpollgoready(wg, 0)
}
}
能够看到,设置 pd.wd=-1,后续以此判断该描述符上的写定时器是否曾经过期。netpollunblock 与 netpollgoready,用于判断是否有协程因为以后描述符阻塞,如果有将其状态置为可运行,并退出可运行队列;否则什么都不做。
这下所有都明确了,WriteTimeout 只是增加了读写超时定时器,待定时器过期时,也仅仅是设置该描述符读写超时。所以哪怕申请解决工夫是 5 秒远超过 WriteTimeout 设置的超时工夫,该申请仍然不会被中断,会失常执行直到完结,在向客户端返回后果时才会产生异样。
最初咱们通过 dlv 调试,打印一下设置 WriteTimeout 的函数调用链。
0 0x0000000001034c23 in internal/poll.runtime_pollSetDeadline
at /usr/local/go/src/runtime/netpoll.go:224
1 0x00000000010ee3a0 in internal/poll.setDeadlineImpl
at /usr/local/go/src/internal/poll/fd_poll_runtime.go:155
2 0x00000000010ee14a in internal/poll.(*FD).SetReadDeadline
at /usr/local/go/src/internal/poll/fd_poll_runtime.go:132
3 0x00000000011cc868 in net.(*netFD).SetReadDeadline
at /usr/local/go/src/net/fd_unix.go:276
4 0x00000000011dffca in net.(*conn).SetReadDeadline
at /usr/local/go/src/net/net.go:251
5 0x000000000131491f in net/http.(*conn).readRequest
at /usr/local/go/src/net/http/server.go:953
6 0x000000000131bd5a in net/http.(*conn).serve
at /usr/local/go/src/net/http/server.go:1822
小小的思考:底层描述符上的读写超时事件触发后,为什么不间接敞开该描述符,只是标识一下呢?
502 就是这么来的
这次咱们简略一点,不必一点一点去追踪了。方才设置超时工夫会调用 poll.(fd FD).SetWriteDeadline,FD 即进一步封装了底层 的描述符 pollDesc,其必然提供读写处理函数。咱们在 poll.(fd FD).Write 打断点:
(dlv) b poll.Write
Breakpoint 1 set at 0x10ef40b for internal/poll.(*FD).Write() /usr/local/go/src/internal/poll/fd_unix.go:254
(dlv) bt
0 0x00000000010ef40b in internal/poll.(*FD).Write
at /usr/local/go/src/internal/poll/fd_unix.go:254
1 0x00000000011cc0ac in net.(*netFD).Write
at /usr/local/go/src/net/fd_unix.go:220
2 0x00000000011df765 in net.(*conn).Write
at /usr/local/go/src/net/net.go:196
3 0x000000000132276c in net/http.checkConnErrorWriter.Write
at /usr/local/go/src/net/http/server.go:3434
4 0x0000000001177e91 in bufio.(*Writer).Flush
at /usr/local/go/src/bufio/bufio.go:591
5 0x000000000131a329 in net/http.(*response).finishRequest
at /usr/local/go/src/net/http/server.go:1594
6 0x000000000131c7c5 in net/http.(*conn).serve
at /usr/local/go/src/net/http/server.go:1900
正如上一节所说,待申请解决实现后,哪怕超时了,下层业务仍然会尝试写响应后果,最终判断发现 pollDesc 超时,返回谬误,下层业务从而敞开连贯。
poll.(fd *FD).Write
poll.(pd *pollDesc).prepareWrite
poll.(pd *pollDesc).prepare
poll.runtime_pollReset
函数 runtime_pollReset 的实现逻辑同样是在 runtime/netpoll.go 文件。通过 netpollcheckerr 实现校验逻辑:
//go:linkname poll_runtime_pollReset internal/poll.runtime_pollReset
func poll_runtime_pollReset(pd *pollDesc, mode int) int {
}
func netpollcheckerr(pd *pollDesc, mode int32) int {
if pd.closing {return 1 // ErrFileClosing or ErrNetClosing}
if (mode == 'r' && pd.rd < 0) || (mode == 'w' && pd.wd < 0) {return 2 // ErrTimeout}
……
return 0
}
底层写数据返回谬误,下层 http.(c *conn).serve 办法间接返回,返回前执行 defer 做收尾工作,比方敞开连贯。
超时怎么管制?
参照下面的剖析,通过 WriteTimeout 管制申请的超时工夫,存在两个问题:1)申请解决超时后 Golang 会断开连接,Nginx 会呈现 502;2)申请不会因为 WriteTimeout 超时而被中断,须要等到申请真正解决实现,客户端期待响应工夫较长;在遇到大量慢申请时,Golang 服务资源占用会急剧减少。
那么如何优雅的管制超时状况呢?超时后 Golang 间接完结以后申请,并向客户端返回默认后果。能够利用 context.Context 实现,这是一个接口,有多种实现,如 cancelCtx 可勾销的上下文,timerCtx 可定时勾销的上下文,valueCtx 可基于上下文传递变量。
context.Context 定义如下:
type Context interface {Deadline() (deadline time.Time, ok bool)
Done() <-chan struct{}
Err() error
Value(key interface{}) interface{}}
- Deadline:返回绑定以后 context 的工作被勾销的截止工夫;如果没有设置,则返回 ok=false;
- Done:当绑定以后 context 的工作被勾销时,将返回一个敞开的 channel;否则返回 nil;
- Err:当 Done 返回的 channel 被敞开时,返回非空的值示意工作完结的起因;
- Value 返回 context 存储的键值对中以后 key 对应的值,如果没有对应的 key, 则返回 nil。
上面举一个小小的例子:
ctx := context.Background()
ctx, cancel := context.WithCancel(ctx)
go Proc()
time.Sleep(time.Second)
cancel()
func Proc(ctx context.Context) {
for {
select {case <- ctx.Done():
return
default:
//do something
}
}
}
更多 context.Context 的介绍参考这两篇文章:
- 深刻了解 Golang 之 context:https://zhuanlan.zhihu.com/p/…
- 今日头条 Go 建千亿级微服务的实际:https://36kr.com/p/1721518997505
小小的扩大
WriteTimeout 导致的 502 咱们曾经剖析分明了,最初咱们再扩大一下协程因为读写阻塞导致的切换流程。
for {n, err := syscall.Read(fd.Sysfd, p)
if err != nil {
n = 0
if err == syscall.EAGAIN && fd.pd.pollable() {if err = fd.pd.waitRead(fd.isFile);
}
……
}
}
poll.(fd *FD).Read
poll.(pd *pollDesc).waitRead
poll.(pd *pollDesc).wait
poll.runtime_pollWait
函数 runtime_pollWait 的实现逻辑同样是在 runtime/netpoll.go 文件。通过 netpollblock 实现协程阻塞逻辑
//go:linkname poll_runtime_pollWait internal/poll.runtime_pollWait
func poll_runtime_pollWait(pd *pollDesc, mode int) int {
}
func netpollblock(pd *pollDesc, mode int32, waitio bool) bool {
……
if waitio || netpollcheckerr(pd, mode) == 0 {gopark(netpollblockcommit, unsafe.Pointer(gpp), waitReasonIOWait, traceEvGoBlockNet, 5)
}
}
IdleTimeout + 长连贯
Golang sdk 的正文阐明如下:
”IdleTimeout is the maximum amount of time to wait for the next request when keep-alives are enabled. If IdleTimeout is zero, the value of ReadTimeout is used. If both are zero, there is no timeout”。
能够看到只有当网关 Nginx 和上游 Golang 服务之间采纳 keep-alived 长连贯时,该配置才失效。须要特地留神的是,如果 IdleTimeout 等于 0,则默认取 ReadTimeout 的值。
留神:Nginx 在通过 proxy_pass 配置转发时,默认采纳 HTTP 1.0,且 ”Connection:close”。因而须要增加如下配置能力应用长连贯:
proxy_http_version 1.1;
proxy_set_header Connection "";
一个小小的试验
该场景下的 502 存在概率问题,只有当上游 Golang 服务敞开连贯,与新的申请达到,简直同时产生时,才有可能呈现。因而最终只是通过 tcpdump 抓包察看 Golang 服务端敞开连贯。
留神:这种场景有一个显著的特色,upstream_response_time 靠近于 0。
记得配置网关 Nginx 到 Golang 服务之间采纳长连贯,同时配置 IdleTimeout= 5 秒。只申请一次,tcpdump 抓包察看景象如下:
15:15:03.155362 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [S], seq 3293818352, win 43690, length 0
01:50:36.801131 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [S.], seq 901857004, ack 3293818353, win 43690, length 0
15:15:03.155385 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [.], ack 1, win 86, length 0
15:15:03.155406 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [P.], seq 1:135, ack 1, win 86, length 134: HTTP: GET /test HTTP/1.1
15:15:03.155411 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [.], ack 135, win 88, length 0
15:15:03.155886 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [P.], seq 1:130, ack 135, win 88, length 129: HTTP: HTTP/1.1 200 OK
15:15:03.155894 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [.], ack 130, win 88, length 0
//IdleTimeout 5 秒超时后,Golang 服务被动断开连接
15:15:08.156130 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [F.], seq 130, ack 135, win 88, length 0
15:15:08.156234 IP 127.0.0.1.20775 > 127.0.0.1.8080: Flags [F.], seq 135, ack 131, win 88, length 0
15:15:08.156249 IP 127.0.0.1.8080 > 127.0.0.1.20775: Flags [.], ack 136, win 88, length 0
Golang 服务被动断开连接,网关 Nginx 就有产生 502 的可能。怎么解决这个问题呢?只有保障每次都是网关 Nginx 被动断开连接即可。
ngx_http_upstream_module 模块在新版本增加了一个配置参数,keepalive_timeout。留神这不是 ngx_http_core_module 模块里的,两个参数名称一样,然而用处不一样。
Syntax: keepalive_timeout timeout;
Default:
keepalive_timeout 60s;
Context: upstream
This directive appeared in version 1.15.3.
Sets a timeout during which an idle keepalive connection to an upstream server will stay open.
显然只有 Golang 服务配置的 IdleTimeout 大于这里的 keepalive_timeout 即可。
源码剖析
整个处理过程在 http.(c *conn).serve 办法,逻辑如下:
func (c *conn) serve(ctx context.Context) {defer func() {
// 函数返回前敞开连贯
c.close()}()
// 循环解决
for {
// 读申请
w, err := c.readRequest(ctx)
// 解决申请
serverHandler{c.server}.ServeHTTP(w, w.req)
// 响应
w.finishRequest()
// 没有开启 keepalive,则敞开连贯
if !w.conn.server.doKeepAlives() {return}
if d := c.server.idleTimeout(); d != 0 {
// 设置读超时工夫为 idleTimeout
c.rwc.SetReadDeadline(time.Now().Add(d))
// 阻塞读,待 idleTimeout 超时后,返回谬误
if _, err := c.bufr.Peek(4); err != nil {return}
}
// 接管到新的申请,清空 ReadTimeout
c.rwc.SetReadDeadline(time.Time{})
}
}
能够看到在设置读超时工夫为 idleTimeout 后,会再次从连贯读取数据,此时会阻塞以后协程;待超时后,读取操作会返回谬误,此时 serve 办法返回,而在返回前会敞开该连贯。
服务 panic 重启
panic 会导致程序的异样终止,Golang 服务都终止了,Nginx 必然会产生刹时大量 502 了。对应的,能够通过 recover 捕捉异样,恢复程序的执行。
生产环境,在申请入口还是加上 recover 比拟好。
defer func() {if err := recover(); err != nil {
// 打印调用栈
stack := stack(3)
// 记录申请详情
httprequest, _ := httputil.DumpRequest(c.Request, false)
logger.E("[Recovery]", "%s panic recovered:\n%s\n%s\n%s", time.Now().Format("2006/01/02 - 15:04:05"), string(httprequest), err, stack)
c.AbortWithStatus(500)
}
}()