x/net/http2: Client POST request fails against golang http/2 server if client request.Body isn't completely consumed. #15425
Comments
|
To expand on this, I made a repo containing code which is able to reproduce this issue over at https://github.com/6f7262/go-http2-bug including an equivalent nodejs sever. I'd also like to point out that during testing, some clients which were using HTTP/1.1 still had similar effects, except that consequent requests were still fine and the error returned from chrome's inspector was |
|
Hmm, I've tried digging into this with go version go version devel +758431f Mon Apr 25 02:13:58 2016 +0000 darwin/amd64, because about 2 months ago, I encountered this same issue on production servers and worked around it by the same work around I've updated your original code @nemothekid spinning a client and a server. The code is at https://github.com/odeke-em/bugs/tree/master/golang/15425 or here below inlined
package main
import (
"crypto/tls"
"io"
"io/ioutil"
"log"
"net/http"
"os"
"strings"
"golang.org/x/net/http2"
)
func main() {
serverURL := "https://localhost:1333"
if envServURL := os.Getenv("SERVER_URL"); envServURL != "" {
serverURL = envServURL
}
certs, err := tls.LoadX509KeyPair("key.crt", "key.key")
if err != nil {
log.Fatal(err)
}
tr := &http.Transport{
TLSClientConfig: &tls.Config{
Certificates: []tls.Certificate{certs},
InsecureSkipVerify: true,
},
}
http2.ConfigureTransport(tr)
client := &http.Client{
Transport: tr,
}
// Make a GigaByte of data
raw := strings.Repeat("A", 1024*1024*1024)
log.Printf("len(data)=%v\n", len(raw))
sr := strings.NewReader(raw)
req, err := http.NewRequest("POST", serverURL, sr)
if err != nil {
log.Fatal(err)
}
log.Printf("client.Do next\n")
res, err := client.Do(req)
log.Printf("client.Do done\n")
if err != nil {
log.Fatal(err)
}
n, err := io.Copy(ioutil.Discard, res.Body)
log.Printf("done Reading the server response's body n=(%v) err=%v\nres.headers: %v\n", n, err, res.Header)
_ = res.Body.Close()
}
package main
import (
"io"
"io/ioutil"
"log"
"net/http"
"strings"
"time"
)
func handler(w http.ResponseWriter, r *http.Request) {
if r.Method == "POST" {
log.Printf("Received post request whose Headers are %v", r.Header)
if false {
io.Copy(ioutil.Discard, r.Body)
}
err := r.Body.Close()
log.Printf("req.Body.Close() here, err=%v\n", err)
if false {
time.Sleep(700 * time.Millisecond)
}
//http.Error(w, error, code)
w.WriteHeader(413)
b, err := io.Copy(w, strings.NewReader(strings.Repeat("XXXXXX", 4192)))
log.Printf("Wrote %d bytes. Error: %v", b, err)
return
}
w.Header().Set("Content-Type", "text/html")
w.Write([]byte(`
<body>
<script type="text/javascript" src="https://cdnjs.cloudflare.com/ajax/libs/jquery/3.0.0-beta1/jquery.min.js"></script>
<script>
var reqs = 1;
$('body').text('Sending ' + reqs + ' requests...');
function send(i) {
var el = $('<div class="req">Waiting...</div>').attr('id', i).appendTo('body');
var data = new FormData();
data.append('file', new File([new Blob([new Array(5 * 1024 * 1024).join('0')], {type: 'image/jpeg'})], 'test.jpg'));
var done = false;
var req = new XMLHttpRequest();
req.upload.onprogress = function(e) {
if (!e.lengthComputable || done) return;
el.text((e.loaded / e.total * 100) + '%');
}
req.onreadystatechange = function(e) {
if (done || req.readyState !== 3) return;
done = true;
el.text('Done. Got ' + req.status);
}
req.open('POST', '/', true);
req.send(data);
}
for (var i = 0; i < reqs; i++)
send(i);
</script>
</body>
`))
}
func main() {
http.HandleFunc("/", handler)
if err := http.ListenAndServeTLS(":1333", "key.crt", "key.key", nil); err != nil {
log.Fatal(err)
}
}However, running it on my local network and debugging http2 gives
$ GODEBUG=http2debug=1 go run server.go
2016/04/24 22:50:30 http2: server connection from [::1]:53481 on 0xc820088200
2016/04/24 22:50:30 http2: server: client [::1]:53481 said hello
2016/04/24 22:50:30 http2: server read frame SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2016/04/24 22:50:30 http2: server processing setting [ENABLE_PUSH = 0]
2016/04/24 22:50:30 http2: server processing setting [INITIAL_WINDOW_SIZE = 4194304]
2016/04/24 22:50:30 http2: server processing setting [MAX_HEADER_LIST_SIZE = 10485760]
2016/04/24 22:50:30 http2: server read frame WINDOW_UPDATE len=4 (conn) incr=1073741824
2016/04/24 22:50:30 http2: server read frame SETTINGS flags=ACK len=0
2016/04/24 22:50:30 http2: server read frame HEADERS flags=END_HEADERS stream=1 len=44
2016/04/24 22:50:30 Received post request whose Headers are map[Content-Length:[1073741824] Accept-Encoding:[gzip] User-Agent:[Go-http-client/2.0]]
2016/04/24 22:50:30 req.Body.Close() here, err=<nil>
2016/04/24 22:50:30 http2: server encoding header ":status" = "413"
2016/04/24 22:50:30 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2016/04/24 22:50:30 http2: server encoding header "date" = "Mon, 25 Apr 2016 05:50:30 GMT"
2016/04/24 22:50:30 Wrote 25152 bytes. Error: <nil>
2016/04/24 22:50:30 http2: server read frame DATA stream=1 len=65535 data="AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA" (65279 bytes omitted)
2016/04/24 22:50:30 http2: server read frame WINDOW_UPDATE stream=1 len=4 incr=12288
2016/04/24 22:50:30 http2: server read frame WINDOW_UPDATE stream=1 len=4 incr=12864and the client when run $ go run client.go
2016/04/24 22:56:28 len(data)=1073741824
2016/04/24 22:56:28 client.Do next
2016/04/24 22:56:28 client.Do done
2016/04/24 22:56:28 done Reading the server response's body n=(25152) err=<nil>
res.headers: map[Content-Type:[text/plain; charset=utf-8] Date:[Mon, 25 Apr 2016 05:56:28 GMT]]only the first 65535 of the client's Body are consumed in the HTTP2 server, res.Body.Close is successful and it writes out the response to the client asap. Maybe am missing something? |
|
In Go 1.6, I tested your client and server code and it works, but doesn't exhibit the same behavior the Chrome & Firefox seem to have. However, Chrome 49.0.2623.112 still exhibits the erroneous behavior when Chrome makes the post request (via JS). Here is the output of server.go, from a Chrome client (go 1.6): Does the request succeed with Chrome, when the script is compiled with go tip? I can try building tip and testing the code again. |
|
@nemothekid that's because in your Javascript you are trying to use an incompatible feature if (!e.lengthComputable || done) return;ProgressEvent.lengthComputable of which ProgressEvents are not supported in Chrome Also a quick examination of the console in Chrome gives It however works in Firefox which supports ProgressEvents This isn't a bug in Go, but a case of browser incompatibility. |
|
I don't think this has anything to do with a progress event in JavaScript... And I'm certain that MDN is wrong. Especially as it says it's supported in the Chrome documentation |
|
e.lengthComputable is always false for me in Chrome 49.0.2623.112 - I'm not sure its supported. Secondly, I just tried it for myself, and Im' not sure that part of the JS is relevant. If you remove the entire
It should fail with status code 413, entity too large. Chrome doesn't get any data back. |
|
^this. Even if it wasn't supported then it wouldn't return an error like that. |
|
If it was a problem with As all the numbers would be 0%, and it still doesn't explain the connection hanging in both Chrome and Firefox. But there definitely is something fishy going on with the browsers, too, I agree. Just strange that more than Chrome has had the issue. Interestingly, in my testing, using HTTPS vs. HTTP affected the results. |
|
|
|
|
|
Ignore my last 2 posts, I just ended up discovering #15444. When I fix the WriteHeaderFrame function to account for StreamDep=0, the code works.
|
|
I think in this case, my original assessment at caddyserver/caddy#782 (comment) may have been right. I'm pretty sure its data race, as I'm having a really hard to time writing a script that will set the conditions just right (even though it always occurs in Chrome). Using https://github.com/golang/net/tree/master/http2 @ b797637b7aeeed133049c7281bfa31dcc9ca42d6
Kinda sort have a diagram: It looks like the issue here is the |
|
Great work! The results are really interesting but, where do we go from here? |
|
I was able to craft a script that mimics Chrome's behavior - https://gist.github.com/nemothekid/753ca2db95faaa6fd0395fe857b36c21 EDIT: The script is racy :/ sometimes it reliably fails, sometimes it succeeds :/ (or it might just succeed the first time, and fail every other time). Now its just fixing the http2 code in Go. |
|
So I was able to conceptualize a quick hack/fix for this issue that fixes the issue in my script here nemosupremo/net@ad5c348 that just pretty much ignores While this fixes the script, it doesn't fix the request in Chrome. This is a wireshark output (decode port 1333 as SSL and use the session keys provided, see https://blog.cloudflare.com/tools-for-debugging-testing-and-using-http-2/). AFAICT nothing in the communication violates the spec, so I'm guessing Chrome's internal state machine is fucked? I've opened an issue with Chromium here - https://bugs.chromium.org/p/chromium/issues/detail?id=606990 |
|
Is there any other workaround than consuming the request body in the handler using ioutil.Discard? In error cases and a large body this has an undesirable effect, doable until the fix though if there is no workaround. Thanks! |
|
@nemothekid, thanks for all the analysis so far, but I'm a bit overwhelmed with all of it (and with other Go 1.7 bugs in general). What is the summary at this point? If there's something to fix on Go's side, I have approximately 24 hours to do so before I disappear for a month, and at that point fixing it for Go 1.7 will almost certainly be too late. Is your comment at #15425 (comment) still the latest summary? It's not clear what's that's doing, or why. And is there a server component that's necessary to reproduce it? Can you make a stand-alone repro using httptest.NewServer? |
|
Sorry for leaving this bug report in such a sorry state. I looked into submitting a patch to net/http2, and got a bit overwhelmed/intimidated ¯_(ツ)_/¯.
Point 2. can only be fixed in Chrome (the issue was brought up by the nginx team). Here is a script using httptest.NewServer that reproduces point 1. https://gist.github.com/nemothekid/35a3edcf332a20225c725696c0e40e70 Note that the request should succeed, but currently fails. A possible work around I developed as to never close the underlying pipe in |
|
What is that repro (https://gist.github.com/nemothekid/35a3edcf332a20225c725696c0e40e70) trying to show? There's a bunch of weird stuff in it:
Here's a modified version of your repro, if it still shows what you were trying to show: ? package main
import (
"crypto/tls"
"io"
"io/ioutil"
"log"
"net/http"
"net/http/httptest"
"golang.org/x/net/http2"
)
type neverEnding byte
func (b neverEnding) Read(p []byte) (int, error) {
for i := range p {
p[i] = byte(b)
}
return len(p), nil
}
func main() {
ts := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
r.Body.Close()
log.Printf("Http: %s", r.Proto)
io.Copy(w, io.LimitReader(neverEnding('A'), 1024*1024*1024))
}))
http2.ConfigureServer(ts.Config, &http2.Server{})
ts.TLS = ts.Config.TLSConfig
ts.StartTLS()
defer ts.Close()
tr := &http.Transport{TLSClientConfig: &tls.Config{
InsecureSkipVerify: true,
}}
http2.ConfigureTransport(tr)
client := &http.Client{
Transport: tr,
}
req, err := http.NewRequest("POST", ts.URL, struct{ io.Reader }{io.LimitReader(neverEnding('A'), 2048)})
if err != nil {
log.Fatal(err)
}
for i := 0; i < 2; i++ { // racy?
log.Printf("client.Do next\n")
res, err := client.Do(req)
log.Printf("client.Do done\n")
if err != nil {
log.Fatalf("i=%d, Do = %v", i, err)
}
n, err := io.Copy(ioutil.Discard, res.Body)
log.Printf("done Reading the server response's body n=(%v) err=%v\nres.headers: %v\n", n, err, res.Header)
_ = res.Body.Close()
}
}Is this what you were seeing: ? |
|
I have a fix, diff --git a/http2/server.go b/http2/server.go
index 57c8276..4e07a20 100644
--- a/http2/server.go
+++ b/http2/server.go
@@ -1833,7 +1833,7 @@ type requestBody struct {
func (b *requestBody) Close() error {
if b.pipe != nil {
- b.pipe.CloseWithError(errClosedBody)
+ b.pipe.BreakWithError(errClosedBody)
}
b.closed = true
return nil... but I notice that while it fixes it, the Transport is observed to be leaking goroutines, blocked on flow control tokens from the server, even after the stream is dead: So I need to fix that first, and also add a test. |
To expand on point 3, I think the issue is (and referring back to my diagram) is that while the window can still be filled, |
|
In my code, nothing is infinite. I wrapped all the infinite readers in LimitReaders. But this way the program doesn't consume gigabytes of RAM and crash due to my dev VM's small size. I'm a little confused by your analysis still. What would be most helpful if I'm going to be able to fix this in the next few hours is if you can provide a version of your repro which doesn't allocate 2GB of memory and still demonstrates the problem. Make it loop more than 2 times, and have it crash if it gets an unexpected result, making it clear in the failure message or code what it's expecting. That is, I want to see the high level use case fail. I can diagnose the HTTP/2-level problems. But it's hard for me to work the other way, with speculation on the HTTP/2-level problem and trying to guess the use case. If you can comment on whether my patch above makes this better or worse (or completely fixes your case), that would be great too. Thanks. |
|
Sorry for the terrible state of this bug report. It's one of those things that while trying to find the bug I modified a bunch of different values - but didn't work backwards to really isolate what caused the issue. This script uses much less memory, but reliably (on my system) fails. (Smaller values can succeed sometimes). https://gist.github.com/nemothekid/fad888179a061a0e3cd80d191a407b9f The reason I have it loop is because I think the issue is racy. I'm going to continue to see if I can further isolate the issue. |
|
Even the values I provided are a bit racy - I run the program here twice and get two different results (one where it succeeds twice, but then fails the first time). NemoPro:Desktop nimi$ go run ./httptest2.go
2016/05/20 11:07:14 len(data)=256
2016/05/20 11:07:14 client.Do next
2016/05/20 11:07:14 Http: HTTP/2.0
2016/05/20 11:07:14 client.Do done
2016/05/20 11:07:14 done Reading the server response's body n=(4) err=<nil>
res.headers: map[Content-Type:[text/plain; charset=utf-8] Content-Length:[4] Date:[Fri, 20 May 2016 18:07:14 GMT]]
2016/05/20 11:07:14 client.Do next
2016/05/20 11:07:14 Http: HTTP/2.0
2016/05/20 11:07:14 client.Do done
2016/05/20 11:07:14 done Reading the server response's body n=(4) err=<nil>
res.headers: map[Content-Type:[text/plain; charset=utf-8] Content-Length:[4] Date:[Fri, 20 May 2016 18:07:14 GMT]]
NemoPro:Desktop nimi$ go run ./httptest2.go
2016/05/20 11:07:16 len(data)=256
2016/05/20 11:07:16 client.Do next
2016/05/20 11:07:16 Http: HTTP/2.0
2016/05/20 11:07:16 client.Do done
2016/05/20 11:07:16 Post https://127.0.0.1:61011: stream error: stream ID 1; STREAM_CLOSED
exit status 1 |
I think you pasted the wrong file. That has tiny values and seems to work all the time. Please provide a script which reliably fails. Make the loop iteration count high enough to make it eventually fail (not 2, more like 1000 or whatever). And make the script fail with log.Fatal when the behavior isn't as expected. That is, check the result of io.Copy, and don't just log it. |
|
Your patch looks fixes the issue (it no longer occurs on the small & large memory case). I've also modified the test to better reflect what the real use case is - https://gist.github.com/nemothekid/be66f5b4521fbe48cf775a18783ea7d7 - this is when the server sees the request is too large, and refuses to read it (again, it passes it with your patch, but not with This uses values large enough to fail reliably for me, but not use a huge amount of memory. Note that where I have the Also, with that same script I am using:
|
|
I thought it may have been the fact that I was on a mac as well, and it seems I can't reproduce the issue on single core machines. I tried on a couple of our linux boxes: NemoPro:Desktop nimi$ GOOS=linux go build ./httptest2.go
NemoPro:Desktop nimi$ scp httptest2 redis1: && scp httptest2 dev1:
httptest2 100% 8587KB 8.4MB/s 00:01
httptest2 100% 8587KB 4.2MB/s 00:02
NemoPro:Desktop nimi$ ssh redis1
Welcome to Ubuntu 12.04.2 LTS (GNU/Linux 3.13.0-44-generic x86_64)
root@redis1:~# nproc
16
root@redis1:~# ./httptest2
2016/05/20 18:35:29 len(data)=65537
2016/05/20 18:35:29 client.Do next
2016/05/20 18:35:29 Http: HTTP/2.0
2016/05/20 18:35:29 client.Do done
2016/05/20 18:35:29 Expected Status Code 413, Got status code: 0, error: Post https://127.0.0.1:60051: stream error: stream ID 1; STREAM_CLOSED
root@redis1:~# exit
logout
Connection to redis1 closed.
NemoPro:Desktop nimi$ ssh dev1
Welcome to Ubuntu 12.04.2 LTS (GNU/Linux 3.13.0-44-generic x86_64)
nimi@dev1:~$ nproc
1
nimi@dev1:~$ ./httptest2
2016/05/20 18:35:36 len(data)=65537
2016/05/20 18:35:36 client.Do next
2016/05/20 18:35:36 Http: HTTP/2.0
2016/05/20 18:35:36 client.Do done
2016/05/20 18:35:36 done Reading the server response's body n=(4) err=<nil>
res.headers: map[Date:[Fri, 20 May 2016 18:35:36 GMT] Content-Type:[text/plain; charset=utf-8] Content-Length:[4]]
2016/05/20 18:35:36 client.Do next
2016/05/20 18:35:36 Http: HTTP/2.0
2016/05/20 18:35:36 client.Do done
2016/05/20 18:35:36 done Reading the server response's body n=(4) err=<nil>
res.headers: map[Content-Type:[text/plain; charset=utf-8] Content-Length:[4] Date:[Fri, 20 May 2016 18:35:36 GMT]] |
|
I've sent a fix for review: https://golang.org/cl/23287 |
|
CL https://golang.org/cl/23287 mentions this issue. |
Also, fix a Transport goroutine leak if the transport is still trying to write its body after the stream has completed. Updates golang/go#15425 (fixes after bundle into std) Change-Id: Id14d9360d012f53a963ec1999ef88fc592978b80 Reviewed-on: https://go-review.googlesource.com/23287 Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
|
CL https://golang.org/cl/23301 mentions this issue. |
|
Am I correct that to get this fix we must use 1.7? If I am doing something like and have vendored in the http2 package, I still won't get it right? It would be useful to have in the docs a blurb about how using any of the http2 package directly and the bundled http2 in the http package works. |
|
@Gaillard Please open a separate issue for the doc request. Unfortunately I do not know the answer myself. |
|
@ianlancetaylor opened #16412 |
1. What version of Go are you using (
go version)?go version go1.6 darwin/amd642. What operating system and processor architecture are you using (
go env)?OS X El Capitan 10.11.13. What did you do?
Initiate a POST request with a large body. Ignore the request (and/or also Close the request body). The golang http/2 server will not send the response body back to the client. In cases where the request Body is closed, Chrome and other browsers get an error in the connection (
net::ERR_SPDY_PROTOCOL_ERROR)See https://gist.github.com/nemothekid/c20921999d1cce1b3c982d035d6b09b5
This program will server a javascript application that will try to issue a POST request with some data to the server. When run, the POST request will fail.
4. What did you expect to see?
POST request should succeed, the browser should be able to retrieve the server's message body.
5. What did you see instead?
The POST request fails, and the body is never sent by the server. The works fine in HTTP/1.1 (Tested with
GODEBUG=http2server=0). I discovered this issue while trying to debug caddyserver/caddy#782, where an upstream proxy server was rejecting the body. Also this issue would occur on servers that decide to refuse a payload above a specific size and need to respond with a sensible error message.The text was updated successfully, but these errors were encountered: