include received X-Forwarded-For header in access log

log/log.go

@@ -55,6 +55,7 @@ type LogEntry struct {
 	UserAgent       string
 	RequestIDHeader string
 	RequestID       string
+	ForwardedFor    string
 	StatusCode      int
 	ContentLength   int64
 	Err             *ErrEntry
@@ -158,7 +159,7 @@ func (l *Logger) logWriter() {
 			ip = "::ffff:" + ip
 		}
 		fmt.Fprintf(l.writer,
-			"%s - - [%s] \"%s %s %s\" %d %d \"%s\" \"%s\" \"%s:%s\" \"%s\" %0.3f %0.3f\n",
+			"%s - - [%s] \"%s %s %s\" %d %d \"%s\" \"%s\" \"%s:%s\" \"%s\" \"%s\" %0.3f %0.3f\n",
 			ip,
 			nowFormatted,
 			el.Method,
@@ -171,6 +172,7 @@ func (l *Logger) logWriter() {
 			el.RequestIDHeader,
 			el.RequestID,
 			el.BackendKey,
+			el.ForwardedFor,
 			float64(el.TotalDuration)/float64(time.Second),
 			float64(el.BackendDuration)/float64(time.Second),
 		)

log/log_test.go

@@ -42,7 +42,7 @@ func (s *LogSuite) TestNewFileLogger(c *check.C) {
 	logger.Stop()
 	data, err := ioutil.ReadFile(fileName)
 	c.Assert(err, check.IsNil)
-	c.Assert(string(data), check.Equals, "::ffff: - - [01/Jan/0001:00:00:00 +0000] \"  \" 0 0 \"\" \"\" \":\" \"\" 0.000 0.000\n")
+	c.Assert(string(data), check.Equals, "::ffff: - - [01/Jan/0001:00:00:00 +0000] \"  \" 0 0 \"\" \"\" \":\" \"\" \"\" 0.000 0.000\n")
 }
 
 func (s *LogSuite) TestNewSyslogLogger(c *check.C) {
@@ -64,7 +64,7 @@ func (s *LogSuite) TestNewWriterLogger(c *check.C) {
 	logger := NewWriterLogger(nopCloseWriter{buffer})
 	logger.MessageRaw(&LogEntry{})
 	logger.Stop()
-	c.Assert(buffer.String(), check.Equals, "::ffff: - - [01/Jan/0001:00:00:00 +0000] \"  \" 0 0 \"\" \"\" \":\" \"\" 0.000 0.000\n")
+	c.Assert(buffer.String(), check.Equals, "::ffff: - - [01/Jan/0001:00:00:00 +0000] \"  \" 0 0 \"\" \"\" \":\" \"\" \"\" 0.000 0.000\n")
 }
 
 func (s *LogSuite) TestLoggerMessageAfterStop(c *check.C) {
@@ -73,7 +73,7 @@ func (s *LogSuite) TestLoggerMessageAfterStop(c *check.C) {
 	logger.MessageRaw(&LogEntry{})
 	logger.Stop()
 	logger.MessageRaw(&LogEntry{})
-	c.Assert(buffer.String(), check.Equals, "::ffff: - - [01/Jan/0001:00:00:00 +0000] \"  \" 0 0 \"\" \"\" \":\" \"\" 0.000 0.000\n")
+	c.Assert(buffer.String(), check.Equals, "::ffff: - - [01/Jan/0001:00:00:00 +0000] \"  \" 0 0 \"\" \"\" \":\" \"\" \"\" 0.000 0.000\n")
 }
 
 func (s *LogSuite) TestLoggerFull(c *check.C) {
@@ -94,7 +94,7 @@ func (s *LogSuite) TestLoggerFull(c *check.C) {
 	logger.MessageRaw(&LogEntry{})
 	go logger.logWriter()
 	logger.Stop()
-	c.Assert(buffer.String(), check.Equals, `::ffff: - - [01/Jan/0001:00:00:00 +0000] "  " 0 0 "" "" ":" "" 0.000 0.000
+	c.Assert(buffer.String(), check.Equals, `::ffff: - - [01/Jan/0001:00:00:00 +0000] "  " 0 0 "" "" ":" "" "" 0.000 0.000
 Dropping log messages to due to full channel buffer.
 `)
 }

reverseproxy/fasthttp.go

@@ -102,13 +102,6 @@ func (rp *FastReverseProxy) serveWebsocket(dstHost string, reqData *RequestData,
 		reqData.logError(string(uri.Path()), rp.ridString(req), err)
 		return
 	}
-	var clientIP string
-	if clientIP, _, err = net.SplitHostPort(ctx.RemoteAddr().String()); err == nil {
-		if prior := string(req.Header.Peek("X-Forwarded-For")); len(prior) > 0 {
-			clientIP = prior + ", " + clientIP
-		}
-		req.Header.Set("X-Forwarded-For", clientIP)
-	}
 	_, err = req.WriteTo(dstConn)
 	if err != nil {
 		reqData.logError(string(uri.Path()), rp.ridString(req), err)
@@ -173,6 +166,15 @@ func (rp *FastReverseProxy) handler(ctx *fasthttp.RequestCtx) {
 			req.Header.Set(rp.RequestIDHeader, unparsedID.String())
 		}
 	}
+	originalForwardedFor := string(req.Header.Peek("X-Forwarded-For"))
+	var clientIP string
+	var err error
+	if clientIP, _, err = net.SplitHostPort(ctx.RemoteAddr().String()); err == nil {
+		if len(originalForwardedFor) > 0 {
+			clientIP = originalForwardedFor + ", " + clientIP
+		}
+		req.Header.Set("X-Forwarded-For", clientIP)
+	}
 	reqData, dstScheme, dstHost, err := rp.chooseBackend(host)
 	logEntry := func() *log.LogEntry {
 		proto := "HTTP/1.0"
@@ -194,6 +196,7 @@ func (rp *FastReverseProxy) handler(ctx *fasthttp.RequestCtx) {
 			RequestID:       string(req.Header.Peek(rp.RequestIDHeader)),
 			StatusCode:      resp.StatusCode(),
 			ContentLength:   int64(resp.Header.ContentLength()),
+			ForwardedFor:    originalForwardedFor,
 		}
 	}
 	isDebug := len(req.Header.Peek("X-Debug-Router")) > 0

reverseproxy/native.go

@@ -188,6 +188,7 @@ func (rp *NativeReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Reques
 		}
 		return
 	}
+	req.Header["Planb-X-Forwarded-For"] = req.Header["X-Forwarded-For"]
 	rp.rp.ServeHTTP(rw, req)
 }
 
@@ -257,7 +258,7 @@ func (rp *NativeReverseProxy) RoundTrip(req *http.Request) (*http.Response, erro
 	return rp.roundTripWithData(req, reqData, nil), nil
 }
 
-func (rp *NativeReverseProxy) doResponse(req *http.Request, reqData *RequestData, rsp *http.Response, isDebug bool, isDead bool, backendDuration time.Duration) *http.Response {
+func (rp *NativeReverseProxy) doResponse(req *http.Request, reqData *RequestData, rsp *http.Response, isDebug bool, isDead bool, backendDuration time.Duration, originalForwardedFor string) *http.Response {
 	totalDuration := time.Since(reqData.StartTime)
 	logEntry := func() *log.LogEntry {
 		return &log.LogEntry{
@@ -275,6 +276,7 @@ func (rp *NativeReverseProxy) doResponse(req *http.Request, reqData *RequestData
 			RequestID:       fastHeaderGet(req.Header, rp.RequestIDHeader),
 			StatusCode:      rsp.StatusCode,
 			ContentLength:   rsp.ContentLength,
+			ForwardedFor:    originalForwardedFor,
 		}
 	}
 	rsp.Request = req
@@ -301,6 +303,8 @@ func (rp *NativeReverseProxy) doResponse(req *http.Request, reqData *RequestData
 func (rp *NativeReverseProxy) roundTripWithData(req *http.Request, reqData *RequestData, err error) (rsp *http.Response) {
 	isDebug := fastHeaderGet(req.Header, "X-Debug-Router") != ""
 	fastHeaderDel(req.Header, "X-Debug-Router")
+	originalForwardedFor := fastHeaderGet(req.Header, "Planb-X-Forwarded-For")
+	fastHeaderDel(req.Header, "Planb-X-Forwarded-For")
 	if err != nil || req.URL.Scheme == "" || req.URL.Host == "" {
 		switch err {
 		case ErrAllBackendsDead:
@@ -321,7 +325,7 @@ func (rp *NativeReverseProxy) roundTripWithData(req *http.Request, reqData *Requ
 				Body:       emptyResponseBody,
 			}
 		}
-		return rp.doResponse(req, reqData, rsp, isDebug, false, 0)
+		return rp.doResponse(req, reqData, rsp, isDebug, false, 0, originalForwardedFor)
 	}
 	var timedout int32
 	if rp.RequestTimeout > 0 {
@@ -370,7 +374,7 @@ func (rp *NativeReverseProxy) roundTripWithData(req *http.Request, reqData *Requ
 			Body:       emptyResponseBody,
 		}
 	}
-	return rp.doResponse(req, reqData, rsp, isDebug, markAsDead, backendDuration)
+	return rp.doResponse(req, reqData, rsp, isDebug, markAsDead, backendDuration, originalForwardedFor)
 }
 
 func fastHeaderGet(header http.Header, key string) string {

reverseproxy/reverseproxy_test.go

@@ -173,6 +173,76 @@ func (s *S) TestRoundTrip(c *check.C) {
 		RequestIDHeader: "X-RID",
 		StatusCode:      200,
 		ContentLength:   9,
+		ForwardedFor:    "",
+	})
+	c.Assert(router.resultIsDead, check.Equals, false)
+}
+
+func (s *S) TestRoundTripForwarded(c *check.C) {
+	var receivedReq *http.Request
+	ts := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
+		receivedReq = req
+		rw.Header().Set("X-Some-Rsp-Header", "rspvalue")
+		rw.WriteHeader(200)
+		rw.Write([]byte("my result"))
+	}))
+	defer ts.Close()
+	router := &recoderRouter{dst: ts.URL}
+	rp := s.factory()
+	err := rp.Initialize(ReverseProxyConfig{Router: router, RequestIDHeader: "X-RID"})
+	c.Assert(err, check.IsNil)
+	addr, listener := getFreeListener()
+	go rp.Listen(listener)
+	defer rp.Stop()
+	defer listener.Close()
+	req, err := http.NewRequest("GET", fmt.Sprintf("http://%s/", addr), nil)
+	c.Assert(err, check.IsNil)
+	req.Host = "myhost.com"
+	req.Header.Set("X-My-Header", "myvalue")
+	req.Header.Set("X-Forwarded-For", "10.9.8.7")
+	rsp, err := http.DefaultClient.Do(req)
+	c.Assert(err, check.IsNil)
+	defer rsp.Body.Close()
+	c.Assert(rsp.StatusCode, check.Equals, 200)
+	c.Assert(rsp.Header.Get("X-Some-Rsp-Header"), check.Equals, "rspvalue")
+	data, err := ioutil.ReadAll(rsp.Body)
+	c.Assert(err, check.IsNil)
+	c.Assert(string(data), check.Equals, "my result")
+	c.Assert(receivedReq.Host, check.Equals, "myhost.com")
+	c.Assert(receivedReq.Header.Get("X-My-Header"), check.Equals, "myvalue")
+	c.Assert(receivedReq.Header.Get("X-Host"), check.Equals, "")
+	c.Assert(receivedReq.Header.Get("X-Forwarded-Host"), check.Equals, "")
+	c.Assert(receivedReq.Header.Get("X-RID"), check.Not(check.Equals), "")
+	c.Assert(router.resultHost, check.Equals, "myhost.com")
+	c.Assert(router.resultReqData, check.DeepEquals, &RequestData{
+		Backend:    ts.URL,
+		BackendIdx: 0,
+		BackendKey: "myhost.com",
+		BackendLen: 1,
+		Host:       "myhost.com",
+	})
+	le := router.logEntry
+	c.Assert(le.Now.IsZero(), check.Equals, false)
+	c.Assert(le.BackendDuration, check.Not(check.Equals), 0)
+	c.Assert(le.TotalDuration, check.Not(check.Equals), 0)
+	c.Assert(le.RequestID, check.Not(check.Equals), "")
+	c.Assert(le.RemoteAddr, check.Matches, `127\.0\.0\.1:\d+`)
+	le.Now = time.Time{}
+	le.BackendDuration = 0
+	le.TotalDuration = 0
+	le.RequestID = ""
+	le.RemoteAddr = ""
+	c.Assert(le, check.DeepEquals, &log.LogEntry{
+		BackendKey:      "myhost.com",
+		Method:          "GET",
+		Path:            "/",
+		Proto:           "HTTP/1.1",
+		Referer:         "",
+		UserAgent:       "Go-http-client/1.1",
+		RequestIDHeader: "X-RID",
+		StatusCode:      200,
+		ContentLength:   9,
+		ForwardedFor:    "10.9.8.7",
 	})
 	c.Assert(router.resultIsDead, check.Equals, false)
 }

router/router_test.go

@@ -400,7 +400,7 @@ func (s *S) TestEndRequestWithLogFunc(c *check.C) {
 	members := s.redis.SMembers("dead:myfe.com").Val()
 	c.Assert(members, check.DeepEquals, []string{})
 	router.Stop()
-	c.Assert(buf.String(), check.Equals, "::ffff: - - [01/Jan/0001:00:00:00 +0000] \"  \" 0 0 \"\" \"\" \":\" \"\" 0.000 0.000\n")
+	c.Assert(buf.String(), check.Equals, "::ffff: - - [01/Jan/0001:00:00:00 +0000] \"  \" 0 0 \"\" \"\" \":\" \"\" \"\" 0.000 0.000\n")
 }
 
 func (s *S) TestEndRequestWithError(c *check.C) {