Merge pull request #187 from gouthamve/fix-error-logging-http

Log errors when write fails, not 200; requires Go 1.13
weaveworks · May 12, 2020 · 384f100 · 384f100
2 parents c4a9ff7 + 817e953
commit 384f100
Show file tree

Hide file tree

Showing 3 changed files with 98 additions and 1 deletion.
diff --git a/middleware/logging.go b/middleware/logging.go
@@ -2,6 +2,8 @@ package middleware
 
 import (
  "bytes"
+ "context"
+ "errors"
  "net/http"
  "time"
 
@@ -39,7 +41,18 @@ func (l Log) Wrap(next http.Handler) http.Handler {
  var buf bytes.Buffer
  wrapped := newBadResponseLoggingWriter(w, &buf)
  next.ServeHTTP(wrapped, r)
- statusCode := wrapped.statusCode
+
+ statusCode, writeErr := wrapped.statusCode, wrapped.writeError
+
+ if writeErr != nil {
+ if errors.Is(writeErr, context.Canceled) {
+ l.logWithRequest(r).Debugf("%s %s %s, request cancelled: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
+ } else {
+ l.logWithRequest(r).Warnf("%s %s %s, error: %s ws: %v; %s", r.Method, uri, time.Since(begin), writeErr, IsWSHandshakeRequest(r), headers)
+ }
+
+ return
+ }
  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 {

diff --git a/middleware/logging_test.go b/middleware/logging_test.go
@@ -0,0 +1,80 @@
+package middleware
+
+import (
+ "bytes"
+ "context"
+ "errors"
+ "io"
+ "net/http"
+ "net/http/httptest"
+ "testing"
+
+ "github.com/sirupsen/logrus"
+ "github.com/stretchr/testify/require"
+ "github.com/weaveworks/common/logging"
+)
+
+func TestBadWriteLogging(t *testing.T) {
+ for _, tc := range []struct {
+ err error
+ logContains []string
+ }{{
+ err: context.Canceled,
+ logContains: []string{"debug", "request cancelled: context canceled"},
+ }, {
+ err: errors.New("yolo"),
+ logContains: []string{"warning", "error: yolo"},
+ }, {
+ err: nil,
+ logContains: []string{"debug", "GET http://example.com/foo (200)"},
+ }} {
+ buf := bytes.NewBuffer(nil)
+ logrusLogger := logrus.New()
+ logrusLogger.Out = buf
+ logrusLogger.Level = logrus.DebugLevel
+
+ loggingMiddleware := Log{
+ Log: logging.Logrus(logrusLogger),
+ }
+ handler := func(w http.ResponseWriter, r *http.Request) {
+ io.WriteString(w, "<html><body>Hello World!</body></html>")
+ }
+ loggingHandler := loggingMiddleware.Wrap(http.HandlerFunc(handler))
+
+ req := httptest.NewRequest("GET", "http://example.com/foo", nil)
+ recorder := httptest.NewRecorder()
+
+ w := errorWriter{
+ err: tc.err,
+ w: recorder,
+ }
+ loggingHandler.ServeHTTP(w, req)
+
+ for _, content := range tc.logContains {
+ require.True(t, bytes.Contains(buf.Bytes(), []byte(content)))
+ }
+ }
+
+}
+
+type errorWriter struct {
+ err error
+
+ w http.ResponseWriter
+}
+
+func (e errorWriter) Header() http.Header {
+ return e.w.Header()
+}
+
+func (e errorWriter) WriteHeader(statusCode int) {
+ e.w.WriteHeader(statusCode)
+}
+
+func (e errorWriter) Write(b []byte) (int, error) {
+ if e.err != nil {
+ return 0, e.err
+ }
+
+ return e.w.Write(b)
+}
diff --git a/middleware/response.go b/middleware/response.go
@@ -20,6 +20,7 @@ type badResponseLoggingWriter struct {
  logBody bool
  bodyBytesLeft int
  statusCode int
+ writeError error // The error returned when downstream Write() fails.
 }
 
 // newBadResponseLoggingWriter makes a new badResponseLoggingWriter.
@@ -50,6 +51,9 @@ func (b *badResponseLoggingWriter) Write(data []byte) (int, error) {
  if b.logBody {
  b.captureResponseBody(data)
  }
+ if err != nil {
+ b.writeError = err
+ }
  return n, err
 }