升级golang版本引起的一个bug

1 背景

最经公司在搞开源组件漏洞修复, 有个api网关项目扫出了几个漏洞, 为了修复这些漏洞升级了gin的版本, 同时由于gin的新版本依赖了一些go语言的新特性, 因此将编译用的go镜像也从1.15升级到了1.19.

简单测试没啥问题之后就发到了测试环境, 但是过了几天有人找过来, 当返回的数据量比较大的时候, 数据会被截断, 需要排查.

2 分析

这个项目是一个api网关, 本质上就是使用了gin做为api框架, 然后定义了几个 middleware, 最后一层middleware用了go自带的reverseproxy实现请求转发.

观察curl命令的返回结果:

* Connected to 127.0.0.1 (127.0.0.1) port 8888 (#0)
    > POST /apis/ HTTP/1.1
    > Host: 127.0.0.1:8888
    > User-Agent: curl/8.1.2
    > Accept: */*
    > Content-Type: application/json
    > Content-Length: 233
    >
} [233 bytes data]
100   233    0     0  100   233      0    192  0:00:01  0:00:01 --:--:--   193< HTTP/1.1 200 OK
< Access-Control-Allow-Credentials: true
< Access-Control-Allow-Headers: *
< Access-Control-Allow-Methods: *
< Access-Control-Expose-Headers: *
< Content-Type: application/json
< Date: Wed, 22 May 2024 06:33:05 GMT
< Server: nginx
< Transfer-Encoding: chunked
<
{ [32774 bytes data]
  100 33001    0 32768  100   233  23057    163  0:00:01  0:00:01 --:--:-- 23289
  * Connection #0 to host 127.0.0.1 left intact

实际上后端返回的数据有400多k, 但是curl命令只拿到了32768, 恰好是32KB, 因此考虑这里是写一个32k的buffer写完之后没有继续写而是直接关闭连接了.

继续观察这里比较可疑的"Transfer-Encoding: chunked", 这个header是为了在数据量大的时候支持流式传输, 提升响应速度. golang中如果返回的数据里比较小会设置Content-Length, 客户端通过Content-Length来判断什么时获取到全部数据, 当数据量大的时候则设置Transfer-Encoding: chunked分块传输, 客户端每次都会先难道一个块大小然后是块内容, 当拿到块大小为0则说明传输完成. 这里猜测是设置了"Transfer-Encoding: chunked"但是只传输了一个块, 链接就中断了, 但是go基础库和gin都是很成熟的组件, 如果出现这种情况早就被发现了.

telnet发送http请求

由于curl隐藏了一些信息, 为了更直观的分析返回数据, 这里用telnet来发送http请求

$ telnet 127.0.0.1 8888
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
^]
  telnet>
  POST /apis/ HTTP/1.1
  Host: 127.0.0.1:8888
  User-Agent: curl/8.1.2
  Accept: */*
  Content-Type: application/json
  Content-Length: 180

  {POST的数据}
  HTTP/1.1 200 OK
  Access-Control-Allow-Credentials: true
  Access-Control-Allow-Headers: *
  Access-Control-Allow-Methods: *
  Access-Control-Expose-Headers: *
  Content-Type: application/json
  Date: Wed, 22 May 2024 03:13:24 GMT
  Server: nginx
  Transfer-Encoding: chunked

  8000
  // 具体数据

  0

可以看到后端服务返回的第一个快大小是8000, 这个是16进制, 其实就是32KB, 但是第二个块就直接是0了. 也就是说这里并不是异常导致的链接中断, 而是服务器正常结束链接

ReverseProxy

接下来排查思路就是看下gin的middleware是如何写数据给客户端的. 我们的代码中最后一个middleware是go自带的ReverseProxy, 最终写返回数据也是这一个 middleware里写的, 因此需要分析这个组件的代码.

这里的核心逻辑代码位于src/net/http/httputils/reverseproxy.go的ServerHTTP函数

func() {
        // ...
        // 获取下游的返回数据
        res, err := transport.RoundTrip(outreq)
        if err != nil {
                p.getErrorHandler()(rw, outreq, err)
                return
        }

        // ...
        // 允许修改下游返回的response
        if !p.modifyResponse(rw, res, outreq) {
                return
        }

        copyHeader(rw.Header(), res.Header)

        // ...

        // 写返回数据到writer
        err = p.copyResponse(rw, res.Body, p.flushInterval(res))
        // ...
}

copyResponse的实现:

func (p *ReverseProxy) copyResponse(dst io.Writer, src io.Reader, flushInterval time.Duration) error {
        if flushInterval != 0 {
                if wf, ok := dst.(writeFlusher); ok {
                        // 多了个定期flush的功能
                        mlw := &maxLatencyWriter{
                                dst:     wf,
                                latency: flushInterval,
                        }
                        defer mlw.stop()

                        // set up initial timer so headers get flushed even if body writes are delayed
                        mlw.flushPending = true
                        mlw.t = time.AfterFunc(flushInterval, mlw.delayedFlush)

                        dst = mlw
                }
        }

        var buf []byte
        if p.BufferPool != nil {
                buf = p.BufferPool.Get()
                defer p.BufferPool.Put(buf)
        }
        _, err := p.copyBuffer(dst, src, buf)
        return err
}

// copyBuffer returns any write errors or non-EOF read errors, and the amount
// of bytes written.
func (p *ReverseProxy) copyBuffer(dst io.Writer, src io.Reader, buf []byte) (int64, error) {
        if len(buf) == 0 {
                buf = make([]byte, 32*1024)
        }
        var written int64
        for {
                // 每次从下游的response里读取数据到buf, 然后写到上游给的writer里
                nr, rerr := src.Read(buf)
                if rerr != nil && rerr != io.EOF && rerr != context.Canceled {
                        p.logf("httputil: ReverseProxy read error during body copy: %v", rerr)
                }
                if nr > 0 {
                        nw, werr := dst.Write(buf[:nr])
                        if nw > 0 {
                                written += int64(nw)
                        }
                        if werr != nil {
                                return written, werr
                        }
                        if nr != nw {
                                return written, io.ErrShortWrite
                        }
                }
                if rerr != nil {
                        if rerr == io.EOF {
                                rerr = nil
                        }
                        return written, rerr
                }
        }
}

其中copyBuffer的代码中看到了熟悉的32*1024(32KB), 直觉上问题就跟这里脱不了关系了. 但是看下面的读写数据的代码没看出错误来, 做为go的基础库应该也不会有问题.

接下来就看dst.Write到底write到了什么地方, 这里的dst应该gin框架中的 ResponseWriter, 为了排查问题直接修改vendor中ResponseWriter的Writer函数加了一行日志

func (w *responseWriter) Write(data []byte) (n int, err error) {
        // 加了这里
        fmt.Println("write %d", len(data))
        w.WriteHeaderNow()
        n, err = w.ResponseWriter.Write(data)
        w.size += n
        return
}

但是运行结果里看到只打印了一行write 32768, 就没有后续了.

继续排查, copyResponse中有一个maxLatencyWriter用于定时Flush, 将 flushInterval打印出来得到-1, 也就是每次write都会flush, 这里再在 ResponseWriter的Flush接口中也加一行日志, 可以发现根本就没有被调用到! 那就只有一种可能, 这里的Writer根本就不是ResponseWriter对象. 将writer的类型也打印出来, 原来是我们这个网关自己定义了一个Writer替换掉了gin中默认的ResponseWriter囧囧囧, 至于为什么要自定义, 原作者已经跑路也无从得知了

这个自定义的代码是这么写的

// Flush fake flush
func (w *responseBuffer) Flush() {
        return
}

func (w *responseBuffer) realFlush() {
        // 已经Flush过久不再flush
        if w.Flushed {
                return
        }
        w.Response.WriteHeader(w.status)
        if w.Body.Len() > 0 {
                _, err := w.Response.Write(w.Body.Bytes())
                if err != nil {
                        panic(err)
                }
                w.Body.Reset()
        }
        w.Flushed = true
}

当数据量大的时候, ReverseProxy会每次写32KB, 然后flush, 但是这个自定义的writer flush过一次之后后续的flush都会忽略, 所以导致了客户端只收到 32KB这个问题

那么为什么1.15的go编译出来就没问题呢? 这里看了下1.15和1.19的代码的区别 https://github.com/golang/go/blob/go1.15.11/src/net/http/httputil/reverseproxy.go

// flushInterval returns the p.FlushInterval value, conditionally
// overriding its value for a specific request/response.
func (p *ReverseProxy) flushInterval(req *http.Request, res *http.Response) time.Duration {
        resCT := res.Header.Get("Content-Type")

        // For Server-Sent Events responses, flush immediately.
        // The MIME type is defined in https://www.w3.org/TR/eventsource/#text-event-stream
        if resCT == "text/event-stream" {
                return -1 // negative means immediately
        }

        // TODO: more specific cases? e.g. res.ContentLength == -1?
        return p.FlushInterval
}

https://github.com/golang/go/blob/go1.19.13/src/net/http/httputil/reverseproxy.go

// flushInterval returns the p.FlushInterval value, conditionally
// overriding its value for a specific request/response.
func (p *ReverseProxy) flushInterval(res *http.Response) time.Duration {
        resCT := res.Header.Get("Content-Type")

        // For Server-Sent Events responses, flush immediately.
        // The MIME type is defined in https://www.w3.org/TR/eventsource/#text-event-stream
        if baseCT, _, _ := mime.ParseMediaType(resCT); baseCT == "text/event-stream" {
                return -1 // negative means immediately
        }

        // We might have the case of streaming for which Content-Length might be unset.
        if res.ContentLength == -1 {
                return -1
        }

        return p.FlushInterval
}

可以看到, 1.19多了几行代码, 当ContentLength未指定的时候会将flush interval设置成-1, -1会导致每次都flush, 进而触发自定义writer的bug. 而 1.15没有这个逻辑, 最终flushinterval会用默认的也就是0, 0的话就不会分多次flush, 而是最终全部写完之后执行一次flush, 所以自定义writer没问题

升级golang版本引起的一个bug

1 背景

2 分析

telnet发送http请求

ReverseProxy

CATALOG

FEATURED TAGS

FRIENDS