Date
1 - 10 of 10
I'm getting different x_forwarded_for in my Gorouter access logs depending on what browser/cli-tool I use.
|
Simon Johansson <simon@...>
Hiya!
Im looking into an issue where the x_forwarded_for have different values depending on what you are using to hit it with. With curl, w3m, lynx x_forwarded_for gets set to "sourceIP, a-gateway-ip" whereas with Firefox, Chrome, Opera, wget x_forwarded_for is simply set to "sourceIP" This is causing confusion but most of all it makes me tear my hair out as I cannot figure out what is going on, from what I can see the issue is not in Gorouter directly but in the stdlib of Golang. I have made two patches to figure out what is going on In the gorouter --- a/proxy/proxy.go +++ b/proxy/proxy.go @@ -2,18 +2,18 @@ package proxy import ( "errors" + "fmt" "io" ) const ( @@ -117,6 +117,8 @@ func (p *proxy) lookup(request *http.Request) *route.Pool { } func (p *proxy) ServeHTTP(responseWriter http.ResponseWriter, request *http.Request) { + fmt.Println("In proxy.ServeHTTP") + fmt.Println("Request: ", request) startedAt := time.Now() accessLog := access_log.AccessLogRecord{ @@ -207,7 +209,9 @@ func (p *proxy) ServeHTTP(responseWriter http.ResponseWriter, request *http.Requ }, } + fmt.Println("X-Forwarded-For before newReverseProxy.ServeHTTP: ", request.Header.Get("X-Forwarded-For")) p.newReverseProxy(roundTripper, request).ServeHTTP(proxyWriter, request) + fmt.Println("X-Forwarded-For after newReverseProxy.ServeHTTP: ", request.Header.Get("X-Forwarded-For")) accessLog.FinishedAt = time.Now() accessLog.BodyBytesSent = proxyWriter.Size() And in golang/src/net/http/httputil/reverseproxy.go --- a/src/net/http/httputil/reverseproxy.go +++ b/src/net/http/httputil/reverseproxy.go @@ -7,6 +7,7 @@ package httputil import ( + "fmt" "io" "log" "net" @@ -101,6 +102,7 @@ var hopHeaders = []string{ } func (p *ReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) { + fmt.Println("In net/http/httputil/reverseproxy.go: ServeHTTP") transport := p.Transport if transport == nil { transport = http.DefaultTransport @@ -132,6 +134,7 @@ func (p *ReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) { } } + fmt.Println("X-Forwarded-For in req before 'If we aren't the first proxy retain prior': ", req.Header.Get("X-Forwarded-For")) if clientIP, _, err := net.SplitHostPort(req.RemoteAddr); err == nil { // If we aren't the first proxy retain prior // X-Forwarded-For information as a comma+space @@ -140,7 +143,9 @@ func (p *ReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) { clientIP = strings.Join(prior, ", ") + ", " + clientIP } outreq.Header.Set("X-Forwarded-For", clientIP) + fmt.Println("X-Forwarded-For in outreq: ", outreq.Header.Get("X-Forwarded-For")) } + fmt.Println("X-Forwarded-For in req after 'If we aren't the first proxy retain prior': ", req.Header.Get("X-Forwarded-For")) res, err := transport.RoundTrip(outreq) if err != nil { @@ -158,6 +163,7 @@ func (p *ReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) { rw.WriteHeader(res.StatusCode) p.copyResponse(rw, res.Body) + fmt.Println("Done in net/http/httputil/reverseproxy.go: ServeHTTP") } So basically debug printing. This is the difference I see (first example with 2 ips in the headers, second example with 1 ip in the headers), both requests from the same machine to the same Gorouter. Logs from gorouter In proxy.ServeHTTP Request: &{GET / HTTP/1.1 1 1 map[Accept:[*/*] Forwarded:[for=172.21.27.221; proto=http] X-Forwarded-Proto:[http] X-Forwarded-For:[172.21.27.221] True_client_ip:[172.21.27.221] X-Cf-Requestid:[874ed33a-c361-4946-74c3-c18b693ade7e] User-Agent:[curl/7.43.0]] 0xbb2730 0 [] false cf-env.test.cf.springer-sbm.com map[] map[] <nil> map[] 10.230.31.8:43597 / <nil>} X-Forwarded-For before newReverseProxy.ServeHTTP: 172.21.27.221 In net/http/httputil/reverseproxy.go: ServeHTTP X-Forwarded-For in req before 'If we aren't the first proxy retain prior': 172.21.27.221 X-Forwarded-For in outreq: 172.21.27.221, 10.230.31.8 X-Forwarded-For in req after 'If we aren't the first proxy retain prior': 172.21.27.221, 10.230.31.8 Done in net/http/httputil/reverseproxy.go: ServeHTTP X-Forwarded-For after newReverseProxy.ServeHTTP: 172.21.27.221, 10.230.31.8 $ cf logs cf-env 2015-08-19T15:11:36.22+0200 [RTR/0] OUT cf-env.test.cf.springer-sbm.com - [19/08/2015:13:11:36 +0000] "GET / HTTP/1.1" 200 0 4155 "-" "curl/7.43.0" 10.230.31.8:43597 x_forwarded_for:"172.21.27.221, 10.230.31.8" vcap_request_id:c2ce64d5-5951-46fb-7b0a-9ea233c34823 response_time:0.011068200 app_id:9011c83a-9407-4e0a-ae91-0c66ff3d6e92 Logs from gorouter In proxy.ServeHTTP Request: &{GET / HTTP/1.1 1 1 map[True_client_ip:[172.21.27.221] X-Cf-Requestid:[d7629a05-cbae-4f13-63d2-43acf5bfe8c9] User-Agent:[Mozilla/5.0 (X11; Linux x86_64; rv:40.0) Gecko/20100101 Firefox/40.0] Accept-Language:[en-US,en;q=0.5] Accept-Encoding:[gzip, deflate] Forwarded:[for=172.21.27.221; proto=http] X-Forwarded-Proto:[http] X-Forwarded-For:[172.21.27.221] Accept:[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8] Cookie:[wt3_eid=%3B846182373400841%7C2141346926300579527%3B532695141032829%7C2142289007300951926%3B929408468507536%7C2142323421600457694%3B987963572816400%7C2142323579400274413%3B595753140200997%7C2142364572200667778%3B754741632944378%7C2142539934000605010] Connection:[keep-alive]] 0xbb2730 0 [] false cf-env.test.cf.springer-sbm.com map[] map[] <nil> map[] 10.230.31.8:43601 / <nil>} X-Forwarded-For before newReverseProxy.ServeHTTP: 172.21.27.221 In net/http/httputil/reverseproxy.go: ServeHTTP X-Forwarded-For in req before 'If we aren't the first proxy retain prior': 172.21.27.221 X-Forwarded-For in outreq: 172.21.27.221, 10.230.31.8 X-Forwarded-For in req after 'If we aren't the first proxy retain prior': 172.21.27.221 Done in net/http/httputil/reverseproxy.go: ServeHTTP X-Forwarded-For after newReverseProxy.ServeHTTP: 172.21.27.221 $ cf logs cf-env 2015-08-19T15:12:16.28+0200 [RTR/0] OUT cf-env.test.cf.springer-sbm.com - [19/08/2015:13:12:16 +0000] "GET / HTTP/1.1" 200 0 4700 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:40.0) Gecko/20100101 Firefox/40.0" 10.230.31.8:43601 x_forwarded_for:"172.21.27.221" vcap_request_id:f807d34a-9191-4a29-5831-cb78eece72e1 response_time:0.008955044 app_id:9011c83a-9407-4e0a-ae91-0c66ff3d6e92 I use Gorouter 212 source and Golang 1.4.2 source. What confuses me is that here(https://github.com/golang/go/blob/release-branch.go1.4/src/net/http/httputil/reverseproxy.go#L110) we set outreq to req, and here(https://github.com/golang/go/blob/release-branch.go1.4/src/net/http/httputil/reverseproxy.go#L142) we set the outreq's X-Forwareded-For headers that affect req's X-Forwareded-For header when using curl/w3m/lynx but not with Firefox/Opera/Chrome/wget Anyone ever seen anything similar or anything obvious I have missed? |
|
|
|
Simon Johansson <simon@...>
Gist of diff:
https://gist.github.com/simonjohansson/847e972f1459ea4cd65e Gist of debug output: https://gist.github.com/simonjohansson/3324b08fc42e5ac7105a Since it's quite hard to read in the email... |
|
|
|
Dieu Cao <dcao@...>
What do you use for your edge load balancer?
You could try to set up your edge load balancer to strip x_forwarded_for sent in the request and set it again before forwarding on. In that way, I believe it should be consistent, whatever the client. -Dieu On Wed, Aug 19, 2015 at 7:38 AM, Simon Johansson <simon(a)simonjohansson.com> wrote: Gist of diff: |
|
|
|
Simon Johansson <simon@...>
Dieu,
We use F5, just tried with the release HAProxy and I get concictent X-Forwarded-For between clients! Dont know how I managed to forget to check that. :) In that way, I believe it should be consistent, whatever the client.So in the HAProxy config the header gets updated/inserted with frontend http-in .... option forwardfor In the HTTP profile in F5 we have " Insert X-Forwarded-For " enabled which is basically the same as the HAProxy config option. No irules to modify the header. But I get different results depending on the client. How curious.... |
|
|
|
Simon Johansson <simon@...>
Disregarding F5/HAProxy comletely and going directly(10.230.18.134) to a Gorouter also yields different results depending on the client.
$ curl -H "host:cf-env.domain.com" 10.230.18.134 $ wget --header=host:cf-env.domain.com -qO- 10.230.18.134 Results in the following gorouter logs cf-env.domain.com - [20/08/2015:13:32:57 +0000] "GET / HTTP/1.1" 200 0 5576 "-" "curl/7.43.0" 172.21.27.221:41193 x_forwarded_for:"172.21.27.221" ... cf-env.domain.com - [20/08/2015:13:35:47 +0000] "GET / HTTP/1.1" 200 0 5655 "-" "Wget/1.16.3 (linux-gnu)" 172.21.27.221:41218 x_forwarded_for:"-" .... I.e when using curl the x_forwarded_for header is set, but when using wget its not. Doing a tcpdump on the gorouter we get these headers for the incoming request. GET / HTTP/1.1 host:cf-env.domain.com User-Agent: curl/7.43.0 Accept: */* GET / HTTP/1.1 User-Agent: Wget/1.16.3 (linux-gnu) Accept: */* Accept-Encoding: identity host: cf-env.domain.com Connection: Keep-Alive As we can see there is two(well, three if you cound User-Agent) differing headers, the wget request have the Accept-Encoding and Connection headers whereas the curl request does not. So, when going directly to a gorouter with curl(that previously set the x_forwarded_for header) and setting the Connection header to Keep-Alive we get this $ curl -H "host:cf-env.domain.com" -H "Connection: Keep-Alive" 10.230.18.134 GET / HTTP/1.1 host:cf-env.domain.com User-Agent: curl/7.43.0 Accept: */* Connection: Keep-Alive cf-env.domain.com - [20/08/2015:13:46:25 +0000] "GET /curl-keep-alive HTTP/1.1" 404 0 18 "-" "curl/7.43.0" 172.21.27.221:41313 x_forwarded_for:"-" ... So, Keep-Alive seems to be the difference between getting x_forwarded_for set or not in this case. Interestingly, when hitting an app with either wget or curl via HAProxy(that both logs x_forwarded_for: sourceIP, HAProxyIP) we can see the headers for the requests on the Gorouter have Connection unset. $ # On my machine $ curl -H "host:cf-env.domain.com" 10.230.18.68/curl $ curl -H "host:cf-env.domain.com" -H "Connection: Keep-Alive" 10.230.18.68/curl-keep-alive-set $ wget --header=host:cf-env.domain.com -qO- 10.230.18.68/wget $ # Tcpdump on HAProxy GET /curl HTTP/1.1 host: cf-env.domain.com User-Agent: curl/7.43.0 Accept: */* GET /curl-keep-alive-set HTTP/1.1 host: cf-env.domain.com User-Agent: curl/7.43.0 Accept: */* Connection: Keep-Alive GET /wget HTTP/1.1 User-Agent: Wget/1.16.3 (linux-gnu) Accept: */* Accept-Encoding: identity host: cf-env.domain.com Connection: Keep-Alive $ # Tcpdump on Gorouter GET /curl HTTP/1.1 User-Agent: curl/7.43.0 Accept: */* host: cf-env.domain.com X-Forwarded-Proto: http X-Forwarded-For: 172.21.27.221 GET /curl-keep-alive-set HTTP/1.1 User-Agent: curl/7.43.0 Accept: */* host: cf-env.domain.com X-Forwarded-Proto: http X-Forwarded-For: 172.21.27.221 GET /wget HTTP/1.1 User-Agent: Wget/1.16.3 (linux-gnu) Accept: */* Accept-Encoding: identity host: cf-env.domain.com X-Forwarded-Proto: http X-Forwarded-For: 172.21.27.221 $ cf logs cf-env cf-env.domain.com - [20/08/2015:14:10:12 +0000] "GET /curl HTTP/1.1" 404 0 18 "-" "curl/7.43.0" 10.230.18.68:60573 x_forwarded_for:"172.21.27.221, 10.230.18.68" ... cf-env.domain.com - [20/08/2015:14:10:17 +0000] "GET /curl-keep-alive-set HTTP/1.1" 404 0 18 "-" "curl/7.43.0" 10.230.18.68:60594 x_forwarded_for:"172.21.27.221, 10.230.18.68" ... cf-env.domain.com - [20/08/2015:14:10:22 +0000] "GET /wget HTTP/1.1" 404 0 18 "-" "Wget/1.16.3 (linux-gnu)" 10.230.18.68:60615 x_forwarded_for:"172.21.27.221, 10.230.18.68" ... So it seems HAProxy is stripping the Connection header before forwarding it to a Gorouter and that is why we dont get different x_forwarded_for ips depending on client whereas we get different when using F5 as it doesnt strip the Connection header. |
|
|
|
Christopher Piraino <cpiraino@...>
Simon,
That is very interesting, nice investigation. I would have to do a little digging to try and see what exactly is going on, but the fact that the GoRouter is not setting the "X-Forwarded-For" header when keep-alive is enabled sounds suspiciously similar to an issue with HaProxy <http://comments.gmane.org/gmane.comp.web.haproxy/5419> where it was only adding the x-forwarded-proto on the first request for a connection. Not sure if this is actually similar though. I took a quick look through golang's reverseproxy code and nothing jumped out at me, I added a story in our backlog <https://www.pivotaltracker.com/story/show/101692478> to investigate further. - Chris Piraino On Thu, Aug 20, 2015 at 7:20 AM, Simon Johansson <simon(a)simonjohansson.com> wrote: Disregarding F5/HAProxy comletely and going directly(10.230.18.134) to a |
|
|
|
Simon Johansson <simon@...>
Chris, I now know why this is happening.
In ServeHTTP in reverseproxy in the httputil package[1] we make a copy of the incoming request for the outgoing request[2]. We then check[3] if the incoming request have any "Hop-by-hop"[4] headers are set. If they are set we assign the outgoing requests headers to a new Header object[5], deep copy all the headers into it from the incoming request and delete the Hop-by-hop headers. After this we update the X-Forwarded-For header[6]. This effectively means that if the incoming request doesn't container any of the hop-by-hop headers we will in step [6] update the incoming requests X-Forwarded-For header as outrec.Header is a reference to rec.Header. But in the case we do have a hop-by-hop header the inrec.Headers, outrec.Headers will not be a reference and thus we get different logs when we enter the defer in gorouter/proxy/proxy.go[7] I have emailed Brad Fitzpatrick who was involved in writing the reverse proxy to see if this is expected behaviour, to me it seems like a bug? [1] https://github.com/golang/go/blob/release-branch.go1.4/src/net/http/httputil/reverseproxy.go [2] https://github.com/golang/go/blob/release-branch.go1.4/src/net/http/httputil/reverseproxy.go#L110 [3] https://github.com/golang/go/blob/release-branch.go1.4/src/net/http/httputil/reverseproxy.go#L125 [4] https://github.com/golang/go/blob/release-branch.go1.4/src/net/http/httputil/reverseproxy.go#L92 [5] https://github.com/golang/go/blob/release-branch.go1.4/src/net/http/httputil/reverseproxy.go#L127 [6] https://github.com/golang/go/blob/release-branch.go1.4/src/net/http/httputil/reverseproxy.go#L142 [7] https://github.com/cloudfoundry/gorouter/blob/master/proxy/proxy.go#L149 On Thu, Aug 20, 2015 at 6:05 PM, Christopher Piraino <cpiraino(a)pivotal.io> wrote: Simon, |
|
|
|
Simon Johansson <simon@...>
I have now asked in golang-nuts[1] . It might take up to 24h for my message to appear, it will be called "Inconsistent X-Forwarded-For when using the httputil.ReverseProxy ?"
[1] https://groups.google.com/forum/#!forum/golang-nuts |
|
|
|
Christopher Piraino <cpiraino@...>
Ah I see the problem. Nice find.
I'll await reply from Golang devs, but I'm wondering how much of a problem this is for you? We could come up with a work around if this was hurting you in some way. - Chris On Fri, Aug 21, 2015 at 3:00 AM, Simon Johansson <simon(a)simonjohansson.com> wrote: I have now asked in golang-nuts[1] . It might take up to 24h for my |
|
|
|
Simon Johansson <simon@...>
https://groups.google.com/forum/#!searchin/golang-nuts/Inconsistent$20X-Forwarded-For/golang-nuts/iUnZgzrOszI/ngxcLbSm1VYJ
Mail thread about the issue at golang-nuts. This is not really a massive issue for us, the main use we have for this is to get the source IP, so whatewher comes after that is not really looked at in our env. This issue is howewher quite confusing and its not obvious why there is inconsistency, I dont know how big of a deal that will be for other deployments. But the easy fix would be to copy setRequestXForwardedFor for proxy and just call it before we call p.accessLogger.Log in the defer in ServeHTTP. |
|
|