net/http: req.Body.Close called multiple times in http1, sometimes not called by the time Do returns on error

[twmb]

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

go version devel +c80897b691 Mon Jul 16 20:29:54 2018 +0000 linux/amd64

Does this issue reproduce with the latest release?

Yes.

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/twmb/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/twmb/go"
GORACE=""
GOROOT="/home/twmb/go/go"
GOTMPDIR=""
GOTOOLDIR="/home/twmb/go/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build640822210=/tmp/go-build -gno-record-gcc-switches"

What did you do?

In net/http/clientserver_test.go

func TestOneCloseOnPartialReqBodyRead(t *testing.T) {
        defer afterTest(t)
        for _, doUseH2 := range []bool{false, true} {
                for _, chunked := range []bool{false, true} {
                        cst := newClientServerTest(t, doUseH2, HandlerFunc(func(w ResponseWriter, r *Request) {
                                r.Body.Read(make([]byte, 1))
                                panic(ErrAbortHandler)
                        }))
                        defer cst.close()

                        saw0, sawMany := false, false
                        for i := 0; i < 10000; i++ {
                                closes := 0 
                                req, err := NewRequest("POST", cst.ts.URL, nil) 
                                if err != nil {
                                        t.Fatalf("unable to make request: %v", err) 
                                }
                                req.Body = countCloseReader{
                                        &closes,
                                        bytes.NewReader(bytes.Repeat([]byte("a"), 12586)),
                                }
                                req.ContentLength = 12586
                                if chunked {
                                        req.ContentLength = -1 
                                }
                                res, err := cst.c.Do(req)
                                if err == nil {
                                        res.Body.Close()
                                        t.Fatalf("expected an error to be returned from Post")
                                }
                                switch closes {
                                case 0:
                                        if !saw0 {
                                                t.Errorf("closes = %d; want 1 (h2? %v, chunked? %v)", closes, doUseH2, chunked)
                                        }
                                        saw0 = true 
                                case 1:
                                default:
                                        if !sawMany {
                                                t.Errorf("closes = %d; want 1 (h2? %v, chunked? %v)", closes, doUseH2, chunked)
                                        }
                                        sawMany = true 
                                }
                                if saw0 && sawMany {
                                        break
                                }
                        }
                }
        }
}

What did you expect to see?

No test failure.

What did you see instead?

--- FAIL: TestOneCloseOnPartialReqBodyRead (5.97s)
    clientserver_test.go:1429: closes = 2; want 1 (h2? false, chunked? false)
    clientserver_test.go:1423: closes = 0; want 1 (h2? false, chunked? false)
    clientserver_test.go:1429: closes = 2; want 1 (h2? false, chunked? true)
    clientserver_test.go:1423: closes = 0; want 1 (h2? true, chunked? false)

transferWriter's WriteBody calls its BodyCloser's Close if there was no write error (close one). That function then returns nil, at which point the persistConn flushes buffered data. That can error, and the error causes a closeBody.

Unrelated but visible in the same test, sometimes close is not called by the time the request returns. I'm not sure if this is expected, and it may be fine. If so, the test iterations can be dropped significantly and the switch / failure cases modified. It does close shortly after return (which is visible with a sleep and then a re-check). I would expect this to be show up in the race detector but I can't get it to show up (I also can't get any output / prints to show up when running tests in the stdlib).

[twmb]

Also, I couldn't get this to trigger using a small body. I did not dig into why exactly that is.

[FiloSottile]

/cc @bradfitz

[bradfitz]

Moving to Go 1.12, as I see no mention of this being a regression since Go 1.10.

[twmb]

(not a regression, also note related to #19186)

[gopherbot]

Change https://golang.org/cl/124315 mentions this issue: net/http: fix double-close of req.Body

[gopherbot]

Change https://golang.org/cl/125635 mentions this issue: net/http: fix double-close of of req.Body after redirect

[twmb]

I lost interest in pursuing this after the initial round of reviews took quite a long time.. Maybe it doesn't happen anymore on tip, maybe it does.