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

mkmg · 2019-03-08T19:47:22Z

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:

Create a bucket in GCS
Set-up authentication so the sample program can write to the bucket
Change the DEFAULT_BUCKET constant in the sample program to the name of your bucket
Run go get cloud.google.com/go/storage
Run the sample program (bugrepro.go)
bugrepro.go.zip [edit: also at https://play.golang.org/p/73Qbd4DMpbV ]

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!

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

bradfitz · 2019-03-08T23:19:39Z

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

bradfitz · 2019-03-08T23:20:01Z

(be sure to redact any credentials)

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

bradfitz · 2019-03-09T00:27:44Z

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 · 2019-03-09T00:28:37Z

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

mkmg · 2019-03-09T00:54:04Z

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 · 2019-03-09T01:49:13Z

@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 · 2019-03-09T01:59:36Z

@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 · 2019-03-09T02:19:00Z

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.

jeanbza · 2019-03-11T16:06:02Z

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

bradfitz · 2019-03-16T16:35:08Z

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

I have a fix I'm sending there.

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>

bradfitz added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 9, 2019

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 added this to the Go1.13 milestone Mar 9, 2019

bradfitz self-assigned this Mar 9, 2019

jeanbza mentioned this issue Mar 11, 2019

googleapi: got HTTP response code 400 with body: Invalid multipart request with 0 mime parts. googleapis/google-cloud-go#1350

Closed

bradfitz mentioned this issue Mar 16, 2019

UploadRequest uses the wrong boundary on retries googleapis/google-api-go-client#343

Closed

bradfitz closed this as completed Mar 16, 2019

golang locked and limited conversation to collaborators Mar 15, 2020

gopherbot added the FrozenDueToAge label Mar 15, 2020

rsc unassigned bradfitz Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

mkmg commented Mar 8, 2019 •

edited by bradfitz

bradfitz commented Mar 8, 2019

bradfitz commented Mar 8, 2019

bradfitz commented Mar 9, 2019

bradfitz commented Mar 9, 2019

mkmg commented Mar 9, 2019

fraenkel commented Mar 9, 2019

bradfitz commented Mar 9, 2019

fraenkel commented Mar 9, 2019

jeanbza commented Mar 11, 2019

bradfitz commented Mar 16, 2019

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

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

Comments

mkmg commented Mar 8, 2019 • edited by bradfitz

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?

bradfitz commented Mar 8, 2019

bradfitz commented Mar 8, 2019

bradfitz commented Mar 9, 2019

bradfitz commented Mar 9, 2019

mkmg commented Mar 9, 2019

fraenkel commented Mar 9, 2019

bradfitz commented Mar 9, 2019

fraenkel commented Mar 9, 2019

jeanbza commented Mar 11, 2019

bradfitz commented Mar 16, 2019

mkmg commented Mar 8, 2019 •

edited by bradfitz

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

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