net/http: data race in HTTP/2 body close #61596

neild · 2023-07-26T18:29:15Z

This is pulling #60041 (comment) out into a separate issue.

Reproduction case:

package tmpgbudljeu3i_test

import (
	"bufio"
	"bytes"
	"fmt"
	"io"
	"net/http"
	"net/http/httptest"
	"testing"
)

func writeChunk(w io.Writer, b []byte) {
	fmt.Fprintf(w, "%x\r\n", len(b))
	w.Write(b)
	fmt.Fprint(w, "\r\n")
}

func startRequestGenerator(url string) io.ReadCloser {
	r, w := io.Pipe()
	chunk := bytes.Repeat([]byte("A"), 64)
	go func() {
		for {
			_, err := fmt.Fprintf(w, "POST %s HTTP/1.1\r\n", url)
			if err != nil {
				return
			}
			fmt.Fprint(w, "Host: localhost\r\n")
			fmt.Fprint(w, "Transfer-Encoding: chunked\r\n")
			fmt.Fprint(w, "\r\n")
			writeChunk(w, chunk)
			writeChunk(w, nil)
		}
	}()

	return r
}

func TestHTTPRace(t *testing.T) {
	svr := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		// cause cs.abortRequestBodyWrite()
		// https://github.com/golang/go/blob/go1.20.6/src/net/http/h2_bundle.go#L8205-L8216
		w.WriteHeader(http.StatusBadRequest)
	}))
	svr.EnableHTTP2 = true
	svr.StartTLS()

	r := startRequestGenerator("https://" + svr.Listener.Addr().String() + "/")
	defer r.Close()
	b := bufio.NewReader(r)
	for i := 0; i < 3; i++ {
		req, err := http.ReadRequest(b)
		if err != nil {
			t.Fatal(err)
		}
		req.RequestURI = ""
		_, err = svr.Client().Transport.RoundTrip(req)
		if err != nil {
			t.Log(err)
		}
	}
}

The text was updated successfully, but these errors were encountered:

neild · 2023-07-26T19:08:13Z

This turns out to not be a bug.

The test sends three requests. Each request is created with http.ReadRequest on the same io.Reader, so each request shares the same reader for its request body.

Closing the request body in the request returned by ReadRequest consumes the remaining body. This isn't documented, but it's probably behavior you can count on.

RoundTrip closes the request body. However, the docs state:

	// RoundTrip must always close the body, including on errors,
	// but depending on the implementation may do so in a separate
	// goroutine even after RoundTrip returns. This means that
	// callers wanting to reuse the body for subsequent requests
	// must arrange to wait for the Close call before doing so.

So what is happening is a request is sent, RoundTrip returns prior to consuming the body (because the server rejected the request without reading the body), and RoundTrip closing the body in the background then races with the next request being read.

If I insert a req.Body.Close at the end of the loop in the test, the race goes away. (The body is then double-closed by RoundTrip and the test, but it handles that fine.)

WGH- · 2023-07-26T19:11:31Z

Thank you for the analysis! Totally missed that note, my bad.

This data race requires quite of few conditions to appear. 1) The transport has to have HTTP/2 enabled (in goproxy, it's not by default). 2) The target server must be an HTTP/2 one. 3) The request must have a body. 4) The server must return certain erroneus HTTP status code. 5) The client must ignore Connection: close header from the proxy (4ec7933). Somehow, I managed to hit all these conditions, and got this error: panic: runtime error: slice bounds out of range [96:48] goroutine 341699 [running]: bufio.(*Reader).ReadSlice(0xc000b0c1e0, 0x80?) /usr/local/go/src/bufio/bufio.go:347 +0x225 bufio.(*Reader).ReadLine(0xc000b0c1e0) /usr/local/go/src/bufio/bufio.go:401 +0x27 net/textproto.(*Reader).readLineSlice(0xc0013400f0) /usr/local/go/src/net/textproto/reader.go:56 +0x99 net/textproto.(*Reader).ReadLine(...) /usr/local/go/src/net/textproto/reader.go:39 net/http.readRequest(0xc000847d40?) /usr/local/go/src/net/http/request.go:1042 +0xba net/http.ReadRequest(0xc000b0c1e0?) /usr/local/go/src/net/http/request.go:1025 +0x19 github.com/elazarl/goproxy.(*ProxyHttpServer).handleHttps.func2() /root/go/pkg/mod/github.com/elazarl/goproxy@v0.0.0-20220901064549-fbd10ff4f5a1/https.go:221 +0x3db created by github.com/elazarl/goproxy.(*ProxyHttpServer).handleHttps /root/go/pkg/mod/github.com/elazarl/goproxy@v0.0.0-20220901064549-fbd10ff4f5a1/https.go:211 +0x611 Despite 5), goproxy should not break from non-compliant HTTP clients, and "Connection: close" is more like of an accidental fix. See also golang/go#61596 (comment)

…1596 (comment))

This data race requires quite of few conditions to appear. 1) The transport has to have HTTP/2 enabled (in goproxy, it's not by default). 2) The target server must be an HTTP/2 one. 3) The request must have a body. 4) The server must return certain erroneus HTTP status code. 5) The client must ignore Connection: close header from the proxy (4ec79339bd51dec356e283d8c8de29748b42b1fe). Somehow, I managed to hit all these conditions, and got this error: panic: runtime error: slice bounds out of range [96:48] goroutine 341699 [running]: bufio.(*Reader).ReadSlice(0xc000b0c1e0, 0x80?) /usr/local/go/src/bufio/bufio.go:347 +0x225 bufio.(*Reader).ReadLine(0xc000b0c1e0) /usr/local/go/src/bufio/bufio.go:401 +0x27 net/textproto.(*Reader).readLineSlice(0xc0013400f0) /usr/local/go/src/net/textproto/reader.go:56 +0x99 net/textproto.(*Reader).ReadLine(...) /usr/local/go/src/net/textproto/reader.go:39 net/http.readRequest(0xc000847d40?) /usr/local/go/src/net/http/request.go:1042 +0xba net/http.ReadRequest(0xc000b0c1e0?) /usr/local/go/src/net/http/request.go:1025 +0x19 github.com/elazarl/goproxy.(*ProxyHttpServer).handleHttps.func2() /root/go/pkg/mod/github.com/elazarl/goproxy@v0.0.0-20220901064549-fbd10ff4f5a1/https.go:221 +0x3db created by github.com/elazarl/goproxy.(*ProxyHttpServer).handleHttps /root/go/pkg/mod/github.com/elazarl/goproxy@v0.0.0-20220901064549-fbd10ff4f5a1/https.go:211 +0x611 Despite 5), goproxy should not break from non-compliant HTTP clients, and "Connection: close" is more like of an accidental fix. See also golang/go#61596 (comment)

This data race requires quite of few conditions to appear. 1) The transport has to have HTTP/2 enabled (in goproxy, it's not by default). 2) The target server must be an HTTP/2 one. 3) The request must have a body. 4) The server must return certain erroneus HTTP status code. 5) The client must ignore Connection: close header from the proxy (4ec7933). Somehow, I managed to hit all these conditions, and got this error: panic: runtime error: slice bounds out of range [96:48] goroutine 341699 [running]: bufio.(*Reader).ReadSlice(0xc000b0c1e0, 0x80?) /usr/local/go/src/bufio/bufio.go:347 +0x225 bufio.(*Reader).ReadLine(0xc000b0c1e0) /usr/local/go/src/bufio/bufio.go:401 +0x27 net/textproto.(*Reader).readLineSlice(0xc0013400f0) /usr/local/go/src/net/textproto/reader.go:56 +0x99 net/textproto.(*Reader).ReadLine(...) /usr/local/go/src/net/textproto/reader.go:39 net/http.readRequest(0xc000847d40?) /usr/local/go/src/net/http/request.go:1042 +0xba net/http.ReadRequest(0xc000b0c1e0?) /usr/local/go/src/net/http/request.go:1025 +0x19 github.com/elazarl/goproxy.(*ProxyHttpServer).handleHttps.func2() /root/go/pkg/mod/github.com/elazarl/goproxy@v0.0.0-20220901064549-fbd10ff4f5a1/https.go:221 +0x3db created by github.com/elazarl/goproxy.(*ProxyHttpServer).handleHttps /root/go/pkg/mod/github.com/elazarl/goproxy@v0.0.0-20220901064549-fbd10ff4f5a1/https.go:211 +0x611 Despite 5), goproxy should not break from non-compliant HTTP clients, and "Connection: close" is more like of an accidental fix. See also golang/go#61596 (comment)

neild self-assigned this Jul 26, 2023

neild mentioned this issue Jul 26, 2023

net/http: data race in tip after CL 461675 #60041

Closed

bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 26, 2023

neild closed this as completed Jul 26, 2023

bcmills added the Unfortunate label Jul 26, 2023

WGH- mentioned this issue Jul 26, 2023

Fix data race in MITM'ed HTTPS request handling elazarl/goproxy#509

Merged

telanflow added a commit to telanflow/mps that referenced this issue Sep 1, 2023

Fix data race in MITM'ed HTTPS request handling.[comment](golang/go#6…

5a2b7e7

…1596 (comment))

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: data race in HTTP/2 body close #61596

net/http: data race in HTTP/2 body close #61596

neild commented Jul 26, 2023

neild commented Jul 26, 2023

WGH- commented Jul 26, 2023

net/http: data race in HTTP/2 body close #61596

net/http: data race in HTTP/2 body close #61596

Comments

neild commented Jul 26, 2023

neild commented Jul 26, 2023

WGH- commented Jul 26, 2023