net/http: Transfer-Encoding: chunked is sometimes used when making HTTP2 requests

[spantaleev]

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

$ docker run --rm docker.io/golang:1.15.6-alpine3.12 go version
go version go1.15.6 linux/amd64

Using docker.io/golang:1.15.6-alpine3.12

It's the same on 1.15.2 though. So I wouldn't say it's some new regression.

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ docker run --rm docker.io/golang:1.15.6-alpine3.12 go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
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=/tmp/go-build719806207=/tmp/go-build -gno-record-gcc-switches"

What did you do?

package main

import (
    "net/http"
    "io/ioutil"
    "bytes"
)

func main() {
    payloadBytes := []byte("abcd")

    request, err := http.NewRequest(
        "POST",
        "https://example.com",
        // Without `ioutil.NopCloser()`, we'd get it to find the content length.
        // With it, it remains unknown (0).
        // This is somewhat contrived.
        ioutil.NopCloser(bytes.NewReader(payloadBytes)),
    )
    if err != nil {
        panic(err)
    }

    // If this is not set, `Transfer-Encoding: chunked` may be used,
    // even over HTTP2, which is not supported:
    // https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Transfer-Encoding
    // request.ContentLength = int64(len(payloadBytes))

    http.DefaultClient.Do(request)
}

I can't reproduce it with a server of my own, but I had another person (on shared Apache hosting) show me the request headers (in PHP). We saw that it's an HTTP2 connection and that there's a Transfer-Encoding: chunked request header.

The original problem was that he couldn't read the request body (JSON).. We tracked it down to this. As soon as we set .ContentLength explicitly, Go's HTTP client no longer sets Transfer-Encoding: chunked and the problem goes away.

The same code (even without explicitly setting .ContentLength) works as expected on HTTP2-capable servers of mine (nginx).

So it seems to be some weird interaction between that specific Apache version (which is unknown so far) and Golang's HTTP client. There may be some reverse-proxies inbetween, so it may be something else's fault entirely (not Golang's HTTP client).

Unfortunately, I neither have an HTTP2-capable Apache server of mine, nor do I know the exact Apache version that his shared hosting provider runs.

Obviously, there's lack of information about this (Apache version used, whether there are other reverse-proxies involved, etc.), but perhaps this is still enough to track down the problem of net/http's willingness to combine HTTP2 with chunked transfer encoding under weird circumstances..? Again, that is, unless something else (some reverse-proxy) is actually causing this.

[networkimprov]

cc @fraenkel

[fraenkel]

@spantaleev can you collect the http2debug logs for the client so we can see what is being sent?

It's going to be difficult without a way to reproduce this.

[spantaleev]

Testing with this code:

package main

import (
    "fmt"
    "net/http"
    "bytes"
    "io/ioutil"
)

func main() {
    payloadBytes := []byte("{\"key\": \"value\"}")

    request, err := http.NewRequest(
        "POST",
        "https://example.com/api",
        bytes.NewReader(payloadBytes),
    )
    if err != nil {
        panic(err)
    }

    request.Header.Set("Content-Type", "application/json")
    request.Header.Set("Authorization", "Bearer XXXXXXXXXXXX")

    request.ContentLength = 0

    resp, err := http.DefaultClient.Do(request)
    if err != nil {
        panic(err)
    }
    
    defer resp.Body.Close()
    
    bodyBytes, err := ioutil.ReadAll(resp.Body)
    if err != nil {
        panic(err)
    }
                                                                                                                                                                                                  
    fmt.Println(string(bodyBytes))
}

---

The faulty server is Apache/2.4.46 (Ubuntu) OpenSSL/1.1.1.

GODEBUG=http2debug=2 go run go.go:

2020/12/23 15:09:09 http2: Transport failed to get client conn for apache.hostname:443: http2: no cached connection was available
2020/12/23 15:09:10 http2: Transport creating client conn 0xc000482600 to 1.2.3.4:443
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/12/23 15:09:10 http2: Transport encoding header ":authority" = "apache.hostname"
2020/12/23 15:09:10 http2: Transport encoding header ":method" = "POST"
2020/12/23 15:09:10 http2: Transport encoding header ":path" = "/api"
2020/12/23 15:09:10 http2: Transport encoding header ":scheme" = "https"
2020/12/23 15:09:10 http2: Transport encoding header "content-type" = "application/json"
2020/12/23 15:09:10 http2: Transport encoding header "authorization" = "Bearer XXXXXXXXXXXX"
2020/12/23 15:09:10 http2: Transport encoding header "accept-encoding" = "gzip"
2020/12/23 15:09:10 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: wrote HEADERS flags=END_HEADERS stream=1 len=106
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: wrote DATA stream=1 len=16 data="{\"key\": \"value\"}"
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: wrote DATA flags=END_STREAM stream=1 len=0 data=""
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: read SETTINGS len=6, settings: MAX_CONCURRENT_STREAMS=100
2020/12/23 15:09:10 http2: Transport received SETTINGS len=6, settings: MAX_CONCURRENT_STREAMS=100
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: wrote SETTINGS flags=ACK len=0
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: read SETTINGS flags=ACK len=0
2020/12/23 15:09:10 http2: Transport received SETTINGS flags=ACK len=0
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: read WINDOW_UPDATE len=4 (conn) incr=2147418112
2020/12/23 15:09:10 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2147418112
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: read HEADERS flags=END_HEADERS stream=1 len=70
2020/12/23 15:09:10 http2: decoded hpack field header field ":status" = "200"
2020/12/23 15:09:10 http2: decoded hpack field header field "date" = "Wed, 23 Dec 2020 13:09:10 GMT"
2020/12/23 15:09:10 http2: decoded hpack field header field "server" = "Apache"
2020/12/23 15:09:10 http2: decoded hpack field header field "access-control-allow-origin" = "*"
2020/12/23 15:09:10 http2: decoded hpack field header field "vary" = "Accept-Encoding,User-Agent"
2020/12/23 15:09:10 http2: decoded hpack field header field "content-encoding" = "gzip"
2020/12/23 15:09:10 http2: decoded hpack field header field "content-type" = "text/html"
2020/12/23 15:09:10 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=70
2020/12/23 15:09:10 http2: Framer 0xc0002f7420: read DATA flags=END_STREAM stream=1 len=230 data="\x1f\x8b\b\x00\x00........"
2020/12/23 15:09:10 http2: Transport received DATA flags=END_STREAM stream=1 len=230 data="\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x03L........"

The request headers are dumped into the response body and I can see Transfer-Encoding: chunked there.

---

Here's what I get for another server (nginx/1.18.0), where it's all fine:

GODEBUG=http2debug=2 go run go.go:

2020/12/23 15:07:52 http2: Transport failed to get client conn for nginx.hostname:443: http2: no cached connection was available
2020/12/23 15:07:52 http2: Transport creating client conn 0xc000582300 to 4.3.2.1:443
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2020/12/23 15:07:52 http2: Transport encoding header ":authority" = "nginx.hostname"
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
2020/12/23 15:07:52 http2: Transport encoding header ":method" = "POST"
2020/12/23 15:07:52 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=128, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16777215
2020/12/23 15:07:52 http2: Transport encoding header ":path" = "/api"
2020/12/23 15:07:52 http2: Transport encoding header ":scheme" = "https"
2020/12/23 15:07:52 http2: Transport encoding header "content-type" = "application/json"
2020/12/23 15:07:52 http2: Transport encoding header "authorization" = "Bearer XXXXXXXXXXXX"
2020/12/23 15:07:52 http2: Transport encoding header "accept-encoding" = "gzip"
2020/12/23 15:07:52 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: wrote HEADERS flags=END_HEADERS stream=1 len=93
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: wrote SETTINGS flags=ACK len=0
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: read WINDOW_UPDATE len=4 (conn) incr=2147418112
2020/12/23 15:07:52 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=2147418112
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: wrote DATA stream=1 len=16 data="{\"key\": \"value\"}"
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: wrote DATA flags=END_STREAM stream=1 len=0 data=""
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: read SETTINGS flags=ACK len=0
2020/12/23 15:07:52 http2: Transport received SETTINGS flags=ACK len=0
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: read WINDOW_UPDATE stream=1 len=4 incr=2147418111
2020/12/23 15:07:52 http2: Transport received WINDOW_UPDATE stream=1 len=4 incr=2147418111
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: read HEADERS flags=END_HEADERS stream=1 len=44
2020/12/23 15:07:52 http2: decoded hpack field header field ":status" = "200"
2020/12/23 15:07:52 http2: decoded hpack field header field "server" = "nginx"
2020/12/23 15:07:52 http2: decoded hpack field header field "date" = "Wed, 23 Dec 2020 13:07:52 GMT"
2020/12/23 15:07:52 http2: decoded hpack field header field "content-type" = "application/json"
2020/12/23 15:07:52 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=44
2020/12/23 15:07:52 http2: Framer 0xc0002b61c0: read DATA flags=END_STREAM stream=1 len=246 data="{\"action\": .....}"
2020/12/23 15:07:52 http2: Transport received DATA flags=END_STREAM stream=1 len=246 data="{\"action\": .....}"

---

Hope this is helpful!

[fraenkel]

Sorry but I don't see them client ever sending chunked. If there server side is saying so it is broken.
The debug shows exactly what headers are sent.

The only other difference I see is one is sending a gzipped response which is allowed.

[spantaleev]

Thanks for checking it out! I suppose the problem lies somewhere on the server side then. Perhaps there's some reverse-proxy somewhere or something. It will be reported to the service provider. Sorry for wasting your time on this!