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

net/http/httputil: Proxy terminates HTTP/2 stream before reading response body. #16788

Closed
elithrar opened this issue Aug 18, 2016 · 19 comments

Comments

Projects
None yet
3 participants
@elithrar
Copy link

commented Aug 18, 2016

Please answer these questions before submitting your issue. Thanks!

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

go version go1.7 darwin/amd64

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

GOHOSTARCH="amd64"
GOHOSTOS="darwin"

3. What did you do?

  • Running a reverse proxy using https://golang.org/pkg/net/http/httputil/
  • Proxies HTTP on host:port to a target server defined by the -proxy flag.
  • Sending POST data through the proxy (the proxy manipulates CORS headers)

4. What did you expect to see?

  • A HTTP 200 (or other successful status code).

5. What did you see instead?

  • A HTTP 502 and a proxy error due to premature termination of the HTTP/2 stream.
go run simple.go -proxy=https://repeater.getattest.io/post/data -port=8001
curl http://localhost:8001/post/data -d "gophers=yes;"
ts="2016/08/18 06:40:38" msg="http: proxy error: stream error: stream ID 3; STREAM_CLOSED"
ts=2016-08-18T06:40:38-07:00 status=502 method=POST uri=https://repeater.getattest.io/post/data duration=20.74786ms bytes=0 from=127.0.0.1:56479
  • The proxy I'm running (single file): https://gist.github.com/elithrar/a47af11adb818571d364cc5797ce0fb6 - run it, then hit with the curl above. Updated with simpler code
  • The upstream, in this case, is nginx (CloudFlare; HTTP/2), fronting my test server (Go on Heroku HTTP/1.1).
  • Running binaryname -proxy=https://post.workwithgo.com/post/data (Caddy, HTTP/2, proxying the same origin application) and running the same curl does not cause the same error.
  • To be tested: nginx mainline over HTTP/2, which appears to be the last remaining variable.

Note: Disabling HTTP/2 via a custom transport on the upstream leg avoids the issue (as you would expect, given the error). I have yet to test on another HTTP/2 origin (I'll spin up a raw Caddy instance shortly).

@elithrar

This comment has been minimized.

Copy link
Author

commented Aug 18, 2016

(I did run into mholt/caddy#782 + #15425 - but not yet convinced these are the same issue)

@elithrar

This comment has been minimized.

Copy link
Author

commented Aug 18, 2016

Updated issue with additional tests.

@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 18, 2016

Do you have a stand-alone repro which doesn't import external packages, and doesn't wrap the ResponseWriter with your own version?

Also, which side of Go's HTTP/2 support are you reporting problems against? Go's HTTP/2 server or Go's HTTP/2 client? Draw me a little picture of the three entities involved and which protocols are on the two links.

@elithrar

This comment has been minimized.

Copy link
Author

commented Aug 18, 2016

Issue is against Go's HTTP/2 client - e.g. the upstream connection from the reverse proxy to the target.

(Terrible) ASCII diagram:

local client (browser, curl) issues HTTP POST  ---HTTP/1.1---> Go proxy (the gist) running on localhost, designed to rewrite CORS headers ---HTTP/2---> HTTP/2 server (Go or nginx) ---HTTP/1.1|HTTP/2---> (optional backend app to echo the POST)

The issue (termination of the HTTP/2 stream before the response can be written) occurs at this point:

Go proxy (the gist) ---HTTP/2---> HTTP/2 server (Go or nginx) 

Caddy

curl http://localhost:8001/post/data -d "gophers=yes;" -sv

*   Trying ::1...
* connect to ::1 port 8001 failed: Connection refused
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8001 (#0)
> POST /post/data HTTP/1.1
> Host: localhost:8001
> User-Agent: curl/7.50.1
> Accept: */*
> Content-Length: 12
> Content-Type: application/x-www-form-urlencoded
>
* upload completely sent off: 12 out of 12 bytes
< HTTP/1.1 502 Bad Gateway
< Date: Thu, 18 Aug 2016 17:31:33 GMT
< Content-Length: 0
< Content-Type: text/plain; charset=utf-8
<
* Connection #0 to host localhost left intact
go run simple.go -port 8001 -proxy=https://post.workwithgo.com/post/data
2016/08/18 10:29:20 listening on host 127.0.0.1 - port 8001
2016/08/18 10:29:23 POST - https://post.workwithgo.com/post/data - 127.0.0.1:61416
2016/08/18 10:29:23 http: proxy error: stream error: stream ID 1; STREAM_CLOSED

nginx

curl http://localhost:8001/post/data -d "gophers=yes;" -sv

*   Trying ::1...
* connect to ::1 port 8001 failed: Connection refused
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8001 (#0)
> POST /post/data HTTP/1.1
> Host: localhost:8001
> User-Agent: curl/7.50.1
> Accept: */*
> Content-Length: 12
> Content-Type: application/x-www-form-urlencoded
>
* upload completely sent off: 12 out of 12 bytes
< HTTP/1.1 502 Bad Gateway
< Date: Thu, 18 Aug 2016 17:32:34 GMT
< Content-Length: 0
< Content-Type: text/plain; charset=utf-8
<
* Connection #0 to host localhost left intact
go run simple.go -port 8001 -proxy=https://repeater.getattest.io/post/data
2016/08/18 10:32:32 listening on host 127.0.0.1 - port 8001
2016/08/18 10:32:34 POST - https://repeater.getattest.io/post/data - 127.0.0.1:61461
2016/08/18 10:32:34 http: proxy error: stream error: stream ID 1; STREAM_CLOSED

All of those endpoints are live. Hammer as much as you want. The backend application just echoes the request; the same HTTP 502 and premature stream termination occurs when hitting CloudFlare's API via the same proxy (you would require API keys to test that).

@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 18, 2016

Oh, this might be a dup of #16450

Can you remove your ReadTimeout and WriteTimeout and see if the problem goes away? Or make them larger and see if it takes correspondingly long for the problem to repro?

@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 18, 2016

Oh, but you said it's a client problem, not a server problem. Still, if you're connecting to the server with HTTP/2 also and the conn dies, that would cancel the context to the proxy and abort the request there, which might be what you're seeing. Maybe. Worth trying anyway.

@elithrar

This comment has been minimized.

Copy link
Author

commented Aug 18, 2016

Yep, client problem!

Still, removed the Write/Read timeouts from the server-side of the proxy: issue persists, noting that the server-side (listening on localhost) of the proxy is just plaintext HTTP/1.1.

Note: to make this somewhat worse, it appears to be broken ~95% of the time, with ~5% of responses being written.

@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 18, 2016

Can you paste the output of the proxy running with env GODEBUG=http2debug=2 set?

@elithrar

This comment has been minimized.

Copy link
Author

commented Aug 18, 2016

2016/08/18 14:19:22 POST - https://post.workwithgo.com/post/data - 127.0.0.1:65531
2016/08/18 14:19:22 http2: Transport encoding header ":authority" = "post.workwithgo.com"
2016/08/18 14:19:22 http2: Transport encoding header ":method" = "POST"
2016/08/18 14:19:22 http2: Transport encoding header ":path" = "/post/data"
2016/08/18 14:19:22 http2: Transport encoding header ":scheme" = "https"
2016/08/18 14:19:22 http2: Transport encoding header "x-forwarded-for" = "127.0.0.1"
2016/08/18 14:19:22 http2: Transport encoding header "user-agent" = "curl/7.50.1"
2016/08/18 14:19:22 http2: Transport encoding header "accept" = "*/*"
2016/08/18 14:19:22 http2: Transport encoding header "content-type" = "application/x-www-form-urlencoded"
2016/08/18 14:19:22 http2: Transport encoding header "content-length" = "12"
2016/08/18 14:19:22 http2: Transport encoding header "accept-encoding" = "gzip"
2016/08/18 14:19:22 http2: Framer 0xc4200fccc0: wrote HEADERS flags=END_HEADERS stream=13 len=10
2016/08/18 14:19:22 http2: Framer 0xc4200fccc0: wrote DATA flags=END_STREAM stream=13 len=12 data="gophers=yes;"
2016/08/18 14:19:22 http2: Framer 0xc4200fccc0: wrote DATA flags=END_STREAM stream=13 len=0 data=""
2016/08/18 14:19:22 http2: Framer 0xc4200fccc0: read WINDOW_UPDATE len=4 (conn) incr=12
2016/08/18 14:19:22 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=12
2016/08/18 14:19:22 http2: Framer 0xc4200fccc0: read RST_STREAM stream=13 len=4 ErrCode=STREAM_CLOSED
2016/08/18 14:19:22 http2: Transport received RST_STREAM stream=13 len=4 ErrCode=STREAM_CLOSED
2016/08/18 14:19:22 RoundTrip failure: stream error: stream ID 13; STREAM_CLOSED
2016/08/18 14:19:22 http: proxy error: stream error: stream ID 13; STREAM_CLOSED

It looks like the RST_STREAM (from the client) is where we're hung up here. There is a similar issue in #16514 but not concrete (I see the issue regardless of upstream webserver).

@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 18, 2016

Whoa, this is messed up:

2016/08/18 14:19:22 http2: Framer 0xc4200fccc0: wrote DATA flags=END_STREAM stream=13 len=12 data="gophers=yes;"
2016/08/18 14:19:22 http2: Framer 0xc4200fccc0: wrote DATA flags=END_STREAM stream=13 len=0 data=""

Two END_STREAM bits for the same stream ID (13).

No wonder the server on the other side is telling us RST_STREAM. I'm surprised it's not just hanging up on us for a protocol error violation.

(To be clear, because your comment looks backwards, @elithrar: the Go HTTP/2 client appears to be writing bogus frames, and then the server is writing RST_STREAM stream=13 len=4 ErrCode=STREAM_CLOSED, which the proxy's HTTP client then reads.)

@bradfitz bradfitz added this to the Go1.7.1 milestone Aug 18, 2016

@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 18, 2016

@elithrar, this is untested, but can you try out this patch:

diff --git a/src/net/http/h2_bundle.go b/src/net/http/h2_bundle.go
index ffe15f0..00718f6 100644
--- a/src/net/http/h2_bundle.go
+++ b/src/net/http/h2_bundle.go
@@ -5714,8 +5714,12 @@ func (cs *http2clientStream) writeRequestBody(body io.Reader, bodyCloser io.Clos
                }
        }

+       if sentEnd {
+               return nil
+       }
+
        var trls []byte
-       if !sentEnd && hasTrailers {
+       if hasTrailers {
                cc.mu.Lock()
                defer cc.mu.Unlock()
                trls = cc.encodeTrailers(req)
@elithrar

This comment has been minimized.

Copy link
Author

commented Aug 18, 2016

@bradfitz Works for me. Ran a few thousand curls through it with differing data (to detect any transient issues) - no longer seeing the client write bad frames:


2016/08/18 15:34:24 POST - https://post.workwithgo.com/post/data - 127.0.0.1:52280
2016/08/18 15:34:24 http2: Transport encoding header ":authority" = "post.workwithgo.com"
2016/08/18 15:34:24 http2: Transport encoding header ":method" = "POST"
2016/08/18 15:34:24 http2: Transport encoding header ":path" = "/post/data"
2016/08/18 15:34:24 http2: Transport encoding header ":scheme" = "https"
2016/08/18 15:34:24 http2: Transport encoding header "accept" = "*/*"
2016/08/18 15:34:24 http2: Transport encoding header "content-type" = "application/x-www-form-urlencoded"
2016/08/18 15:34:24 http2: Transport encoding header "x-forwarded-for" = "127.0.0.1"
2016/08/18 15:34:24 http2: Transport encoding header "user-agent" = "curl/7.50.1"
2016/08/18 15:34:24 http2: Transport encoding header "content-length" = "64"
2016/08/18 15:34:24 http2: Transport encoding header "accept-encoding" = "gzip"
2016/08/18 15:34:24 http2: Framer 0xc420145740: wrote HEADERS flags=END_HEADERS stream=1077 len=10
2016/08/18 15:34:24 http2: Framer 0xc420145740: wrote DATA flags=END_STREAM stream=1077 len=64 data="e01aaaed5e504ddc2ebcb0107209a0bbbb715376c7d862a61bee8bcd70c43f40"
2016/08/18 15:34:24 http2: Framer 0xc420145740: read WINDOW_UPDATE len=4 (conn) incr=64
2016/08/18 15:34:24 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=64
2016/08/18 15:34:24 http2: Framer 0xc420145740: read HEADERS flags=END_HEADERS stream=1077 len=5
2016/08/18 15:34:24 http2: decoded hpack field header field ":status" = "200"
2016/08/18 15:34:24 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2016/08/18 15:34:24 http2: decoded hpack field header field "date" = "Thu, 18 Aug 2016 22:34:23 GMT"
2016/08/18 15:34:24 http2: decoded hpack field header field "server" = "Caddy"
2016/08/18 15:34:24 http2: decoded hpack field header field "content-length" = "149"
2016/08/18 15:34:24 http2: Transport received HEADERS flags=END_HEADERS stream=1077 len=5
2016/08/18 15:34:24 http2: Framer 0xc420145740: read DATA flags=END_STREAM stream=1077 len=149 data="HTTP status: 200\n🍕🍕🍕🍕🍕🍕🍕🍕🍕🍕\nReceived POST data:\ne01aaaed5e504ddc2ebcb0107209a0bbbb715376c7d862a61bee8bcd70c43f40: [\"\"]\n"
2016/08/18 15:34:24 http2: Transport received DATA flags=END_STREAM stream=1077 len=149 data="HTTP status: 200\n🍕🍕🍕🍕🍕🍕🍕🍕🍕🍕\nReceived POST data:\ne01aaaed5e504ddc2ebcb0107209a0bbbb715376c7d862a61bee8bcd70c43f40: [\"\"]\n"

(I'm also curious as to why others haven't hit this yet, and it doesn't seem unique to my env)

@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 18, 2016

@elithrar, I am also curious about that.

I will investigate more.

I also don't know how this regressed (did it?) or how our end-to-end tests didn't catch it. Very confused.

@elithrar

This comment has been minimized.

Copy link
Author

commented Aug 19, 2016

Simple client.go - sees the same empty write. In this case the HTTP/2 client handles it.

package main

import (
    "fmt"
    "io/ioutil"
    "log"
    "net/http"
    "net/url"
)

func main() {
    resp, err := http.PostForm("https://post.workwithgo.com/post/data",
        url.Values{"key": {"Value"}, "id": {"123"}})
    if err != nil {
        log.Fatal(err)
    }
    defer resp.Body.Close()

    fmt.Println(resp.StatusCode)

    body, err := ioutil.ReadAll(resp.Body)
    if err != nil {
        log.Fatal(err)
    }

    fmt.Println(string(body))
}
2016/08/18 17:26:12 http2: Framer 0xc42043ecc0: wrote DATA stream=1 len=16 data="id=123&key=Value"
2016/08/18 17:26:12 http2: Framer 0xc42043ecc0: wrote DATA flags=END_STREAM stream=1 len=0 data=""
@bradfitz

This comment has been minimized.

Copy link
Member

commented Aug 19, 2016

The empty write isn't the problem. That second DATA frame is conveying useful information: END_STREAM is the "EOF" bit.

The problem above is the duplicate END_STREAM.

@gopherbot

This comment has been minimized.

Copy link

commented Aug 19, 2016

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

@elithrar

This comment has been minimized.

Copy link
Author

commented Aug 19, 2016

Thanks for the patch + very fast CL @bradfitz—hugely appreciated.

gopherbot pushed a commit to golang/net that referenced this issue Aug 19, 2016

http2: fix protocol violation regression when writing certain request…
… bodies

The mod_h2 workaround CL (git rev 28d1bd4,
https://golang.org/cl/25362) introduced a regression where the
Transport could write two DATA frames, both with END_STREAM, if the
Request.Body returned (non-0, io.EOF). strings.Reader, bytes.Reader
are the most common Reader types used with HTTP requests and they only
return (0, io.EOF) so we got generally lucky and things seemed to
work, but other Readers do return (non-0, io.EOF), like the HTTP
transport/server Readers. This is why we broke the HTTP proxy code,
when proxying to HTTP/2.

Updates golang/go#16788 (fixes after it's bundled into std)

Change-Id: I42684017039eacfc27ee53e9c11431f713fdaca4
Reviewed-on: https://go-review.googlesource.com/27406
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Chris Broadfoot <cbro@golang.org>
@gopherbot

This comment has been minimized.

Copy link

commented Aug 20, 2016

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

@gopherbot gopherbot closed this in ec8d49c Aug 22, 2016

gopherbot pushed a commit that referenced this issue Sep 7, 2016

[release-branch.go1.7] net/http: update bundled http2 for Transport d…
…ouble STREAM_ENDED error

Updates bundled http2 to x/net/http2 git rev 7394c11 for:

http2: fix protocol violation regression when writing certain request bodies
https://golang.org/cl/27406

Fixes #16788

Change-Id: I0efcd36e2b4b34a1df79f763d35bf7a3a1858506
Reviewed-on: https://go-review.googlesource.com/27451
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Andrew Gerrand <adg@golang.org>
Reviewed-on: https://go-review.googlesource.com/28636
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
@gopherbot

This comment has been minimized.

Copy link

commented Sep 12, 2016

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

gopherbot pushed a commit to golang/net that referenced this issue Sep 13, 2016

[release-branch.go1.7] http2: fix protocol violation regression when …
…writing certain request bodies

The mod_h2 workaround CL (git rev 28d1bd4,
https://golang.org/cl/25362) introduced a regression where the
Transport could write two DATA frames, both with END_STREAM, if the
Request.Body returned (non-0, io.EOF). strings.Reader, bytes.Reader
are the most common Reader types used with HTTP requests and they only
return (0, io.EOF) so we got generally lucky and things seemed to
work, but other Readers do return (non-0, io.EOF), like the HTTP
transport/server Readers. This is why we broke the HTTP proxy code,
when proxying to HTTP/2.

Updates golang/go#16788 (fixes after it's bundled into std)

Change-Id: I42684017039eacfc27ee53e9c11431f713fdaca4
Reviewed-on: https://go-review.googlesource.com/27406
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Chris Broadfoot <cbro@golang.org>
Reviewed-on: https://go-review.googlesource.com/29080

@golang golang locked and limited conversation to collaborators Sep 12, 2017

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.