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: under load, Go GCS library or http2 sends bad MIME, gets 400 response with body: "Invalid multipart request with 0 mime parts" #30693

Closed
mkmg opened this Issue Mar 8, 2019 · 10 comments

Comments

Projects
None yet
4 participants
@mkmg
Copy link

commented Mar 8, 2019

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

$ go version
go version go1.12 linux/amd64

Does this issue reproduce with the latest release?

Yes, but not with go1.11

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

go env Output
$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/usr/local/home/mkmg/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/usr/local/home/mkmg/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/home/mkmg/.gimme/versions/go1.12.linux.amd64"
GOTMPDIR=""
GOTOOLDIR="/usr/local/home/mkmg/.gimme/versions/go1.12.linux.amd64/pkg/tool/linux_amd64"
GCCGO="gccgo"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build652119083=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Created many threads (>=100) which continuously upload objects to a GCS bucket in parallel.
To run the program:

What did you expect to see?

No errors.

What did you see instead?

A small number of requests fail with the following error:
googleapi: got HTTP response code 400 with body: Invalid multipart request with 0 mime parts.

These errors do not appear when the program is run with go version go1.11 linux/amd64.

Output from running the provided sample program:

2019/03/08 19:06:05 Setting up GCS client...
2019/03/08 19:06:06 Worker 20: Failed to copy file: googleapi: got HTTP response code 400 with body: Invalid multipart request with 0 mime parts.
2019/03/08 19:06:09 Worker 25: Failed to copy file: googleapi: got HTTP response code 400 with body: Invalid multipart request with 0 mime parts.
2019/03/08 19:06:11 Worker 43: Failed to copy file: googleapi: got HTTP response code 400 with body: Invalid multipart request with 0 mime parts.
2019/03/08 19:06:15 Worker 13: Failed to copy file: googleapi: got HTTP response code 400 with body: Invalid multipart request with 0 mime parts.
2019/03/08 19:06:35 Done!
@bradfitz

This comment has been minimized.

Copy link
Member

commented Mar 8, 2019

Can you share the output of GODEBUG=http2debug=2?

@bradfitz

This comment has been minimized.

Copy link
Member

commented Mar 8, 2019

(be sure to redact any credentials)

Or email it to me privately. This username at golang org.

@bradfitz

This comment has been minimized.

Copy link
Member

commented Mar 9, 2019

Thanks for the email. I extracted out one of the failures from the 163M log.

2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2019/03/08 23:37:50 http2: Transport encoding header ":authority" = "www.googleapis.com"
2019/03/08 23:37:50 http2: Framer 0xc000159500: read SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2019/03/08 23:37:50 http2: Transport received SETTINGS len=18, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_HEADER_LIST_SIZE=16384
2019/03/08 23:37:50 http2: Transport encoding header ":method" = "POST"
2019/03/08 23:37:50 http2: Transport encoding header ":path" = "/upload/storage/v1/b/xxx/o?alt=json&prettyPrint=false&projection=full&uploadType=multipart"
2019/03/08 23:37:50 http2: Transport encoding header ":scheme" = "https"
2019/03/08 23:37:50 http2: Transport encoding header "user-agent" = "gcloud-golang-storage/20151204"
2019/03/08 23:37:50 http2: Transport encoding header "content-type" = "multipart/related; boundary=2d8fa96978b2c1f3a1166a9b95bf155f577d4dee5e0995ecc13d8bd1fad1"
2019/03/08 23:37:50 http2: Transport encoding header "authorization" = ""
2019/03/08 23:37:50 http2: Transport encoding header "x-cloud-trace-context" = "7b6b126401b59a2618b8359163589ef1/10174193077940530760;o=0"
2019/03/08 23:37:50 http2: Transport encoding header "x-goog-api-client" = "xxx"
2019/03/08 23:37:50 http2: Transport encoding header "accept-encoding" = "gzip"
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote HEADERS flags=END_HEADERS stream=1 len=387
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote SETTINGS flags=ACK len=0
2019/03/08 23:37:50 http2: Framer 0xc000159500: read WINDOW_UPDATE len=4 (conn) incr=983041
2019/03/08 23:37:50 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2019/03/08 23:37:50 http2: Framer 0xc000159500: read SETTINGS flags=ACK len=0
2019/03/08 23:37:50 http2: Transport received SETTINGS flags=ACK len=0
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote DATA stream=1 len=98 data="--4a8bd68a87d2cceda24a08ceb18c297da81b033bba680f856141c2b1ec93\r\nContent-Type: application/json\r\n\r\n"
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote DATA stream=1 len=68 data="{\"bucket\”:\”xxx\”,\”name\":\"2019-03-08-23-37-50/83/file-0.bin\"}\n"
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote DATA stream=1 len=108 data="\r\n--4a8bd68a87d2cceda24a08ceb18c297da81b033bba680f856141c2b1ec93\r\nContent-Type: application/octet-stream\r\n\r\n"
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote DATA stream=1 len=1024 data=“….” (nnn bytes omitted)
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote DATA stream=1 len=68 data="\r\n--4a8bd68a87d2cceda24a08ceb18c297da81b033bba680f856141c2b1ec93--\r\n"
2019/03/08 23:37:50 http2: Framer 0xc000159500: wrote DATA flags=END_STREAM stream=1 len=0 data=""
…
2019/03/08 23:37:50 http2: Framer 0xc000159500: read HEADERS flags=END_HEADERS stream=1 len=178
2019/03/08 23:37:50 http2: decoded hpack field header field ":status" = "400"
2019/03/08 23:37:50 http2: decoded hpack field header field "x-guploader-uploadid" = “xxx-xxxx”
2019/03/08 23:37:50 http2: decoded hpack field header field "content-length" = "44"
2019/03/08 23:37:50 http2: decoded hpack field header field "date" = "Fri, 08 Mar 2019 23:37:50 GMT"
2019/03/08 23:37:50 http2: decoded hpack field header field "server" = "UploadServer"
2019/03/08 23:37:50 http2: decoded hpack field header field "content-type" = "text/html; charset=UTF-8"
2019/03/08 23:37:50 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=178
2019/03/08 23:37:50 http2: Transport encoding header ":authority" = "www.googleapis.com"
2019/03/08 23:37:50 http2: Transport encoding header ":method" = "POST"
2019/03/08 23:37:50 http2: Transport encoding header ":path" = "/upload/storage/v1/b/xxxx/o?alt=json&prettyPrint=false&projection=full&uploadType=multipart"
2019/03/08 23:37:50 http2: Transport encoding header ":scheme" = "https"
2019/03/08 23:37:50 http2: Framer 0xc000159500: read DATA stream=1 len=44 data="Invalid multipart request with 0 mime parts."

Looks like the boundary delimiter is declared to be 2d8fa96978b2c1f3a1166a9b95bf155f577d4dee5e0995ecc13d8bd1fad1 in the headers but then it's 4a8bd68a87d2cceda24a08ceb18c297da81b033bba680f856141c2b1ec93 in the request body. Looks like that's also the case with other 400s in the log you emailed me.

I'm not sure what's causing that, though.

It looks like the code responsible for generating that multipart message is https://github.com/googleapis/google-api-go-client/blob/ed2534c57ed076df43af394869d83ac66b040e17/gensupport/media.go#L118 but I don't see anything wrong with that code.

As for Go 1.11 vs Go 1.12, I can't think of anything in mime/multipart, net/http, or x/net/http2 that would've changed behavior here. There was a629399 for mime/multipart but I don't see any quoted boundaries here anyway, and I don't think anybody is calling the mime/multipart.Writer.SetBoundary method anyway.

You're sure you're not able to reproduce it with Go 1.11 but are with Go 1.12?

Hopefully it's not a race within x/net/http2, sending the wrong headers from a different request. That'd scare & surprise me if so.

Can you try running it under the Go race detector and see if there are any errors? Your repro code looks fine.

/cc @fraenkel

@bradfitz

This comment has been minimized.

Copy link
Member

commented Mar 9, 2019

Also cc @jadekler @jba @zombiezen on the Go Cloud side.

@bradfitz bradfitz changed the title HTTP response code 400 with body: Invalid multipart request with 0 mime parts. x/net/http2: under load, Go GCS library or http2 sends bad MIME, gets 400 response with body: "Invalid multipart request with 0 mime parts" Mar 9, 2019

@bradfitz bradfitz added this to the Go1.13 milestone Mar 9, 2019

@bradfitz bradfitz self-assigned this Mar 9, 2019

@mkmg

This comment has been minimized.

Copy link
Author

commented Mar 9, 2019

I tried running it under the Go race detector and it didn't print any errors.

I'm sure this isn't reproducible with go 1.11.

@fraenkel

This comment has been minimized.

Copy link
Contributor

commented Mar 9, 2019

@bradfitz Given that the request had a mismatch on boundary, was there a request in the log that had matching data or a matching header?

@bradfitz

This comment has been minimized.

Copy link
Member

commented Mar 9, 2019

@fraenkel, great question. I just looked. Both those strings above only occurred in the exchange as quoted.

And it looks the same in the other failure. (I just noticed the 163M log only has two 400s.)

@fraenkel

This comment has been minimized.

Copy link
Contributor

commented Mar 9, 2019

I think I see the issue, but I could be mistaken.
If we start at https://github.com/googleapis/google-api-go-client/blob/master/gensupport/media.go#L282, an initial boundary is created. If fb and fm are != nil, then a second one is created in the getBody at https://github.com/googleapis/google-api-go-client/blob/master/gensupport/media.go#L287.

@jadekler

This comment has been minimized.

Copy link
Contributor

commented Mar 11, 2019

Different user reported the same thing: googleapis/google-cloud-go#1350

@bradfitz

This comment has been minimized.

Copy link
Member

commented Mar 16, 2019

Dup of googleapis/google-api-go-client#343

I have a fix I'm sending there.

@bradfitz bradfitz closed this Mar 16, 2019

gopherbot pushed a commit to googleapis/google-api-go-client that referenced this issue Mar 18, 2019

gensupport: fix incorrect MIME boundary being used in bodies on retries
And fix the test that was trying to catch this case but was failing
due to its always-returns-zeros rand fake. The corrected test now
fails without the fix and passes with it.

Thanks to Michael Fraenkel for identifying the problem.

Fixes #343
Fixes googleapis/google-cloud-go#1350
Fixes golang/go#30693

Change-Id: If4251facebbbbeb9f1e169845d0d3573e871d741
Reviewed-on: https://code-review.googlesource.com/c/google-api-go-client/+/39076
Reviewed-by: Jean de Klerk <deklerk@google.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.