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?

Join cf-dev@lists.cloudfoundry.org to automatically receive all group messages.