net/http: request.Body.Close can be called more than once

[benoit-a]

What version of Go are you using (go version)?

❯ go version
go version go1.14.5 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

❯ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/me/Library/Caches/go-build"
GOENV="/Users/me/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/me/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.14.5/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.14.5/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/yp/8jdpdcb13mn5k6m6jdcqlbjr0000gn/T/go-build087461839=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Context: doing a large PUT on a remote server ( > 200 kB) with no specified Content-Length (using T-E: chunked)

I am passing a io.ReadCloser to request.Body and I want to avoid a double call on close (these are supposed to be undefined behaviour).
But sometimes, when the remote server is not consuming the entire payload and returns an error, Close() is called twice.

The following code reproduce the issue on my laptop. This may require multiple runs.

package main

import (
	"fmt"
	"io"
	"net/http"
	"net/http/httptest"
	"runtime/debug"
	"strings"
)

type smallReader struct {
	r      io.Reader
	closed bool
	prevBt []byte
}

func (r *smallReader) Read(p []byte) (int, error) {
	return r.r.Read(p)
}

func (r *smallReader) Close() error {
	if r.closed == true {
		fmt.Println((string)(r.prevBt))
		panic("already closed")
	}
	r.prevBt = debug.Stack()
	r.closed = true
	return nil
}

func newSmallReader(size int) io.ReadCloser {
	r := &smallReader{
		r:      strings.NewReader(strings.Repeat("X", size)),
		closed: false,
	}
	return r
}

func TestCrash906() {
	h := func(w http.ResponseWriter, r *http.Request) {
		if r.Body != nil {
			buf := make([]byte, 1)
			r.Body.Read(buf)
			defer r.Body.Close()
		}
		w.Header().Add("Connection", "close")
		w.WriteHeader(411)
	}

	mux := http.NewServeMux()
	mux.HandleFunc("/", h)

	srv := httptest.NewServer(mux)
	defer srv.Close()

	for i := 300000; i < 600000; i += 10000 {
		req, err := http.NewRequest(http.MethodPut, srv.URL, nil)

		req.Body = newSmallReader(i)

		if err != nil || req == nil {
			panic("not expected")
		}

		resp, _ := http.DefaultClient.Do(req)
		if resp != nil {
			resp.Body.Close()
		}
	}
}

func main() {
	TestCrash906()
}

What did you expect to see?

Nothing, Close() should be called only once.

What did you see instead?

❯ go run -race main.go
goroutine 51 [running]:
runtime/debug.Stack(0xc0000a01f0, 0x0, 0x3)
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/debug/stack.go:24 +0xab
main.(*smallReader).Close(0xc0000a01e0, 0x0, 0x0)
	/Users/benoitartuso/Sources/T906/main.go:27 +0x65
net/http.(*transferWriter).writeBody(0xc0002b6000, 0x1528200, 0xc0002a0000, 0x2, 0x2)
	/usr/local/Cellar/go/1.14.5/libexec/src/net/http/transfer.go:372 +0x5aa
net/http.(*Request).write(0xc0000ae100, 0x1528200, 0xc0002a0000, 0x0, 0xc00029a060, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/net/http/request.go:685 +0x85a
net/http.(*persistConn).writeLoop(0xc0000ca000)
	/usr/local/Cellar/go/1.14.5/libexec/src/net/http/transport.go:2280 +0x332
created by net/http.(*Transport).dialConn
	/usr/local/Cellar/go/1.14.5/libexec/src/net/http/transport.go:1648 +0xc34

panic: already closed

goroutine 51 [running]:
main.(*smallReader).Close(0xc0000a01e0, 0x1528400, 0xc0002c4000)
	/Users/benoitartuso/Sources/T906/main.go:25 +0x1e4
net/http.(*Request).closeBody(...)
	/usr/local/Cellar/go/1.14.5/libexec/src/net/http/request.go:1391
net/http.(*persistConn).writeLoop(0xc0000ca000)
	/usr/local/Cellar/go/1.14.5/libexec/src/net/http/transport.go:2296 +0x5a4
created by net/http.(*Transport).dialConn
	/usr/local/Cellar/go/1.14.5/libexec/src/net/http/transport.go:1648 +0xc34
exit status 2

With a first glance at the code, I can see a reason for that.

In T-E: chunked, the net/http.(*transferWriter).writeBody function will close the body and then, will write the EOF chunk. This write and all the following "Flush" calls on the writer may return an error.
If there is an error, writeLoop() interpret it as a signal that the body is not closed. So any error happening after the actual close of the body in writeBody() will lead to a double close.

[seankhliao]

io.Closer says

The behavior of Close after the first call is undefined. Specific implementations may document their own behavior.

So I agree that net/http should not call Close twice

[cagedmantis]

/cc @bradfitz @bcmills

[rsc]

Since this bug dates back to Go 1.14 I think we can leave it for the next cycle and not hold up Go 1.15.

[rsc]

/cc @neild