cc @neild

@mariash Can you try running it with -race to see if there is any race conditions with the code? Thanks

@mauri870 the error I am getting with -race is:

WARNING: DATA RACE
Write at 0x00c0001d2060 by goroutine 27:
  net/http.(*response).Header()
      /usr/local/go/src/net/http/server.go:1094 +0x11d
  net/http/httputil.(*ReverseProxy).ServeHTTP.func2()
      /usr/local/go/src/net/http/httputil/reverseproxy.go:459 +0x54
  net/http.(*persistConn).readResponse()
      /usr/local/go/src/net/http/transport.go:2338 +0x38f
  net/http.(*persistConn).readLoop()
      /usr/local/go/src/net/http/transport.go:2133 +0x59c
  net/http.(*Transport).dialConn.func5()
      /usr/local/go/src/net/http/transport.go:1776 +0x33

Previous write at 0x00c0001d2060 by goroutine 16:
  net/http.(*response).Header()
      /usr/local/go/src/net/http/server.go:1094 +0x11d
  main.main.func4()
      /home/pivotal/workspace/reverseproxy-example-or/server.go:50 +0x6d
  net/http/httputil.(*ReverseProxy).ServeHTTP()
      /usr/local/go/src/net/http/httputil/reverseproxy.go:475 +0x185d
  main.main.main.func2.func6()
      /home/pivotal/workspace/reverseproxy-example-or/server.go:33 +0x17b
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2136 +0x47
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/go/src/net/http/server.go:2514 +0xbc
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2938 +0x2a1
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:2009 +0xc24
  net/http.(*Server).Serve.func3()
      /usr/local/go/src/net/http/server.go:3086 +0x4f

Goroutine 27 (running) created at:
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1776 +0x25d9
  net/http.(*Transport).dialConnFor()
      /usr/local/go/src/net/http/transport.go:1467 +0x129
  net/http.(*Transport).queueForDial.func1()
      /usr/local/go/src/net/http/transport.go:1436 +0x44

Goroutine 16 (running) created at:
  net/http.(*Server).Serve()
      /usr/local/go/src/net/http/server.go:3086 +0x86c
  net/http.(*Server).ListenAndServe()
      /usr/local/go/src/net/http/server.go:2985 +0xbc
  net/http.ListenAndServe()
      /usr/local/go/src/net/http/server.go:3239 +0x124
  main.main.func8()
      /home/pivotal/workspace/reverseproxy-example-or/server.go:56 +0x39

My understanding the first ReadResponse happens in the same goroutine. Subsequent ReadResponse calls are happening in the separate goroutine. Which eventually calls Got1xxResponse. ReverseProxy configures Got1xxResponse to write to Headers map. And then original goroutine modifies headers as well.

My understanding the first ReadResponse happens in the same goroutine. Subsequent ReadResponse calls are happening in the separate goroutine. Which eventually calls Got1xxResponse. ReverseProxy configures Got1xxResponse to write to Headers map. And then original goroutine modifies headers as well.

That's pretty much it. Nice catch! Would you like to send a CL to fix it? Contribution is always welcome! If it's not convenient for you, I can take on it.
@mariash

Change https://go.dev/cl/556037 mentions this issue: net/http/httputil: fix the contention of response header for ReverseProxy

Now I've taken a deeper look at the code, CL 556037 needs more work, still working on it.

Hi @panjf2000 thank you for looking into this.

Looking at CL 556037:
1 . Seems like access to got1xxResponses variable might not be thread-safe.
2. It can be read before Got1xxResponse hook is called which will result in inconsistent behavior.

I feel like there could be couple ways to fix the issue. Ideally, ResponseWriter would be thread-safe, but it returns a Headers map directly and changing this seems to be a complex change.

Second option would be for Transport to wait for read response before returning from RoundTrip, e.g. making sure readLoop is done which seems like what was fixed in writeLoop. This would be great too since it will allow anyone to safely use Got100Continue and Got1xxResponse hooks.

And the last option is to make ReverseProxy itself thread-safe, probably add lock when accessing Header map. But this would mean that custom hooks or ErrorHandler can't use the same ResponseWriter safely.

@mariash Thank you for your analysis and suggestion.

Option 2 does sound like a better idea, I'll try that in CL 556037 and add some tests for it.

Looking at CL 556037:
1 . Seems like access to got1xxResponses variable might not be thread-safe.
2. It can be read before Got1xxResponse hook is called which will result in inconsistent behavior.

One more thing though, I don't quite get your point about this, given that got1xxResponses would only be accessed by Got1xxResponse in readLoop goroutine during RoundTrip, how can it not be thread-safe or be read before Got1xxResponse?

After a deeper look at your code, it seems that the root cause of the data race is the RetryTransport you implemented, it would be no contention if it is removed and let the ReverseProxy use the default transport. Besides, according to the doc of RoundTripper, you shouldn't reuse the request body cuz it will be closed after RoundTrip(). Why did you need the RetryTransport anyway?

This issue now seems a little like a false alert to me.

@mariash

@panjf2000 thank you again for you response! To answer your questions:

One more thing though, I don't quite get your point about this, given that got1xxResponses would only be accessed by Got1xxResponse in readLoop goroutine during RoundTrip, how can it not be thread-safe or be read before Got1xxResponse?

got1xxResponses is written in the readLoop goroutine which started when RoundTrip is called. Since RoundTrip method does not wait for readLoop to finish before returning got1xxResponses is getting read on line 481 of your change which causes 2 goroutines to write/read at the same time.

After a deeper look at your code, it seems that the root cause of the data race is the RetryTransport you implemented, it would be no contention if it is removed and let the ReverseProxy use the default transport. Besides, according to the doc of RoundTripper, you shouldn't reuse the request body cuz it will be closed after RoundTrip(). Why did you need the RetryTransport anyway?

Here the doc states:

Transports should be reused instead of created as needed. Transports are safe for concurrent use by multiple goroutines.

My understanding you can call RoundTrip on the same transport multiple times. This is why I titled this issue: "on subsequent RoundTripper usages".

Anyway, since the issue is in readLoop still running you don't need to reuse RoundTripper to get the error. Here I have an example that uses default Transport and will cause RoundTrip to return earlier than the readLoop by setting ResponseHeaderTimeout. It is harder to get the data race in this case. You need to run this code with -race flag which you can't do in the Golang playground. After running this couple times I am getting the same data race:

WARNING: DATA RACE
Write at 0x00c000290120 by goroutine 14:
  runtime.mapassign_faststr()
      /usr/local/go/src/runtime/map_faststr.go:203 +0x0
  net/textproto.MIMEHeader.Set()
      /usr/local/go/src/net/textproto/header.go:22 +0xde
  net/http.Header.Set()
      /usr/local/go/src/net/http/header.go:40 +0x67
  main.main.func3()
      /home/pivotal/workspace/reverseproxy-example/server.go:44 +0x51
  net/http/httputil.(*ReverseProxy).ServeHTTP()
      /usr/local/go/src/net/http/httputil/reverseproxy.go:477 +0x185d
  main.main.main.func2.func5()
      /home/pivotal/workspace/reverseproxy-example/server.go:29 +0x10b
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2136 +0x47
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/go/src/net/http/server.go:2514 +0xbc
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2938 +0x2a1
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:2009 +0xc24
  net/http.(*Server).Serve.func3()
      /usr/local/go/src/net/http/server.go:3086 +0x4f

Previous read at 0x00c000290120 by goroutine 21:
  runtime.mapiternext()
      /usr/local/go/src/runtime/map.go:867 +0x0
  net/http/httputil.(*ReverseProxy).ServeHTTP.func2()
      /usr/local/go/src/net/http/httputil/reverseproxy.go:465 +0x104
  net/http.(*persistConn).readResponse()
      /usr/local/go/src/net/http/transport.go:2387 +0x4b0
  net/http.(*persistConn).readLoop()
      /usr/local/go/src/net/http/transport.go:2165 +0x6a5
  net/http.(*Transport).dialConn.func5()
      /usr/local/go/src/net/http/transport.go:1793 +0x33

So the problem in that transport.go leaves readLoop goroutine running after RoundTrip is returned in some error cases:

1. When calling RoundTrip readLoop goroutine is started, which calls hooks as part of readResponse like Got100Continue and Got1xxResponse.
2. RoundTrip does not wait for readLoop to finish. There was a fix for it to wait for writeLoop but not the readLoop. readLoop waits for RoundTrip to finish (callerGone channel) but not the other way.
3. That results in the readLoop still running after RoundTrip is returned.
4. In case of ReverseProxy that readLoop modifies headers in the Got1xxResponse and after RoundTrip is finished.

In majority of cases readLoop is executed fast enough. But we are seeing this concurrent map writes sometimes and that results in fatal concurrent map write errors that cannot be recovered and it causes the whole server to crash instead of just one connection failure.

I experimented with transport.go and had a change similar to this one - waiting for readResponse to finish if it is running. It seems to fix the race condition for ReverseProxy.

got1xxResponses is written in the readLoop goroutine which started when RoundTrip is called. Since RoundTrip method does not wait for readLoop to finish before returning got1xxResponses is getting read on line 481 of your change which causes 2 goroutines to write/read at the same time.

If I understand the code correctly, even though the default RoundTrip returns without waiting for readLoop to exit, it does wait for persistConn.readResponse in which Got1xxResponse is called to modify the headers. After RoundTrip returns, it's safe to update headers in the current goroutine while readLoop goroutine is running and it will not go into persistConn.readResponse cuz readLoop will be blocked at:

My understanding you can call RoundTrip on the same transport multiple times. This is why I titled this issue: "on subsequent RoundTripper usages".

You certainly can reuse RoundTrip, it's designed that way. What I was saying is that you shouldn't reuse it with the same request cuz the request body would be closed after RoundTrip returns. As the doc states:

// RoundTrip should not modify the request, except for
// consuming and closing the Request's Body. RoundTrip may
// read fields of the request in a separate goroutine. Callers
// should not mutate or reuse the request until the Response's
// Body has been closed.

When you did so, it resumed the readLoop and it went into persistConn.readResponse again:

As for your new reproducer, it does cause data race, but in a completely different way: you manage to prevent RoundTrip from waiting persistConn.readResponse by setting http.Transport.ResponseHeaderTimeout to a non-zero value and stalling the backend server for the exact same amount of time to respond to a request, which causes RoundTrip to fall into the branch case <-respHeaderTimer instead of case re := <-resc and lead to a early return before persistConn.readResponse is done:

I experimented with transport.go and had a change similar to this one - waiting for readResponse to finish if it is running. It seems to fix the race condition for ReverseProxy.

As I said above, we need to determine whether or not this "issue" should be fixed, if we reckon that this needs a fix eventually, and you're interested in making a contribution for it, please let me know and I'd be happy to close my CL and review yours, new contributors are always welcome.

Thanks again for all the effort on this! @mariash

Change https://go.dev/cl/567216 mentions this issue: net/http/httputil: avoid ReverseProxy data race on 1xx response and error

Thanks for all the nice analysis!

I think this is ultimately a fairly straightforward ReverseProxy bug. (Although replicating it is certainly not straightforward!) ReverseProxy uses a httptrace.ClientTrace.Got1xxResponse hook to process 1xx responses. ClientTrace hooks are documented as not being synchronized with RoundTrip; they can execute in a separate goroutine and may be called after RoundTrip has returned. ReverseProxy doesn't account for that possibility.

https://go.dev/cl/567216 adds some synchronization to ReverseProxy to handle hooks executing after the request has completed. (Which should only be possible in the case of a request failing, for one reason or another.)

https://go.dev/cl/567216 adds some synchronization to ReverseProxy to handle hooks executing after the request has completed. (Which should only be possible in the case of a request failing, for one reason or another.)

I am wondering whether lock should also cover p.getErrorHandler() below:

@neild thank you for your fix. We added similar workaround in our code so now we can remove it.

@AlexanderYastrebov

I am wondering whether lock should also cover p.getErrorHandler() below:

I don't think so, but perhaps I'm missing something?

ResponseWriter allows writing any number of 1xx statuses followed by at most one 2xx-5xx status, so it's fine if the Got1xxResponse hook has called WriteHeader prior to the error handler executing. The mutex and roundTripDone guard prevent a 1xx header from being written concurrently with an error.