sort the headers in verbose mode, conditionally log x-forwarded heade…

…rs, only if present

http_logging.go

@@ -19,6 +19,7 @@ import (
 	"fmt"
 	"log"
 	"net/http"
+	"sort"
 	"strings"
 	"time"
 )
@@ -48,6 +49,13 @@ func AppendTLSInfoAttrs(attrs []KeyVal, r *http.Request) []KeyVal {
 	return attrs
 }
 
+func AddIfNotEmpty(attrs []KeyVal, key, value string) []KeyVal {
+	if value != "" {
+		attrs = append(attrs, Str(key, value))
+	}
+	return attrs
+}
+
 // LogRequest logs the incoming request, TLSInfo,
 // including headers when loglevel is verbose.
 // additional key:value pairs can be passed as extraAttributes.
@@ -65,19 +73,27 @@ func LogRequest(r *http.Request, msg string, extraAttributes ...KeyVal) {
 		url = Str("url", r.URL.String())
 	}
 	attr := []KeyVal{
-		Str("method", r.Method), url, Str("proto", r.Proto),
-		Str("remote_addr", r.RemoteAddr), Str("host", r.Host),
-		Str("header.x-forwarded-proto", r.Header.Get("X-Forwarded-Proto")),
-		Str("header.x-forwarded-for", r.Header.Get("X-Forwarded-For")),
-		Str("header.x-forwarded-host", r.Header.Get("X-Forwarded-Host")),
+		Str("method", r.Method), url, Str("host", r.Host),
+		Str("proto", r.Proto), Str("remote_addr", r.RemoteAddr),
 		Str("user-agent", r.Header.Get("User-Agent")),
 	}
+	if !LogVerbose() { // in verbose all headers are already logged
+		attr = AddIfNotEmpty(attr, "header.x-forwarded-proto", r.Header.Get("X-Forwarded-Proto"))
+		attr = AddIfNotEmpty(attr, "header.x-forwarded-for", r.Header.Get("X-Forwarded-For"))
+		attr = AddIfNotEmpty(attr, "header.x-forwarded-host", r.Header.Get("X-Forwarded-Host"))
+	}
 	attr = AppendTLSInfoAttrs(attr, r)
 	attr = append(attr, extraAttributes...)
 	if LogVerbose() {
 		// Host is removed from headers map and put separately
-		for name, headers := range r.Header {
-			attr = append(attr, Str("header."+name, strings.Join(headers, ",")))
+		// Need to sort to get a consistent order
+		keys := make([]string, 0, len(r.Header))
+		for name, _ := range r.Header {
+			keys = append(keys, strings.ToLower(name))
+		}
+		sort.Strings(keys)
+		for _, name := range keys {
+			attr = append(attr, Str("header."+name, strings.Join(r.Header[name], ",")))
 		}
 	}
 	S(Info, msg, attr...)

http_logging_test.go

@@ -17,14 +17,14 @@ import (
 
 // There is additional functional testing in fortio.org/fortio/fhttp.
 func TestLogRequest(t *testing.T) {
-	SetLogLevel(Verbose) // make sure it's already debug when we capture
+	SetLogLevel(Verbose) // make sure it's already verbose when we capture
 	Config.LogFileAndLine = false
 	Config.JSON = true
 	Config.NoTimestamp = true
 	var b bytes.Buffer
 	w := bufio.NewWriter(&b)
 	SetOutput(w)
-	h := http.Header{"foo": []string{"bar1", "bar2"}}
+	h := http.Header{"foo": []string{"bar1", "bar2"}, "X-Forwarded-Host": []string{"foo.fortio.org"}}
 	cert := &x509.Certificate{Subject: pkix.Name{CommonName: "x\nyz"}} // make sure special chars are escaped
 	r := &http.Request{TLS: &tls.ConnectionState{PeerCertificates: []*x509.Certificate{cert}}, Header: h, Host: "foo-host:123"}
 	LogRequest(r, "test1")
@@ -34,8 +34,8 @@ func TestLogRequest(t *testing.T) {
 	w.Flush()
 	actual := b.String()
 	//nolint: lll
-	expected := `{"level":"info","msg":"test1","method":"","url":null,"proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","tls":true,"tls.peer_cn":"x\nyz","header.foo":"bar1,bar2"}
-{"level":"info","msg":"test2","method":"","url":null,"proto":"","remote_addr":"","host":"foo-host:123","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","extra1":"v1","extra2":"v2"}
+	expected := `{"level":"info","msg":"test1","method":"","url":null,"host":"foo-host:123","proto":"","remote_addr":"","user-agent":"","tls":true,"tls.peer_cn":"x\nyz","header.foo":"bar1,bar2","header.x-forwarded-host":""}
+{"level":"info","msg":"test2","method":"","url":null,"host":"foo-host:123","proto":"","remote_addr":"","user-agent":"","extra1":"v1","extra2":"v2"}
 `
 	if actual != expected {
 		t.Errorf("unexpected:\n%s\nvs:\n%s\n", actual, expected)
@@ -80,17 +80,19 @@ func TestLogAndCall(t *testing.T) {
 	Config.JSON = true
 	Config.NoTimestamp = true
 	Config.CombineRequestAndResponse = false // Separate request and response logging
+	SetLogLevelQuiet(Info)
 	var b bytes.Buffer
 	w := bufio.NewWriter(&b)
 	SetOutput(w)
 	hr := &http.Request{}
+	hr.Header = http.Header{"foo": []string{"bar1", "bar2"}, "X-Forwarded-Host": []string{"foo2.fortio.org"}}
 	n := &NullHTTPWriter{}
 	hw := &ResponseRecorder{w: n}
 	LogAndCall("test-log-and-call", testHandler).ServeHTTP(hw, hr)
 	w.Flush()
 	actual := b.String()
 	//nolint: lll
-	expectedPrefix := `{"level":"info","msg":"test-log-and-call","method":"","url":null,"proto":"","remote_addr":"","host":"","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":""}
+	expectedPrefix := `{"level":"info","msg":"test-log-and-call","method":"","url":null,"host":"","proto":"","remote_addr":"","user-agent":"","header.x-forwarded-host":"foo2.fortio.org"}
 {"level":"info","msg":"test-log-and-call","status":200,"size":5,"microsec":1` // the 1 is for the 100ms sleep
 	if !strings.HasPrefix(actual, expectedPrefix) {
 		t.Errorf("unexpected:\n%s\nvs should start with:\n%s\n", actual, expectedPrefix)
@@ -105,7 +107,7 @@ func TestLogAndCall(t *testing.T) {
 	w.Flush()
 	actual = b.String()
 	//nolint: lll
-	expectedPrefix = `{"level":"info","msg":"test-log-and-call2","method":"","url":"/tea","proto":"","remote_addr":"","host":"","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","status":418,"size":5,"microsec":1`
+	expectedPrefix = `{"level":"info","msg":"test-log-and-call2","method":"","url":"/tea","host":"","proto":"","remote_addr":"","user-agent":"","header.x-forwarded-host":"foo2.fortio.org","status":418,"size":5,"microsec":10`
 	if !strings.HasPrefix(actual, expectedPrefix) {
 		t.Errorf("unexpected:\n%s\nvs should start with:\n%s\n", actual, expectedPrefix)
 	}
@@ -114,7 +116,7 @@ func TestLogAndCall(t *testing.T) {
 	LogAndCall("test-log-and-call3", testHandler).ServeHTTP(hw, hr)
 	w.Flush()
 	actual = b.String()
-	expectedFragment := `"user-agent":"","status":500,"size":0,"microsec":1`
+	expectedFragment := `"user-agent":"","header.x-forwarded-host":"foo2.fortio.org","status":500,"size":0,"microsec":1`
 	if !strings.Contains(actual, expectedFragment) {
 		t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment)
 	}