golang net

write on closed buffer 错误分析

Posted by Luffyao on Saturday, September 26, 2020

问题描述

这几天系统测试的同事给我们报了个奇怪的问题，就是在压力测试下，一个服务的 client 端在处理消息的时候会出现 write on closed buffer 的错误。虽然这个问题较为奇怪，但是好在它能够在本地压力测试下复现。

问题分析

由于我们这个服务使用的是 Golang，并且 Client 端使用的是 HTTP2，因此，我们选择的是 net/http2。

下面我贴了下基本处理逻辑代码，（这个显然是很多语法问题的）。我只是为了能够便于下面分析问题。

func Test() error{
    req, _ := http.NewRequest(http.MethodPost, url, bytes.NewBuffer(body))

    rsp, err := f.client.Do(req)

    defer func() { _ = rsp.Body.Close() }()

    switch rsp.StatusCode {
    case http.StatusCreated:
        return rsp.Header.Get("location"), nil
    case http.StatusNotFound:
        return  error.NewError(rsp.StatusCode)
    case http.StatusNotImplemented:
        b, err := ioutil.ReadAll(rsp.Body)
        return error.NewError(rsp.StatusCode)
    case http.StatusServiceUnavailable:
        b, err := ioutil.ReadAll(rsp.Body)
        return error.NewError(rsp.StatusCode)
    default:
        return error.NewError(http.StatusInternalServerError)
    }
}

而上面为啥我说这个问题比较奇怪呢，看到这段代码，是不是觉得相当简单，不可能出现问题呢。所以没理由正常情况下没问题，压力测试下就会出现这个 write on closed buffer 的错误。

虽然觉得奇怪，但是还是要分析解决的。因此我们就在本地复现这个问题，从而定位解决这个问题。

问题复现

由于我们系统测试的同事有他们自己的一套测试用例和集群环境，因为他们比较忙，基本上不可能全职为我们 debug。因此我们只能在本地使用 h2load 和写一个 mock server 去模拟 Server 端回的数据，期待能够复现。

好在上天不负有心人，我们很快就复现了这个问题，并且基本上每次都能够复现（我们一次 10 分钟压力测试）。好了，既然能够复现问题，那找到问题的根源也指日可待。

问题定位

由于我们知道错误的内容是什么，于是乎，在 net/http2 里面 grep 了一把 write on closed buffer 关键词。

结果出现了一处： ./pipe.go:69:var errClosedPipeWrite = errors.New("write on closed buffer") 。 然后又在 pipe.go 中 grep 了一把 errClosedPipeWrite，只有两处，一处就是上面那句，另一处是在下面这个函数中。

// Write copies bytes from p into the buffer and wakes a reader.
// It is an error to write more data than the buffer can hold.
func (p *pipe) Write(d []byte) (n int, err error) {
    p.mu.Lock()
    defer p.mu.Unlock()
    if p.c.L == nil {
        p.c.L = &p.mu
    }
    defer p.c.Signal()
    if p.err != nil {
        return 0, errClosedPipeWrite
    }
    if p.breakErr != nil {
        p.unread += len(d)
        return len(d), nil // discard when there is no reader
    }
    return p.b.Write(d)
}

此函数可以看到出现我们的问题的条件就是这里的 p.err != nil。 因此我们需要找到设置这个 err 值的地方。然后发现下面这两个函数：

// CloseWithError causes the next Read (waking up a current blocked
// Read if needed) to return the provided err after all data has been
// read.
//
// The error must be non-nil.
func (p *pipe) CloseWithError(err error) { p.closeWithError(&p.err, err, nil) }

// closeWithErrorAndCode is like CloseWithError but also sets some code to run
// in the caller's goroutine before returning the error.
func (p *pipe) closeWithErrorAndCode(err error, fn func()) { p.closeWithError(&p.err, err, fn) }

同样 grep 下这两个函数使用的地方（这里我们是 client 端有问题，因此过滤掉了 server 端的调用）:

./pipe.go:104:func (p *pipe) closeWithErrorAndCode(err error, fn func()) { p.closeWithError(&p.err, err, fn) }
./transport.go:2216:cs.bufPipe.closeWithErrorAndCode(err, code)

./pipe.go:95:func (p *pipe) CloseWithError(err error) { p.closeWithError(&p.err, err, nil) }
./transport.go:316:cs.bufPipe.CloseWithError(err)
./transport.go:862:cs.bufPipe.CloseWithError(err)
./transport.go:1728:cs.bufPipe.CloseWithError(err) // no-op if already closed
./transport.go:2340:cs.bufPipe.CloseWithError(err)

可以看到除了在./pipe.go 中两处定义之外，只有五处调用了这两个函数。通过对这五处调用的地方加上日志进行 debug。并且设置GODEBUG=http2debug=2 环境变量开启了 net/HTTP2 的 debug 模式。 然后发现很多下面这句日志2020/09/25 14:30:08 http2: Framer 0xc0004b4380: wrote RST_STREAM stream=170185 len=4 ErrCode=CANCEL。 于是过滤了下这个 CANCEL 的 ErrCode 对应于代码里为 ErrCodeCancel。于是在 ErrCodeCancel 相关的地方都加了日志进行分析。

通过分析，发现下面一个规律：

2020/09/25 14:30:08 http2: Framer 0xc0004b4380: read HEADERS flags=END_HEADERS stream=170185 len=217
2020/09/25 14:30:08 http2: Transport received HEADERS flags=END_HEADERS stream=170185 len=217
2020/09/25 14:30:08 http2: Framer 0xc0004b4380: read DATA flags=END_STREAM stream=170185 len=290 data="xxxxx(34 bytes omitted)
2020/09/25 14:30:08 http2: Transport received DATA flags=END_STREAM stream=170185 len=290 data="xxxxx" (34 bytes omitted)
ErrCodeCancel 8 cancelStream ID  170185
2020/09/25 14:30:08 http2: Framer 0xc0004b4380: wrote RST_STREAM stream=170185 len=4 ErrCode=CANCEL
2020/09/25 14:30:08 http2: Transport conn 0xc000445980 received error from processing frame DATA flags=END_STREAM stream=170185 len=290 data="xxxxx(34 bytes omitted): write on closed buffer

这里以 streamID 为 170185 为例，分析下它的处理流程。(NOTE: ErrCodeCancel 8 cancelStream ID 170185 是在 func (b transportResponseBody) Close() error 函数中）。

从数据包来看，先是 socket 读了 170185 stream 的 HEADER 部分，然后 socket 又收到了 DATA 部分。然后此时，有人调用了 func (b transportResponseBody) Close() error函数去关闭了 responseBody, 并写入了 RST_STREAM 给 Server， 但是此时将 DATA 的数据写入 pip 的时候就出现了我们的这个错误（上述有提到是在调用 pip.Write 函数时，出现的这个问题）。

从上面的处理来看基本上就是将 DATA 数据写入到 pip 的时候，发现 pipbuf 已经被人关闭了。并且是通过调用 func (b transportResponseBody) Close() error 函数关闭的。那这个函数显然是我们业务逻辑代码里写的 defer func() { _ = rsp.Body.Close() }()。

所以分析下来 也就是说，我们收到了 HEADER 进行处理了，就把 response.Body 关闭了，然后 DATA 部分想写入 response.Body 里面，但是 response.Body 已经被关闭，所以就出现这个错误了。从代码上看下来，刚好我们对应于 201 的 response 的 DATA 部分并没有处理。所以导致了这个问题。

解决方案

知道问题所在，那我们就能很快解决了。我是通过在 201 的 response 分支中添加了b, err := ioutil.ReadAll(rsp.Body), 对 response Body 的处理，也就是说等 DATA 部分的数据消费完，再结束函数，调用 defer 的 Close 函数。这样就可以解决这个问题了。通过修改并测试，最终问题解决。

Response Body 处理流程

请参考:

net http2 response body handling flow

简单描述下这个流程：

  1. 当 client 端收到 HEADER 的时候就会创建一个新的 http.Response 结构，并创建一个 pipe 赋值给了 cs.bufPipe，并重新创建了一个 transportResponseBody 对象赋值给了 res.Body。
  2. 当有 DATA frame 的时候，则会在 processData 的函数中调用 cs.bufPipe.Write 函数将 DATA 写入到 bufPipe 中。
  3. 当业务逻辑调用 ioutil.ReadAll(res.Body) 的时候，会最终调用到 transportResponseBody 对象的 Read 函数，并最后调用到 pipe 的 Read 函数。从而将第二步中写入的 DATA 读取出来。
  4. 当处理数据完毕，则调用 res.Body.Close 函数关闭相关资源。首先这函数其实是 transportResponseBody.Close 函数，然后会调用到 pipe 的 BreakWithError 函数，最后将 pipe 的 pipeBuffer 置为 nil，从而使得资源立即释放。

总结

在拿到问题的时候，其实我们开始有点先入为主的思想，想着这个 defer 函数肯定没问题，而浪费了不少时间。而后来又怀疑是 net/http2 库版本升级导致这个问题的出现。于是有分析其代码中的逻辑。而并没有很细致的数据包的处理流程上的分析。基本上通过广撒网的方式在各种怀疑的地方添加日志进行分析。这种方式虽然很有用，但是毕竟有点走弯路。因为这是压力测试，会有很多的日志。所以添加了很多不相关的日志反而添加了分析的难度。

在这个问题也能看出来，net/http2 库对于数据的处理部分不是很好，例如这里我们之所以没有处理 DATA 部分是因为我们不需要 DATA 的数据，又不想调用 ReadAll 去读取，毕竟读取也是需要时间的。但是这会导致本文中的错误，这个错误会导致连接会被关闭，所以这个错误并不是我们所期望的。也不知这个是不是一个 net/httpt2 的一个 BUG 呢？

CATALOG
    FEATURED TAGS
    c++17 client-go coredump design-pattern docker envoy gerrit git github golang hpack hugo iptables istio kafka kernel kubernetes linux mtls net netfilter operator-sdk profiling raft tcpdump 随笔