net/http: context cancellation race condition between http.Server, httputil.ReverseProxy and http.Transport

[rgeronimi]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.8.3 linux/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/rgeronimi/sabrina"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build401940531=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

I deployed on port 80 a standard http.Server S, plugged into a standard httputil.ReverseProxy P, reverse proxying traffic through a standard http.Transport T to another standard golang web server S2 in a separate unix process. P is configured to use keep-alive.

What did you expect to see?

When used with any browser, S should behave normally, displaying the full website of S2 correctly.

What did you see instead?

It worked with Safari, Chrome and Firefox. But with torBrowser (vanilla MacOS version 7.0, nothing customized), some page resources where randomly broken with a "502 Bad Gateway" message and an empty content (and the content-length header says 0). Headers and torBrowser logs show nothing special beyond the 502 error.

I also tried with all other browsers (outside of torBrowser) but over the Tor network, and everything works. So the issue is triggered by the torBrowser itself and not by the Tor network.

Only the first (and sometimes second) resource is correctly downloaded, and then all the following ones fail with a 502. This is inconsistent, suggesting a race condition.

Suspecting a keep-alive connection management issue somewhere in the chain, I checked the chronology and it matches perfectly a scenario where a connection C is always deemed "broken" by http.Transport after the first resource request Req1 is answered, compromising all the following resources requests Req2, Req3, ... that were pipelined on that same connection C.
The rare cases where not only 1 resource but 2 resources were correctly received by torBrowser is because there were 2 parallel connections to pipeline the requests on.

I checked the httputil.ReverseProxy source code and saw that it sends back 502 errors when the request context is canceled, which matches the torBrowser status code received.

So I made the hypothesis that, for some reasons:
(1) torBrowser systematically has a specific behavior that pushes the http.Server S to declare the request Req1 "canceled" slightly before T considers its own clone TReq1 of Req1 completed
(2) Consequently T propagates that cancellation to all the following requests TReq2, TReq3, ... that it had pipelined on the same connection C (established between T and S2)
(4) Which forces P to generate the 502 errors on each of their original requests Req2, Req3, ...

To test this hypothesis, I implemented this workaround in the httputil.ReverseProxy.Director to remove the influence of contexts on the reverse proxy P and its transport T:

func director(req *http.Request) {
	quietReq := req.WithContext(context.Background())
	*req = *quietReq
	...other code...
}

This workaround worked perfectly : the bug symptoms disappeared, torBrowser shows the website perfectly.

The part missing is the exact explanation for (1). Tests show that the breakages are inconsistent : sometimes all requests go through correctly. So it looks like a subtle race condition between http.Server, httputil.ReverseProxy and http.Roundtrip

[rgeronimi]

To pinpoint more precisely the origin of the bug and confirm the theory a second time, I created instead a clone library of httputil.ReverseProxy, commenting out line 146 of reverseproxy.go:

	if cn, ok := rw.(http.CloseNotifier); ok {
  		var cancel context.CancelFunc
  		ctx, cancel = context.WithCancel(ctx)
  		defer cancel()
  		notifyChan := cn.CloseNotify()
  		go func() {
  			select {
  			case <-notifyChan:
  				//TODO RACE cancel() <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
  			case <-ctx.Done():
  			}
  		}()
  	}

The race condition disappeared, the site works normally with torBrowser. So the race condition is indeed in the closing order between on one side the completion of the external request (from the external client) and on the other side the completion of the internal request (from the reverse proxy + transport):
in some cases the external request is deemed completed slightly before the internal request (from the reverse proxy and its transport) is deemed completed, triggering a full cancellation of all the other internal requests that were pipelined on the same internal connection.

That race condition is invisible for most browsers but becomes visible with torBrowser, maybe because it has very unusual delay patterns (roundtrips can take up to several seconds) in the overall request/response cycles.

[willmo]

Well the documentation for CloseNotify says:

        // If the protocol is HTTP/1.1 and CloseNotify is called while
        // processing an idempotent request (such a GET) while
        // HTTP/1.1 pipelining is in use, the arrival of a subsequent
        // pipelined request may cause a value to be sent on the
        // returned channel. In practice HTTP/1.1 pipelining is not
        // enabled in browsers and not seen often in the wild. If this
        // is a problem, use HTTP/2 or only use CloseNotify on methods
        // such as POST.

And from googling it looks like Tor Browser enables pipelining by default, and ReverseProxy doesn't check the method when using CloseNotify. So I think ReverseProxy is incompatible with HTTP/1.1 pipelining and therefore with Tor Browser (unless you disable pipelining in Tor Browser or make it use HTTP/2). But you could try to work around this in the Director function like you have.

[bradfitz]

Tor Browser enables pipelining by default? Ouch. Everybody else who's tried that has ended up disabling it. I thought we'd all concluded it was a failed experiment.

Go does support HTTP/1.1 pipelining in general, with the exception of the context cancellation caveat noted above. We considered that acceptable at the time because ~nobody uses pipelining in the wild.

I'm super curious to read the thread where Tor decided to that, if anybody has a link.

[bradfitz]

I'll keep this bug open, but I can't think of a good fix. Ideas welcome.

[rgeronimi]

Maybe a starting point: https://blog.torproject.org/blog/experimental-defense-website-traffic-fingerprinting Envoyé de mon iPhone

…

Le 11 juin 2017 à 04:02, Brad Fitzpatrick ***@***.***> a écrit : I'll keep this bug open, but I can't think of a good fix. Ideas welcome. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.

[rgeronimi]

What are the negative side effects of resolving the CloseNotify caveat? Raphael

…

Le 11 juin 2017 à 04:02, Brad Fitzpatrick ***@***.***> a écrit : I'll keep this bug open, but I can't think of a good fix. Ideas welcome. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#20617 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AC4KehTfBcAP3J3KMwdKc64T5WF3sGN9ks5sC0rPgaJpZM4N0kji>.

[bradfitz]

What are the negative side effects of resolving the CloseNotify caveat?

The drug hasn't even been invented yet, so it's a bit early to be talking about negative side effects.

If you have a proposed fix, I'm all ears.

[bradfitz]

Oh, are you referring to your httputil.ReverseProxy change? That's the wrong place to make the change. That only affects the httputil package, but not anything else that uses net/http.(*Request).Context(). If you only cared about ReverseProxy, that might work.