Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

x/net/http2: GET fails on content with very large header #20689

Closed
jba opened this issue Jun 15, 2017 · 18 comments
Closed

x/net/http2: GET fails on content with very large header #20689

jba opened this issue Jun 15, 2017 · 18 comments

Comments

@jba
Copy link
Contributor

@jba jba commented Jun 15, 2017

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

go1.8.1.typealias

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

linux/amd64

What did you do?

Tried to read a GCS object with large metadata, which results in a large header (value is 100,000 bytes long).

import "cloud.google.com/go/storage"
...
 r, err := obj.NewReader(ctx)

If possible, provide a recipe for reproducing the error.

I can do this if you need it.

What did you expect to see?

Here's the http2debug=2 output when the metadata value has size 100:

2017/06/15 16:03:08 http2: Transport failed to get client conn for storage.googleapis.com:443: http2: no cached connection was available
2017/06/15 16:03:08 http2: Transport creating client conn 0xc420972820 to [2607:f8b0:4006:819::2010]:443
2017/06/15 16:03:08 http2: Framer 0xc420d72340: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/06/15 16:03:08 http2: Framer 0xc420d72340: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/06/15 16:03:08 http2: Transport encoding header ":authority" = "storage.googleapis.com"
2017/06/15 16:03:08 http2: Transport encoding header ":method" = "GET"
2017/06/15 16:03:08 http2: Transport encoding header ":path" = "/veener-jba/metadata-test"
2017/06/15 16:03:08 http2: Transport encoding header ":scheme" = "https"
2017/06/15 16:03:08 http2: Transport encoding header "user-agent" = "gcloud-golang-storage/20151204"
2017/06/15 16:03:08 http2: Transport encoding header "authorization" = "Bearer [redacted]"
2017/06/15 16:03:08 http2: Transport encoding header "accept-encoding" = "gzip"
2017/06/15 16:03:08 http2: Framer 0xc420d72340: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=179
2017/06/15 16:03:08 http2: Framer 0xc420d72340: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2017/06/15 16:03:08 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2017/06/15 16:03:08 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2017/06/15 16:03:08 http2: Framer 0xc420d72340: wrote SETTINGS flags=ACK len=0
2017/06/15 16:03:08 http2: Framer 0xc420d72340: read WINDOW_UPDATE len=4 (conn) incr=983041
2017/06/15 16:03:08 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2017/06/15 16:03:08 http2: Framer 0xc420d72340: read SETTINGS flags=ACK len=0
2017/06/15 16:03:08 http2: Transport received SETTINGS flags=ACK len=0
2017/06/15 16:03:08 http2: Framer 0xc420d72340: read HEADERS flags=END_HEADERS stream=1 len=1243
2017/06/15 16:03:08 http2: decoded hpack field header field ":status" = "200"
2017/06/15 16:03:08 http2: decoded hpack field header field "expires" = "Thu, 15 Jun 2017 20:03:08 GMT"
2017/06/15 16:03:08 http2: decoded hpack field header field "date" = "Thu, 15 Jun 2017 20:03:08 GMT"
2017/06/15 16:03:08 http2: decoded hpack field header field "cache-control" = "private, max-age=0"
2017/06/15 16:03:08 http2: decoded hpack field header field "last-modified" = "Thu, 15 Jun 2017 20:03:08 GMT"
2017/06/15 16:03:08 http2: decoded hpack field header field "etag" = "\"7324a8fc1e479cffa07031d88f05267b\""
2017/06/15 16:03:08 http2: decoded hpack field header field "x-goog-meta-k1" = "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"
2017/06/15 16:03:08 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2017/06/15 16:03:08 http2: decoded hpack field header field "accept-ranges" = "bytes"
2017/06/15 16:03:08 http2: decoded hpack field header field "content-length" = "16"
2017/06/15 16:03:08 http2: decoded hpack field header field "server" = "UploadServer"

What did you see instead?

With size 100000:

2017/06/15 16:04:10 http2: Transport failed to get client conn for storage.googleapis.com:443: http2: no cached connection was available
2017/06/15 16:04:10 http2: Transport creating client conn 0xc420d6a000 to [2607:f8b0:4006:819::2010]:443
2017/06/15 16:04:10 http2: Framer 0xc4200816c0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/06/15 16:04:10 http2: Framer 0xc4200816c0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/06/15 16:04:10 http2: Transport encoding header ":authority" = "storage.googleapis.com"
2017/06/15 16:04:10 http2: Framer 0xc4200816c0: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2017/06/15 16:04:10 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2017/06/15 16:04:10 http2: Transport encoding header ":method" = "GET"
2017/06/15 16:04:10 http2: Transport encoding header ":path" = "/veener-jba/metadata-test"
2017/06/15 16:04:10 http2: Transport encoding header ":scheme" = "https"
2017/06/15 16:04:10 http2: Transport encoding header "authorization" = "Bearer [redacted]"
2017/06/15 16:04:10 http2: Transport encoding header "user-agent" = "gcloud-golang-storage/20151204"
2017/06/15 16:04:10 http2: Transport encoding header "accept-encoding" = "gzip"
2017/06/15 16:04:10 http2: Framer 0xc4200816c0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=179
2017/06/15 16:04:10 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2017/06/15 16:04:10 http2: Framer 0xc4200816c0: wrote SETTINGS flags=ACK len=0
2017/06/15 16:04:10 http2: Framer 0xc4200816c0: read WINDOW_UPDATE len=4 (conn) incr=983041
2017/06/15 16:04:10 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2017/06/15 16:04:10 http2: Framer 0xc4200816c0: read SETTINGS flags=ACK len=0
2017/06/15 16:04:10 http2: Transport received SETTINGS flags=ACK len=0
2017/06/15 16:05:39 http2: Transport closing idle conn 0xc420072680 (forSingleUse=false, maxStream=1)
2017/06/15 16:05:39 http2: Transport readFrame error on conn 0xc420072680: (*net.OpError) read tcp [2620:0:1003:1001:6ce4:cf29:3a31:6e42]:58414->[2607:f8b0:4006:819::200d]:443: use of closed network connection
2017/06/15 16:05:40 http2: Transport closing idle conn 0xc420d6a9c0 (forSingleUse=false, maxStream=1)
2017/06/15 16:05:40 http2: Transport readFrame error on conn 0xc420d6a9c0: (*net.OpError) read tcp [2620:0:1003:1001:6ce4:cf29:3a31:6e42]:37024->[2607:f8b0:4006:814::200a]:443: use of closed network connection
2017/06/15 16:08:10 http2: Transport readFrame error on conn 0xc420d6a000: (*errors.errorString) EOF
2017/06/15 16:08:10 RoundTrip failure: unexpected EOF
@odeke-em odeke-em changed the title http2 GET fails on very large header x/net/http2: GET fails on content with very large header Jun 15, 2017
@odeke-em

This comment has been minimized.

Copy link
Member

@odeke-em odeke-em commented Jun 15, 2017

/cc HTTP2 squad @bradfitz @tombergan

@bradfitz

This comment has been minimized.

Copy link
Contributor

@bradfitz bradfitz commented Jun 15, 2017

The GFE hung up on us before sending anything.

Maybe the GFE didn't like our MAX_HEADER_LIST_SIZE = 16384 and decided that since it can't fit in 16KB, they'd just hang up.

Can you click the checkbox to make https://storage.googleapis.com/veener-jba/metadata-test be publicly readable to ease debugging?

@odeke-em

This comment has been minimized.

Copy link
Member

@odeke-em odeke-em commented Jun 15, 2017

@bradfitz or any other folks investigating I've started a repro here https://github.com/odeke-em/bugs/tree/master/golang/20689 and can't yet reproduce with a very large header https://github.com/odeke-em/bugs/blob/master/golang/20689/server.go#L10 or inlined

package main

import (
	"log"
	"net/http"
	"strings"
)

func withLargeHeader(w http.ResponseWriter, r *http.Request) {
	w.Header().Set("x-wimmie", strings.Repeat("wimmie nah", 100001))
}

func main() {
	http.HandleFunc("/", withLargeHeader)

	err := http.ListenAndServeTLS(":9999", "cert.pem", "key.pem", nil)
	if err != nil {
		log.Fatal(err)
	}
}
@jba

This comment has been minimized.

Copy link
Contributor Author

@jba jba commented Jun 15, 2017

Can you click the checkbox to make https://storage.googleapis.com/veener-jba/metadata-test be publicly readable to ease debugging?

Done.

@jba

This comment has been minimized.

Copy link
Contributor Author

@jba jba commented Jun 15, 2017

@odeke-em Consistent with Brad's guess that Google's front end is the culprit.

@jba

This comment has been minimized.

Copy link
Contributor Author

@jba jba commented Jun 15, 2017

On the other hand, this works: gsutil ls -L gs://veener-jba/metadata-test

@bradfitz

This comment has been minimized.

Copy link
Contributor

@bradfitz bradfitz commented Jun 15, 2017

Fun. The GFE or the GCS backend indeed hangs with our request:

bradfitz@gdev:~$ cat h2get.go
package main

import (
        "log"
        "net/http"
        "os"

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

func main() {
        c := &http.Client{Transport: new(http2.Transport)}
        res, err := c.Get("https://storage.googleapis.com/veener-jba/metadata-test")
        if err != nil {
                log.Fatal(err)
        }
        res.Write(os.Stdout)
}
bradfitz@gdev:~$ go build h2get.go
bradfitz@gdev:~$ GODEBUG=http2debug=2 ./h2get 
2017/06/15 21:50:36 http2: Transport creating client conn 0xc420012820 to 173.194.197.128:443
2017/06/15 21:50:36 http2: Framer 0xc42029e380: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2017/06/15 21:50:36 http2: Framer 0xc42029e380: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/06/15 21:50:36 http2: Transport encoding header ":authority" = "storage.googleapis.com"
2017/06/15 21:50:36 http2: Transport encoding header ":method" = "GET"
2017/06/15 21:50:36 http2: Transport encoding header ":path" = "/veener-jba/metadata-test"
2017/06/15 21:50:36 http2: Transport encoding header ":scheme" = "https"
2017/06/15 21:50:36 http2: Transport encoding header "accept-encoding" = "gzip"
2017/06/15 21:50:36 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/06/15 21:50:36 http2: Framer 0xc42029e380: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=59
2017/06/15 21:50:36 http2: Framer 0xc42029e380: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2017/06/15 21:50:36 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2017/06/15 21:50:36 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2017/06/15 21:50:36 http2: Framer 0xc42029e380: wrote SETTINGS flags=ACK len=0
2017/06/15 21:50:36 http2: Framer 0xc42029e380: read WINDOW_UPDATE len=4 (conn) incr=983041
2017/06/15 21:50:36 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2017/06/15 21:50:36 http2: Framer 0xc42029e380: read SETTINGS flags=ACK len=0
2017/06/15 21:50:36 http2: Transport received SETTINGS flags=ACK len=0
....
(hangs.... forever?)
@bradfitz

This comment has been minimized.

Copy link
Contributor

@bradfitz bradfitz commented Jun 15, 2017

There's no change if I modify the Go http2 Transport to not send MAX_HEADER_LIST_SIZE=10MB in our initial settings frame. (Omitting it means unlimited)

No change:

bradfitz@gdev:~$ GODEBUG=http2debug=2 ./h2get 
2017/06/15 21:53:24 http2: Transport creating client conn 0xc4200129c0 to 74.125.129.128:443
2017/06/15 21:53:24 http2: Framer 0xc4202c1180: wrote SETTINGS len=12, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304
2017/06/15 21:53:24 http2: Framer 0xc4202c1180: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2017/06/15 21:53:24 http2: Transport encoding header ":authority" = "storage.googleapis.com"
2017/06/15 21:53:24 http2: Transport encoding header ":method" = "GET"
2017/06/15 21:53:24 http2: Transport encoding header ":path" = "/veener-jba/metadata-test"
2017/06/15 21:53:24 http2: Transport encoding header ":scheme" = "https"
2017/06/15 21:53:24 http2: Transport encoding header "accept-encoding" = "gzip"
2017/06/15 21:53:24 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2017/06/15 21:53:24 http2: Framer 0xc4202c1180: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=59
2017/06/15 21:53:24 http2: Framer 0xc4202c1180: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2017/06/15 21:53:24 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2017/06/15 21:53:24 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2017/06/15 21:53:24 http2: Framer 0xc4202c1180: wrote SETTINGS flags=ACK len=0
2017/06/15 21:53:24 http2: Framer 0xc4202c1180: read WINDOW_UPDATE len=4 (conn) incr=983041
2017/06/15 21:53:24 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2017/06/15 21:53:24 http2: Framer 0xc4202c1180: read SETTINGS flags=ACK len=0
2017/06/15 21:53:24 http2: Transport received SETTINGS flags=ACK len=0
...
(hangs)
....
@bradfitz

This comment has been minimized.

Copy link
Contributor

@bradfitz bradfitz commented Jun 15, 2017

@Capstan, any ideas?

@bradfitz

This comment has been minimized.

Copy link
Contributor

@bradfitz bradfitz commented Jun 15, 2017

Chrome can't load it either:
https://storage.googleapis.com/veener-jba/metadata-test

Works with curl + HTTP/1.1 though.

@bradfitz

This comment has been minimized.

Copy link
Contributor

@bradfitz bradfitz commented Jun 15, 2017

On the other hand, this works: gsutil ls -L gs://veener-jba/metadata-test

@jba, that's Python, right? I bet it's HTTP/1.1 and not HTTP/2.

@odeke-em

This comment has been minimized.

Copy link
Member

@odeke-em odeke-em commented Jun 15, 2017

Yap yap, I can confirm what @bradfitz said about Chrome not loading, it fails with ERR_QUIC_PROTOCOL_ERROR
screen shot 2017-06-15 at 4 08 47 pm

@jba

This comment has been minimized.

Copy link
Contributor Author

@jba jba commented Jun 16, 2017

@bradfitz, yes, gsutil is Python.

@Capstan

This comment has been minimized.

Copy link

@Capstan Capstan commented Jun 21, 2017

I am surprised you can create an object with metadata that large. I was under the impression we enforced a 4KB limit on user-provided metadata.

@Capstan

This comment has been minimized.

Copy link

@Capstan Capstan commented Jun 21, 2017

False impression. We currently don't enforce any limit.

@tombergan

This comment has been minimized.

Copy link
Contributor

@tombergan tombergan commented Jun 23, 2017

I filed internal bug 62956673.

@tombergan

This comment has been minimized.

Copy link
Contributor

@tombergan tombergan commented Jun 24, 2017

Confirmed that this is a GFE bug, so I'm closing.

@jba

This comment has been minimized.

Copy link
Contributor Author

@jba jba commented Jul 27, 2017

Update: fixed in GFE and deployed.

@golang golang locked and limited conversation to collaborators Jul 27, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
6 participants
You can’t perform that action at this time.