x/net/http2: RoundTrip hangs when the response status code > 299

[chungthuang]

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

$ go version
go version go1.15.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
go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/cf000197/Library/Caches/go-build"
GOENV="/Users/cf000197/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/cf000197/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/cf000197/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.15.5/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.15.5/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/cf000197/go/issues/go.mod"
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/t1/fvz_vb0n6g9fpqwmdcl2yfbh0000gn/T/go-build998981477=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I followed #13444 to create bidirectional streams. It works great when the server returns 200, but on the client side we are seeing roundtrip hanging when the response status > 299, after upgrading to latest http2. The commit that introduced the issue is golang/net@ff519b6. Even though abortRequestBodyWrite is called when response status > 299, Read in https://github.com/golang/net/blame/master/http2/transport.go#L1333 is blocked indefinitely.
Here is a program to reproduce the issue.

package main

import (
	"fmt"
	"io"
	"io/ioutil"
	"log"
	"net"
	"net/http"
	"os"
	"time"

	"golang.org/x/net/http2"
)

func main() {
	pr, pw := io.Pipe()

	// Host doesn't matter in this case because we already have a connection to the server
	req, err := http.NewRequest(http.MethodPut, "https://http2.golang.org", ioutil.NopCloser(pr))
	if err != nil {
		log.Fatal(err)
	}

	clientConn, serverConn := net.Pipe()
	if err != nil {
		log.Fatal(err)
	}
	go func() {
		server := http2.Server{}
		server.ServeConn(serverConn, &http2.ServeConnOpts{
			Handler: http.HandlerFunc(errorEndpoint),
		})
	}()
	go func() {
		transport := http2.Transport{}
		http2ClientConn, err := transport.NewClientConn(clientConn)
		res, err := http2ClientConn.RoundTrip(req)
		if err != nil {
			log.Fatal(err)
		}
		log.Printf("Got: %#v", res)
		go streamRequest(pw)
		n, err := io.Copy(os.Stdout, res.Body)
		log.Fatalf("copied %d, %v", n, err)
	}()
	select {}
}

func streamRequest(pw io.Writer) {
	for {
		time.Sleep(1 * time.Second)
		fmt.Fprintf(pw, "It is now %v\n", time.Now())
	}
}

func errorEndpoint(w http.ResponseWriter, r *http.Request) {
	w.WriteHeader(http.StatusInternalServerError)
	w.Write([]byte(http.StatusText(http.StatusInternalServerError)))
}

Go module that causes the roundtrip to hang:

module main

go 1.15

require (
	golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9 // indirect
	golang.org/x/net v0.0.0-20210119194325-5f4716e94777 // indirect
	golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1 // indirect
	golang.org/x/text v0.3.3 // indirect
)

Go module that was working:

module main

go 1.15

require (
	golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9 // indirect
	golang.org/x/net v0.0.0-20200904194848-62affa334b73 // indirect
	golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1 // indirect
	golang.org/x/text v0.3.3 // indirect
)

What did you expect to see?

Roundtrip returns with a 500 response.

What did you see instead?

Roundtrip hangs indefinitely

[fraenkel]

I believe this is a bug in your code.
You create a roundtrip with a body made from a pipe. You never actually start sending any data on it so the RoundTrip is stuck waiting on a read from the pipe.

[chungthuang]

Hi @fraenkel, my client retries only if roundtrip returns an error. To avoid implementing a rewindable reader, I intentionally wait for roundtrip to return before sending data. This was working in golang.org/x/net v0.0.0-20200904194848.

[ipostelnik]

The RoundTrip code relies on being able to read the body to proceed in case of a non-200 status, this is not a reasonable expectation. It's possible that client will wait to see some of the response before writing the body.

[DeepAQ]

Reproduced this bug on Windows with go1.16 h2_bundle.go. Is there any workaround for this?

go env Output

set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.16
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=NUL
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config

[jlourenc]

Hi @fraenkel,

the issue has been reported against x/net/http2 module, however this package version has been integrated into Go 1.15 from the 8th revision (see the release notes and Go 1.16. Hence, it is now mainstream.

This has caused an unfortunate change of behaviour impacting any type of tunnelling relying on the proxy server to acknowledge/decline the transaction before writing the content in the body.

I am providing here below another example using the HTTP CONNECT verb, based on the discussion provided in #13717.

func TestHTTP2Connect(t *testing.T) {
	testCases := []struct {
		name       string
		statusCode int
	}{
		{
			name:       "200 OK",
			statusCode: http.StatusOK,
		},
		{
			name:       "401 UNAUTHORIZED hangs",
			statusCode: http.StatusUnauthorized,
		},
	}

	for _, tc := range testCases {
		t.Run(tc.name, func(t *testing.T) {
			destinationServer := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
				if r.Method != http.MethodPost {
					w.WriteHeader(http.StatusMethodNotAllowed)
					return
				}

				data, err := ioutil.ReadAll(r.Body)
				if err != nil {
					log.Fatalf("destination request body read failure: %s", err)
				}

				w.WriteHeader(http.StatusOK)
				w.Write(append([]byte("received: "), data...))
			}))
			defer destinationServer.Close()

			destinationServer.EnableHTTP2 = true
			destinationServer.StartTLS()
			log.Print("destinationServer: " + destinationServer.URL)

			proxyServer := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
				if r.Method != http.MethodConnect {
					http.Error(w, http.StatusText(http.StatusMethodNotAllowed), http.StatusMethodNotAllowed)
					return
				}

				if tc.statusCode > 299 {
					http.Error(w, http.StatusText(tc.statusCode), tc.statusCode)
					return
				}

				log.Print(r.Host)
				conn, err := tls.Dial("tcp", r.Host, &tls.Config{
					InsecureSkipVerify: true,
				})
				if err != nil {
					http.Error(w, err.Error(), http.StatusServiceUnavailable)
					return
				}

				w.WriteHeader(tc.statusCode)
				w.(http.Flusher).Flush()

				wg := sync.WaitGroup{}

				wg.Add(1)
				go func() {
					if _, err := io.Copy(conn, r.Body); err != nil {
						log.Fatalf("outbound copy failure: %s", err)
					}
					r.Body.Close()
					conn.CloseWrite()
					wg.Done()
				}()

				wg.Add(1)
				go func() {
					if _, err := io.Copy(w, conn); err != nil {
						log.Fatalf("inbound copy failure: %s", err)
					}
					conn.Close()
					wg.Done()
				}()

				wg.Wait()
			}))
			defer proxyServer.Close()

			proxyServer.EnableHTTP2 = true
			proxyServer.StartTLS()
			log.Print("proxyServer: " + proxyServer.URL)

			pr, pw := io.Pipe()
			req, err := http.NewRequest(http.MethodConnect, proxyServer.URL, pr)
			if err != nil {
				log.Fatal(err)
			}
			req.ContentLength = -1

			destinationURL, err := url.Parse(destinationServer.URL)
			if err != nil {
				log.Fatal(err)
			}
			req.Host = destinationURL.Host

			resp, err := proxyServer.Client().Do(req)
			if err != nil {
				log.Fatalf("request execution failure: %s", err)
			}
			log.Printf("resp: %v", resp)

			if resp.StatusCode != http.StatusOK {
				pw.Close()
				log.Fatalf("want 200 OK, got %s", resp.Status)
			}

			req, _ = http.NewRequest(http.MethodPost, destinationServer.URL, strings.NewReader("payload"))
			if err := req.Write(pw); err != nil {
				log.Fatalf("req write failure: %s", err)
			}
			pw.Close()

			resp, err = http.ReadResponse(bufio.NewReader(resp.Body), req)
			if err != nil {
				log.Fatalf("Response read failure: %s", err)
			}
			defer resp.Body.Close()

			data, err := ioutil.ReadAll(resp.Body)
			if err != nil {
				log.Fatalf("Response body read failure: %s", err)
			}

			if string(data) != "received: payload" {
				log.Fatalf("unexpected response body: %s", data)
			}

			log.Print("success")
		})
	}
}

I'd greatly appreciate your input on this matter. Thanks!

[fraenkel]

https://datatracker.ietf.org/doc/html/rfc7231#section-4.3.6

Any 2xx (Successful) response indicates that the sender (and all
inbound proxies) will switch to tunnel mode immediately after the
blank line that concludes the successful response's header section

Any response other than a successful response
   indicates that the tunnel has not yet been formed and that the
   connection remains governed by HTTP.

https://datatracker.ietf.org/doc/html/rfc7540#section-8.3
Notice here, only 2xx are allowed.