net/http: first byte of outgoing request body is sometimes lost

[jacobsa]

% go version
go version devel +8086e7c Mon Sep 12 06:12:35 2016 +0000 darwin/amd64

(Apologies for not having been able to reproduce this hermetically. I suspect maybe it has something to do with SSL, which I don't know how to set up locally. I'm pretty sure the bug does lie in the Go client though; please keep reading.)

Here is a program that makes a bunch of calls to the Google Cloud Storage API. The calls are all identical. Although this is a heavily-reduced test case and they are not valid according to the GCS API (in particular they're missing credentials), they all do supply valid JSON in the request body.

Despite this, every time I run the program, after at most a few tens of seconds I receive an HTTP 400 parse error from GCS:

% go run http2_bug.go
[...]
Req body:
{"bucket":"foo","name":"bar"}
[...]
Resp body:
{
 "error": {
  "errors": [
   {
    "domain": "global",
    "reason": "parseError",
    "message": "Parse Error"
   }
  ],
  "code": 400,
  "message": "Parse Error"
 }
}

Status code: 400

I happen to have insider knowledge that this charmingly terse error message from GCS indicates that the JSON in the request body could not be parsed. (If you want details, please contact me internally within Google.) In particular, the server on the other end does not receive the opening { character.

Go's own HTTP2 debugging agrees.

% GODEBUG=http2debug=2 go run http2_bug.go

With this invocation, among lots of other output I see

2016/09/12 20:46:54 http2: Framer 0xc420242180: wrote HEADERS flags=END_HEADERS stream=455 len=7
2016/09/12 20:46:54 http2: Framer 0xc420242180: wrote DATA stream=455 len=1 data="\""
2016/09/12 20:46:54 http2: Framer 0xc420242180: wrote DATA stream=455 len=27 data="bucket\":\"foo\",\"name\":\"bar\"}"
2016/09/12 20:46:54 http2: Framer 0xc420242180: wrote DATA flags=END_STREAM stream=455 len=0 data=""
2016/09/12 20:46:54 http2: Framer 0xc420242180: read HEADERS flags=END_HEADERS stream=455 len=94
2016/09/12 20:46:54 http2: Framer 0xc420242180: read DATA flags=END_STREAM stream=455 len=171 data="{\n \"error\": {\n  \"errors\": [\n   {\n    \"domain\": \"global\",\n    \

The http2 package has forgotten to write the opening curly brace. In contrast, everything works fine if I use GODEBUG=http2client=0 to downgrade to HTTP1.

FYI, I have observed this from Sydney (Google office and at home, multiple computers) and from a computer within a Google data center in the US. I've seen this in Go 1.7.1 and Go 1.6.1, as well as at HEAD.

[bradfitz]

Well, crap. https://golang.org/cl/29074

Thanks for the report.

[gopherbot]

CL https://golang.org/cl/29074 mentions this issue.

[bradfitz]

This probably warrants a Go 1.7.2 since it's sporadic data corruption. It happens whenever a Request.ContentLength == 0 && Request.Body != nil && the connection is either closed or temporarily at max-streams capacity.

Two possible workarounds, though:

1. set Request.ContentLength
2. disabled HTTP/2

[gopherbot]

CL https://golang.org/cl/29081 mentions this issue.

[jacobsa]

Thanks for the quick fix. Please also consider a patch release for Go 1.6. Note that this bug was actually introduced in a patch release, since Go 1.6 didn't have HTTP2 on by default but 406752b made it into Go 1.6.2. (I may be confused about the details.)

[bradfitz]

The first Go 1.6 included HTTP/2 by default for all user-created http.Transports but not for the http.DefaultTransport. Go 1.6.2 fixed that. All the Go 1.6 betas before Go 1.6 had it enabled for the DefaultTransport too.

In any case, we don't issue point releases for two releases back. Only Go 1.7.x at this point.

[jacobsa]

Okay, sounds good. Thanks for clarifying.

[gopherbot]

CL https://golang.org/cl/29110 mentions this issue.

[gopherbot]

CL https://golang.org/cl/29111 mentions this issue.

[gaillard]

Is this going to be released?

[bradfitz]

Yes. @broady is planning on Monday.

[gaillard]

@bradfitz Forgot to mention, we had to lob this commit off because it caused a deadlock. Some mutex between RoundTrip and CanTakeNewRequest. Sorry I don't have an exact senario for you.

[broady]

@gaillard sorry, can you elaborate? this commit is bad?

[broady]

Holding off the 1.7.2 release announcement to get more information from @gaillard.

[gaillard]

I don't have much more information. Just that it locked up in the client in a concurrent scenario and appeared to be sitting in those two places from the goroutine dumps. Tested with and without the commit but it was not a fully isolated test however seems highly likely since the commit moved that call past a lock.

[bradfitz]

Was your request body an io.Pipe? Sounds like #17480

[bradfitz]

Please post stack traces of the hang if not.

[bradfitz]

Okay, better fix: https://go-review.googlesource.com/31326

@broady, we'll need to cherry-pick that to the 1.7 branch of the "net" repo, and then re-run "go generate" from the "go" repo's 1.7 branch.

[gopherbot]

CL https://golang.org/cl/31326 mentions this issue.

[gopherbot]

CL https://golang.org/cl/31361 mentions this issue.

[gopherbot]

CL https://golang.org/cl/31432 mentions this issue.

[gaillard]

I do remember a pipe in the stacks, sorry I don't have them anymore.

[gopherbot]

CL https://golang.org/cl/31434 mentions this issue.

[gopherbot]

CL https://golang.org/cl/31437 mentions this issue.

[gopherbot]

CL https://golang.org/cl/31445 mentions this issue.

[gopherbot]

CL https://golang.org/cl/31737 mentions this issue.

[gopherbot]

CL https://golang.org/cl/34668 mentions this issue.