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 https://github.com/golang/go/issues/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 https://github.com/golang/net/commit/ff519b6c91021e6316e1df005bc19f266994ddda. 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 https://github.com/golang/go/issues/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.

[fraenkel]

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]

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]

@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]

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

[jlourenc]

@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]

@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]

@fraenkel I think there are two problems here:

1. 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.
2. 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]

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]

@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]

@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]

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