Add option for the logging middleware to log real IP (#2002)

This commit adds the option (enabled via environment variable) to the
logging middleware to log real/originating IP address of a client based
on specific headers.

Three headers are supported: True-Client-IP, X-Real-IP, X-Forwarded-For.

This is particularly useful when there is proxy server(s) sitting
between step-ca and client.

Implements #1995

logging/handler.go

@@ -14,6 +14,14 @@ import (
 	"github.com/smallstep/certificates/middleware/requestid"
 )
 
+// Common headers used for identifying the originating IP address of a client
+// connecting to a web server through a proxy server
+var (
+	trueClientIP  = http.CanonicalHeaderKey("True-Client-IP")
+	xRealIP       = http.CanonicalHeaderKey("X-Real-IP")
+	xForwardedFor = http.CanonicalHeaderKey("X-Forwarded-For")
+)
+
 // LoggerHandler creates a logger handler
 type LoggerHandler struct {
 	name    string
@@ -28,16 +36,23 @@ type options struct {
 	// endpoint should only be logged at the TRACE level in the (expected) HTTP
 	// 200 case
 	onlyTraceHealthEndpoint bool
+
+	// logRealIP determines if the real IP address of the client should be logged
+	// instead of the IP address of the proxy
+	logRealIP bool
 }
 
 // NewLoggerHandler returns the given http.Handler with the logger integrated.
 func NewLoggerHandler(name string, logger *Logger, next http.Handler) http.Handler {
 	onlyTraceHealthEndpoint, _ := strconv.ParseBool(os.Getenv("STEP_LOGGER_ONLY_TRACE_HEALTH_ENDPOINT"))
+	logRealIP, _ := strconv.ParseBool(os.Getenv("STEP_LOGGER_LOG_REAL_IP"))
+
 	return &LoggerHandler{
 		name:   name,
 		logger: logger.GetImpl(),
 		options: options{
 			onlyTraceHealthEndpoint: onlyTraceHealthEndpoint,
+			logRealIP:               logRealIP,
 		},
 		next: next,
 	}
@@ -67,9 +82,12 @@ func (l *LoggerHandler) writeEntry(w ResponseLogger, r *http.Request, t time.Tim
 	}
 
 	// Remote hostname
-	addr, _, err := net.SplitHostPort(r.RemoteAddr)
-	if err != nil {
-		addr = r.RemoteAddr
+	addr := r.RemoteAddr
+	if l.options.logRealIP {
+		addr = realIP(r)
+	}
+	if host, _, err := net.SplitHostPort(addr); err == nil {
+		addr = host
 	}
 
 	// From https://github.com/gorilla/handlers
@@ -125,3 +143,27 @@ func sanitizeLogEntry(s string) string {
 	escaped := strings.ReplaceAll(s, "\n", "")
 	return strings.ReplaceAll(escaped, "\r", "")
 }
+
+// realIP returns the real IP address of the client connecting to the server by
+// parsing either the True-Client-IP, X-Real-IP or the X-Forwarded-For headers
+// (in that order). If the headers are not set or set to an invalid IP, it
+// returns the RemoteAddr of the request.
+func realIP(r *http.Request) string {
+	var ip string
+
+	if tcip := r.Header.Get(trueClientIP); tcip != "" {
+		ip = tcip
+	} else if xrip := r.Header.Get(xRealIP); xrip != "" {
+		ip = xrip
+	} else if xff := r.Header.Get(xForwardedFor); xff != "" {
+		i := strings.Index(xff, ",")
+		if i == -1 {
+			i = len(xff)
+		}
+		ip = xff[:i]
+	}
+	if ip == "" || net.ParseIP(ip) == nil {
+		return r.RemoteAddr
+	}
+	return ip
+}

logging/handler_test.go

@@ -143,3 +143,120 @@ func TestHandlingRegardlessOfOptions(t *testing.T) {
 		})
 	}
 }
+
+// TestLogRealIP ensures that the real originating IP is logged instead of the
+// proxy IP when STEP_LOGGER_LOG_REAL_IP is set to true and specific headers are
+// present.
+func TestLogRealIP(t *testing.T) {
+	statusHandler := func(statusCode int) http.HandlerFunc {
+		return func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(statusCode)
+			w.Write([]byte("{}"))
+		}
+	}
+
+	proxyIP := "1.1.1.1"
+
+	tests := []struct {
+		name      string
+		logRealIP string
+		headers   map[string]string
+		expected  string
+	}{
+		{
+			name:      "setting is turned on, no header is set",
+			logRealIP: "true",
+			expected:  "1.1.1.1",
+			headers:   map[string]string{},
+		},
+		{
+			name:      "setting is turned on, True-Client-IP header is set",
+			logRealIP: "true",
+			headers: map[string]string{
+				"True-Client-IP": "2.2.2.2",
+			},
+			expected: "2.2.2.2",
+		},
+		{
+			name:      "setting is turned on, True-Client-IP header is set with invalid value",
+			logRealIP: "true",
+			headers: map[string]string{
+				"True-Client-IP": "a.b.c.d",
+			},
+			expected: "1.1.1.1",
+		},
+		{
+			name:      "setting is turned on, X-Real-IP header is set",
+			logRealIP: "true",
+			headers: map[string]string{
+				"X-Real-IP": "3.3.3.3",
+			},
+			expected: "3.3.3.3",
+		},
+		{
+			name:      "setting is turned on, X-Forwarded-For header is set",
+			logRealIP: "true",
+			headers: map[string]string{
+				"X-Forwarded-For": "4.4.4.4",
+			},
+			expected: "4.4.4.4",
+		},
+		{
+			name:      "setting is turned on, X-Forwarded-For header is set with multiple IPs",
+			logRealIP: "true",
+			headers: map[string]string{
+				"X-Forwarded-For": "4.4.4.4, 5.5.5.5, 6.6.6.6",
+			},
+			expected: "4.4.4.4",
+		},
+		{
+			name:      "setting is turned on, all headers are set",
+			logRealIP: "true",
+			headers: map[string]string{
+				"True-Client-IP":  "2.2.2.2",
+				"X-Real-IP":       "3.3.3.3",
+				"X-Forwarded-For": "4.4.4.4",
+			},
+			expected: "2.2.2.2",
+		},
+		{
+			name:      "setting is turned off, True-Client-IP header is set",
+			logRealIP: "false",
+			expected:  "1.1.1.1",
+			headers: map[string]string{
+				"True-Client-IP": "2.2.2.2",
+			},
+		},
+		{
+			name:      "setting is turned off, no header is set",
+			logRealIP: "false",
+			expected:  "1.1.1.1",
+			headers:   map[string]string{},
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Setenv("STEP_LOGGER_LOG_REAL_IP", tt.logRealIP)
+
+			baseLogger, hook := test.NewNullLogger()
+			logger := &Logger{
+				Logger: baseLogger,
+			}
+			l := NewLoggerHandler("test", logger, statusHandler(http.StatusOK))
+
+			r := httptest.NewRequest("GET", "/test", http.NoBody)
+			r.RemoteAddr = proxyIP
+			for k, v := range tt.headers {
+				r.Header.Set(k, v)
+			}
+			w := httptest.NewRecorder()
+			l.ServeHTTP(w, r)
+
+			if assert.Equals(t, 1, len(hook.AllEntries())) {
+				entry := hook.LastEntry()
+				assert.Equals(t, tt.expected, entry.Data["remote-address"])
+			}
+		})
+	}
+}