Improve logging of http errors (#115)

* Improve http request logging

When logging an http request, e.g. on 500 error, put all the headers
and response on one line.

Also strip cookies and csrf tokens on security grounds.

* Add a test to generate an http error to check formatting

middleware/logging.go

@@ -3,7 +3,6 @@ package middleware
 import (
 	"bytes"
 	"net/http"
-	"net/http/httputil"
 	"time"
 
 	"github.com/weaveworks/common/logging"
@@ -27,7 +26,7 @@ func (l Log) Wrap(next http.Handler) http.Handler {
 		begin := time.Now()
 		uri := r.RequestURI // capture the URI before running next, as it may get rewritten
 		// Log headers before running 'next' in case other interceptors change the data.
-		headers, err := httputil.DumpRequest(r, false)
+		headers, err := dumpRequest(r)
 		if err != nil {
 			headers = nil
 			l.logWithRequest(r).Errorf("Could not dump request headers: %v", err)
@@ -39,14 +38,11 @@ func (l Log) Wrap(next http.Handler) http.Handler {
 		if 100 <= statusCode && statusCode < 500 || statusCode == http.StatusBadGateway || statusCode == http.StatusServiceUnavailable {
 			l.logWithRequest(r).Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
 			if l.LogRequestHeaders && headers != nil {
-				l.logWithRequest(r).Debugf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers))
+				l.logWithRequest(r).Debugf("ws: %v; %s", IsWSHandshakeRequest(r), string(headers))
 			}
 		} else {
-			l.logWithRequest(r).Warnf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
-			if headers != nil {
-				l.logWithRequest(r).Warnf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers))
-			}
-			l.logWithRequest(r).Warnf("Response: %s", buf.Bytes())
+			l.logWithRequest(r).Warnf("%s %s (%d) %s Response: %q ws: %v; %s",
+				r.Method, uri, statusCode, time.Since(begin), buf.Bytes(), IsWSHandshakeRequest(r), headers)
 		}
 	})
 }
@@ -56,3 +52,19 @@ func (l Log) Wrap(next http.Handler) http.Handler {
 var Logging = Log{
 	Log: logging.Global(),
 }
+
+func dumpRequest(req *http.Request) ([]byte, error) {
+	var b bytes.Buffer
+
+	// Exclude some headers for security, or just that we don't need them when debugging
+	err := req.Header.WriteSubset(&b, map[string]bool{
+		"Cookie":       true,
+		"X-Csrf-Token": true,
+	})
+	if err != nil {
+		return nil, err
+	}
+
+	ret := bytes.Replace(b.Bytes(), []byte("\r\n"), []byte("; "), -1)
+	return ret, nil
+}

server/server_test.go

@@ -13,6 +13,8 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/stretchr/testify/require"
 	"github.com/weaveworks/common/httpgrpc"
+	"github.com/weaveworks/common/logging"
+	"github.com/weaveworks/common/middleware"
 	"golang.org/x/net/context"
 )
 
@@ -131,3 +133,28 @@ func TestRunReturnsError(t *testing.T) {
 		require.NotNil(t, <-errChan)
 	})
 }
+
+// Test to see what the logging of a 500 error looks like
+func TestMiddlewareLogging(t *testing.T) {
+	var level logging.Level
+	level.Set("info")
+	cfg := Config{
+		HTTPListenPort:   9192,
+		HTTPMiddleware:   []middleware.Interface{middleware.Logging},
+		MetricsNamespace: "testing_logging",
+		LogLevel:         level,
+	}
+	server, err := New(cfg)
+	require.NoError(t, err)
+
+	server.HTTP.HandleFunc("/error500", func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(500)
+	})
+
+	go server.Run()
+	defer server.Shutdown()
+
+	req, err := http.NewRequest("GET", "http://127.0.0.1:9192/error500", nil)
+	require.NoError(t, err)
+	http.DefaultClient.Do(req)
+}