Golang之HTTP server 502问题分析

问题引入

  生产环境Golang服务有时会产生502报警，排查发现大多是以下三种原因造成的：

1. http.Server配置了WriteTimeout，请求处理超时，Golang断开连接；
2. http.Server配置了IdleTimeout，且网关和Golang之间使用长连接，Golang断开连接；
3. 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)
    }
}()

有疑问加站长微信联系（非本文作者）