Log request headers, response headers and some body as warning on 500s (

#59)

* Put user/orgID in request log if we have it

* Show request & response headers in logs for 500s

* Only log 500s, not 400s

@bboreham was right

* Don't log headers we don't have

* StatusOK if no explicit `WriteHeader` call

middleware/logging.go

@@ -2,40 +2,54 @@ package middleware
 
 import (
 	"bufio"
+	"bytes"
 	"fmt"
 	"net"
 	"net/http"
 	"net/http/httputil"
 	"time"
 
 	log "github.com/Sirupsen/logrus"
+
+	"github.com/weaveworks/common/user"
 )
 
 // Log middleware logs http requests
 type Log struct {
 	LogRequestHeaders bool // LogRequestHeaders true -> dump http headers at debug log level
 }
 
+// logWithRequest information from the request and context as fields.
+func logWithRequest(r *http.Request) *log.Entry {
+	return log.WithFields(user.LogFields(r.Context()))
+}
+
 // Wrap implements Middleware
 func (l Log) Wrap(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		begin := time.Now()
 		uri := r.RequestURI // capture the URI before running next, as it may get rewritten
-		if l.LogRequestHeaders {
-			// Log headers before running 'next' in case other interceptors change the data.
-			headers, err := httputil.DumpRequest(r, false)
-			if err != nil {
-				log.Warnf("Could not dump request headers: %v", err)
-				return
-			}
-			log.Debugf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers))
+		// Log headers before running 'next' in case other interceptors change the data.
+		headers, err := httputil.DumpRequest(r, false)
+		if err != nil {
+			headers = nil
+			logWithRequest(r).Errorf("Could not dump request headers: %v", err)
 		}
-		i := &interceptor{ResponseWriter: w, statusCode: http.StatusOK}
-		next.ServeHTTP(i, r)
-		if 100 <= i.statusCode && i.statusCode < 400 {
-			log.Debugf("%s %s (%d) %s", r.Method, uri, i.statusCode, time.Since(begin))
+		var buf bytes.Buffer
+		wrapped := newBadResponseLoggingWriter(w, &buf)
+		next.ServeHTTP(wrapped, r)
+		statusCode := wrapped.statusCode
+		if 100 <= statusCode && statusCode < 500 {
+			logWithRequest(r).Debugf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
+			if l.LogRequestHeaders && headers != nil {
+				logWithRequest(r).Debugf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers))
+			}
 		} else {
-			log.Warnf("%s %s (%d) %s", r.Method, uri, i.statusCode, time.Since(begin))
+			logWithRequest(r).Warnf("%s %s (%d) %s", r.Method, uri, statusCode, time.Since(begin))
+			if headers != nil {
+				logWithRequest(r).Warnf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers))
+			}
+			logWithRequest(r).Warnf("Response: %s", buf.Bytes())
 		}
 	})
 }

middleware/response.go

@@ -0,0 +1,82 @@
+package middleware
+
+import (
+	"bufio"
+	"fmt"
+	"io"
+	"net"
+	"net/http"
+)
+
+const (
+	maxResponseBodyInLogs = 4096 // At most 4k bytes from response bodies in our logs.
+)
+
+// badResponseLoggingWriter writes the body of "bad" responses (i.e. 5xx
+// responses) to a buffer.
+type badResponseLoggingWriter struct {
+	rw            http.ResponseWriter
+	buffer        io.Writer
+	logBody       bool
+	bodyBytesLeft int
+	statusCode    int
+}
+
+// newBadResponseLoggingWriter makes a new badResponseLoggingWriter.
+func newBadResponseLoggingWriter(rw http.ResponseWriter, buffer io.Writer) *badResponseLoggingWriter {
+	return &badResponseLoggingWriter{
+		rw:            rw,
+		logBody:       false,
+		bodyBytesLeft: maxResponseBodyInLogs,
+	}
+}
+
+// Header returns the header map that will be sent by WriteHeader.
+// Implements ResponseWriter.
+func (b *badResponseLoggingWriter) Header() http.Header {
+	return b.rw.Header()
+}
+
+// Write writes HTTP response data.
+func (b *badResponseLoggingWriter) Write(data []byte) (int, error) {
+	if b.statusCode == 0 {
+		// WriteHeader has (probably) not been called, so we need to call it with StatusOK to fuflil the interface contract.
+		// https://godoc.org/net/http#ResponseWriter
+		b.WriteHeader(http.StatusOK)
+	}
+	n, err := b.rw.Write(data)
+	if b.logBody {
+		b.captureResponseBody(data)
+	}
+	return n, err
+}
+
+// WriteHeader writes the HTTP response header.
+func (b *badResponseLoggingWriter) WriteHeader(statusCode int) {
+	b.statusCode = statusCode
+	if statusCode >= 500 {
+		b.logBody = true
+	}
+	b.rw.WriteHeader(statusCode)
+}
+
+// Hijack hijacks the first response writer that is a Hijacker.
+func (b *badResponseLoggingWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	hj, ok := b.rw.(http.Hijacker)
+	if ok {
+		return hj.Hijack()
+	}
+	return nil, nil, fmt.Errorf("badResponseLoggingWriter: can't cast underlying response writer to Hijacker")
+}
+
+func (b *badResponseLoggingWriter) captureResponseBody(data []byte) {
+	if len(data) > b.bodyBytesLeft {
+		b.buffer.Write(data[:b.bodyBytesLeft])
+		io.WriteString(b.buffer, "...")
+		b.bodyBytesLeft = 0
+		b.logBody = false
+	} else {
+		b.buffer.Write(data)
+		b.bodyBytesLeft -= len(data)
+	}
+}