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

chungthuang · 2021-01-29T14:31:45Z

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

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

fraenkel · 2021-01-29T19:33:02Z

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 · 2021-01-29T20:33:52Z

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 · 2021-02-01T13:57:45Z

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.

due to lots of issues with x/net/http2, as well as the hundled h2_bundle.go in the go runtime should be avoided for now. golang/go#23559 golang/go#42534 golang/go#43989 golang/go#33425 golang/go#29246 With collection of such issues present, it make sense to remove HTTP2 support for now

due to lots of issues with x/net/http2, as well as the bundled h2_bundle.go in the go runtime should be avoided for now. golang/go#23559 golang/go#42534 golang/go#43989 golang/go#33425 golang/go#29246 With collection of such issues present, it make sense to remove HTTP2 support for now

* fix: metacache should only rename entries during cleanup (minio#11503) To avoid large delays in metacache cleanup, use rename instead of recursive delete calls, renames are cheaper move the content to minioMetaTmpBucket and then cleanup this folder once in 24hrs instead. If the new cache can replace an existing one, we should let it replace since that is currently being saved anyways, this avoids pile up of 1000's of metacache entires for same listing calls that are not necessary to be stored on disk. * turn off http2 for TLS setups for now (minio#11523) due to lots of issues with x/net/http2, as well as the bundled h2_bundle.go in the go runtime should be avoided for now. golang/go#23559 golang/go#42534 golang/go#43989 golang/go#33425 golang/go#29246 With collection of such issues present, it make sense to remove HTTP2 support for now * fix: save ModTime properly in disk cache (minio#11522) fix minio#11414 * fix: osinfos incomplete in case of warnings (minio#11505) The function used for getting host information (host.SensorsTemperaturesWithContext) returns warnings in some cases. Returning with error in such cases means we miss out on the other useful information already fetched (os info). If the OS info has been succesfully fetched, it should always be included in the output irrespective of whether the other data (CPU sensors, users) could be fetched or not. * fix: avoid timed value for network calls (minio#11531) additionally simply timedValue to have RWMutex to avoid concurrent calls to DiskInfo() getting serialized, this has an effect on all calls that use GetDiskInfo() on the same disks. Such as getOnlineDisks, getOnlineDisksWithoutHealing * fix: support IAM policy handling for wildcard actions (minio#11530) This PR fixes - allow 's3:versionid` as a valid conditional for Get,Put,Tags,Object locking APIs - allow additional headers missing for object APIs - allow wildcard based action matching * fix: in MultiDelete API return MalformedXML upon empty input (minio#11532) To follow S3 spec * Update yaml files to latest version RELEASE.2021-02-14T04-01-33Z * fix: multiple pool reads parallelize when possible (minio#11537) * Add support for remote tier management With this change MinIO's ILM supports transitioning objects to a remote tier. This change includes support for Azure Blob Storage, AWS S3 and Google Cloud Storage as remote tier storage backends. Co-authored-by: Poorna Krishnamoorthy <poorna@minio.io> Co-authored-by: Krishna Srinivas <krishna@minio.io> Co-authored-by: Krishnan Parthasarathi <kp@minio.io> Co-authored-by: Harshavardhana <harsha@minio.io> Co-authored-by: Poorna Krishnamoorthy <poornas@users.noreply.github.com> Co-authored-by: Shireesh Anjal <355479+anjalshireesh@users.noreply.github.com> Co-authored-by: Anis Elleuch <vadmeste@users.noreply.github.com> Co-authored-by: Minio Trusted <trusted@minio.io> Co-authored-by: Krishna Srinivas <krishna.srinivas@gmail.com> Co-authored-by: Poorna Krishnamoorthy <poorna@minio.io> Co-authored-by: Krishna Srinivas <krishna@minio.io>

due to lots of issues with x/net/http2, as well as the bundled h2_bundle.go in the go runtime should be avoided for now. golang/go#23559 golang/go#42534 golang/go#43989 golang/go#33425 golang/go#29246 With collection of such issues present, it make sense to remove HTTP2 support for now

DeepAQ · 2021-03-12T15:39:22Z

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 · 2021-05-26T16:38:57Z

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 · 2021-05-26T23:37:11Z

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.

fraenkel · 2021-05-27T00:08:15Z

However, something does feel odd about this. I am looking at it closer.
Your testcase does have issues that are unrelated since you dial and attempt to proxy after you already sent back a 401.

fraenkel · 2021-05-27T00:39:40Z

The issue is when we go down this path
https://github.com/golang/net/blob/master/http2/transport.go#L1129

Nothing will break the outstanding body.Read. We need to close the body but we need to wrap it first so we can allow multiple closes. One from here and one in writeRequestBody

fraenkel · 2021-05-27T01:34:19Z

@bradfitz @neild This means that when a 200 is returned, we do not guarantee closing the body. If we did the fact that the proxy body is being used for the actual request wouldn't work. It also means that we aren't waiting on the body writer before we return in a 2xx as well.

@jlourenc I also found this little tidbit.
https://golang.org/pkg/net/http/#Request

  // Go's HTTP client does not support sending a request with
    // the CONNECT method. See the documentation on Transport for
    // details.

DeepAQ · 2021-05-27T04:35:23Z

Should the client close request body when a non-2xx response is received?

jlourenc · 2021-05-27T18:15:19Z

@fraenkel , thanks for the quick replies.

Your testcase does have issues that are unrelated since you dial and attempt to proxy after you already sent back a 401.

You're right. The test cases have some flaws that I have now corrected (test cases amended). However, I believe this does not alter the change of behaviour in h2_bundle.go they uncover.

@jlourenc I also found this little tidbit.

I noticed that too. This was introduced with this commit which seems to mostly be HTTP/1 related. Plus, the documentation on Transport got removed with this commit. As for HTTP/2, h2_bundle.go's got special handling of CONNECT method, making me think the package is able to handle this verb.

The issue is when we go down this path
https://github.com/golang/net/blob/master/http2/transport.go#L1129

That's right. The goroutine that reads the request body is stuck here, which does not allow the body to be closed here. On the other side the http2serverConn is stuck here.

fraenkel · 2021-05-28T01:16:51Z

@jlourenc If all the fixes are made, I believe the 200 path will also no longer work the way you want. Once Client.Do returns, the request body (pr) will be closed and the Write you do afterwards should result in an error, ErrClosedPipe.

DeepAQ · 2021-05-28T04:13:41Z

@fraenkel I think there are two problems here:

The client starts writing the body immediately after sending request header. In the HTTP CONNECT scenario, "body" data is expected to be sent after receiving a 200 response from server. Currently, the only way to delay body write is to send an Expect: 100-continue header with ExpectContinueTimeout set. There should be another option to delay body write until receiving response header from server.
When the client receives a response with status code > 299, body write will be cancelled but the request body is not closed. This will block the goroutine, and the client will never know that server returned a non-2xx status.

Here is my use case, with a timeout timer for workaround:

pr, pw := io.Pipe()
defer pr.Close()
defer pw.Close()

req, err := http.NewRequest(http.MethodConnect, "https://server_address", pr)
if err != nil {
    return
}
req.Host = "target_address"

timeOut := time.AfterFunc(5 * time.Second, func() {
    pr.Close()
})
resp, err := transport.RoundTrip(req) // transport is a http.Transport
timeOut.Stop()
if err != nil || resp.StatusCode != http.StatusOK {
    return
}

// start writing data to pw and reading from resp.Body

jlourenc · 2021-05-28T11:33:14Z

By and large, I agree with @DeepAQ. The timeout timer does not feel like a viable solution to me as:

it plays with time and there is no guarantee that server processed the request within the given time frame
also, from https://golang.org/pkg/net/http/#RoundTripper, it is the responsibility of the RoundTripper to close the request's body.

However, the code snippet definitely highlights the problem and the steps to resolution.

fraenkel · 2021-05-28T13:33:08Z

@DeepAQ While correct, that is not what the http.Client provides. If you want CONNECT behavior, you must use the Proxy support built-in. There is a reason why the documentation states CONNECT is not supported.

DeepAQ · 2021-05-30T02:49:00Z

@fraenkel This issue is not limited to CONNECT requests, it can happen with other request methods too.

Content-Length headers are optional for HTTP/2, that means both client and server can send data without a fixed length until the underlying stream is closed. In this case, RoundTrip() should return immediately after receiving response header from server, which is the current behavior for 2xx responses. For non-2xx responses, the behavior is inconsistent and will block the client.

I also noticed that the documents in https://golang.org/pkg/net/http/#RoundTripper says:

RoundTrip must always close the body, including on errors

However, http2.Transport is not closing the body on errors, even when body write is cancelled.

gopherbot · 2021-05-30T18:48:45Z

Change https://golang.org/cl/323689 mentions this issue: http2: Transport will close the request body

As per client.Do and Request.Body, the transport is responsible to close the request Body. If there was an error or non 1xx/2xx status code, the transport will wait for the body writer to complete. If there is no data available to read, the body writer will block indefinitely. To prevent this, the body will be closed if it hasn't already. If there was a 1xx/2xx status code, the body will be closed eventually. Updates golang/go#43989 Change-Id: I9a4a5f13658122c562baf915e2c0c8992a023278 Reviewed-on: https://go-review.googlesource.com/c/net/+/323689 Reviewed-by: Damien Neil <dneil@google.com> Trust: Damien Neil <dneil@google.com> Trust: Alexander Rakoczy <alex@golang.org> Run-TryBot: Damien Neil <dneil@google.com> TryBot-Result: Go Bot <gobot@golang.org>

This version contains fix to golang/go#43989

As per client.Do and Request.Body, the transport is responsible to close the request Body. If there was an error or non 1xx/2xx status code, the transport will wait for the body writer to complete. If there is no data available to read, the body writer will block indefinitely. To prevent this, the body will be closed if it hasn't already. If there was a 1xx/2xx status code, the body will be closed eventually. Updates golang/go#43989 Change-Id: I9a4a5f13658122c562baf915e2c0c8992a023278 Reviewed-on: https://go-review.googlesource.com/c/net/+/323689 Reviewed-by: Damien Neil <dneil@google.com> Trust: Damien Neil <dneil@google.com> Trust: Alexander Rakoczy <alex@golang.org> Run-TryBot: Damien Neil <dneil@google.com> TryBot-Result: Go Bot <gobot@golang.org>

seankhliao added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 29, 2021

harshavardhana mentioned this issue Feb 11, 2021

turn off http2 for TLS setups for now minio/minio#11523

Merged

7 tasks

nmldiegues mentioned this issue Aug 25, 2021

Compiling 2021.8.3 using Go 1.17 fails cloudflare/cloudflared#442

Closed

sssilver pushed a commit to cloudflare/cloudflared that referenced this issue Nov 10, 2021

TUN-5405: Update net package to v0.0.0-20211109214657-ef0fda0de508

7024d19

This version contains fix to golang/go#43989

seankhliao added this to the Unplanned milestone Aug 27, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

chungthuang commented Jan 29, 2021

fraenkel commented Jan 29, 2021

chungthuang commented Jan 29, 2021 •

edited

ipostelnik commented Feb 1, 2021

DeepAQ commented Mar 12, 2021

jlourenc commented May 26, 2021 •

edited

fraenkel commented May 26, 2021

fraenkel commented May 27, 2021

fraenkel commented May 27, 2021

fraenkel commented May 27, 2021

DeepAQ commented May 27, 2021

jlourenc commented May 27, 2021

fraenkel commented May 28, 2021

DeepAQ commented May 28, 2021 •

edited

jlourenc commented May 28, 2021

fraenkel commented May 28, 2021

DeepAQ commented May 30, 2021

gopherbot commented May 30, 2021

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

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

Comments

chungthuang commented Jan 29, 2021

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

fraenkel commented Jan 29, 2021

chungthuang commented Jan 29, 2021 • edited

ipostelnik commented Feb 1, 2021

DeepAQ commented Mar 12, 2021

jlourenc commented May 26, 2021 • edited

fraenkel commented May 26, 2021

fraenkel commented May 27, 2021

fraenkel commented May 27, 2021

fraenkel commented May 27, 2021

DeepAQ commented May 27, 2021

jlourenc commented May 27, 2021

fraenkel commented May 28, 2021

DeepAQ commented May 28, 2021 • edited

jlourenc commented May 28, 2021

fraenkel commented May 28, 2021

DeepAQ commented May 30, 2021

gopherbot commented May 30, 2021

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

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

chungthuang commented Jan 29, 2021 •

edited

jlourenc commented May 26, 2021 •

edited

DeepAQ commented May 28, 2021 •

edited