Log successful /health requests at Trace lvl

Adds `STEP_LOGGER_ONLY_TRACE_HEALTH_ENDPOINT` environment variable to
opt-in to only logging successful /health requests at the Trace level

Fixes #420

Signed-off-by: Dominic Evans <dominic.evans@uk.ibm.com>

logging/handler.go

@@ -3,6 +3,8 @@ package logging
 import (
 	"net"
 	"net/http"
+	"os"
+	"strconv"
 	"time"
 
 	"github.com/sirupsen/logrus"
@@ -10,18 +12,31 @@ import (
 
 // LoggerHandler creates a logger handler
 type LoggerHandler struct {
-	name   string
+	name    string
-	logger *logrus.Logger
+	logger  *logrus.Logger
-	next   http.Handler
+	options options
+	next    http.Handler
+}
+
+// options encapsulates any overriding parameters for the logger handler
+type options struct {
+	// onlyTraceHealthEndpoint determines if the kube-probe requests to the /health
+	// endpoint should only be logged at the TRACE level in the (expected) HTTP
+	// 200 case
+	onlyTraceHealthEndpoint bool
 }
 
 // NewLoggerHandler returns the given http.Handler with the logger integrated.
 func NewLoggerHandler(name string, logger *Logger, next http.Handler) http.Handler {
 	h := RequestID(logger.GetTraceHeader())
+	onlyTraceHealthEndpoint, _ := strconv.ParseBool(os.Getenv("STEP_LOGGER_ONLY_TRACE_HEALTH_ENDPOINT"))
 	return h(&LoggerHandler{
 		name:   name,
 		logger: logger.GetImpl(),
-		next:   next,
+		options: options{
+			onlyTraceHealthEndpoint: onlyTraceHealthEndpoint,
+		},
+		next: next,
 	})
 }
 
@@ -91,7 +106,11 @@ func (l *LoggerHandler) writeEntry(w ResponseLogger, r *http.Request, t time.Tim
 
 	switch {
 	case status < http.StatusBadRequest:
-		l.logger.WithFields(fields).Info()
+		if l.options.onlyTraceHealthEndpoint && uri == "/health" {
+			l.logger.WithFields(fields).Trace()
+		} else {
+			l.logger.WithFields(fields).Info()
+		}
 	case status < http.StatusInternalServerError:
 		l.logger.WithFields(fields).Warn()
 	default:

logging/handler_test.go

@@ -0,0 +1,145 @@
+package logging
+
+import (
+	"fmt"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/smallstep/assert"
+
+	"github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/test"
+)
+
+// TestHealthOKHandling ensures that http requests from the Kubernetes
+// liveness/readiness probes are only logged at Trace level if they are HTTP
+// 200 (which is normal operation) and the user has opted-in. If the user has
+// not opted-in then they continue to be logged at Info level.
+func TestHealthOKHandling(t *testing.T) {
+	statusHandler := func(statusCode int) http.HandlerFunc {
+		return func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(statusCode)
+			fmt.Fprint(w, "{}")
+		}
+	}
+
+	tests := []struct {
+		name    string
+		path    string
+		options options
+		handler http.HandlerFunc
+		want    logrus.Level
+	}{
+		{
+			name:    "200 should be logged at Info level for /health request without explicit opt-in",
+			path:    "/health",
+			handler: statusHandler(http.StatusOK),
+			want:    logrus.InfoLevel,
+		},
+		{
+			name: "200 should be logged only at Trace level for /health request if opt-in",
+			path: "/health",
+			options: options{
+				onlyTraceHealthEndpoint: true,
+			},
+			handler: statusHandler(http.StatusOK),
+			want:    logrus.TraceLevel,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			logger, hook := test.NewNullLogger()
+			logger.SetLevel(logrus.TraceLevel)
+			l := &LoggerHandler{
+				logger:  logger,
+				options: tt.options,
+				next:    tt.handler,
+			}
+
+			r := httptest.NewRequest("GET", tt.path, nil)
+			w := httptest.NewRecorder()
+			l.ServeHTTP(w, r)
+
+			if assert.Equals(t, 1, len(hook.AllEntries())) {
+				assert.Equals(t, tt.want, hook.LastEntry().Level)
+			}
+		})
+	}
+}
+
+// TestHandlingRegardlessOfOptions ensures that http requests are treated like
+// any other request if they are for a non-health uri or fall within the
+// warn/error ranges of the http status codes, regardless of the
+// "onlyTraceHealthEndpoint" option.
+func TestHandlingRegardlessOfOptions(t *testing.T) {
+	statusHandler := func(statusCode int) http.HandlerFunc {
+		return func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(statusCode)
+			fmt.Fprint(w, "{}")
+		}
+	}
+
+	tests := []struct {
+		name    string
+		path    string
+		handler http.HandlerFunc
+		want    logrus.Level
+	}{
+		{
+			name:    "200 should be logged at Info level for non-health requests",
+			path:    "/info",
+			handler: statusHandler(http.StatusOK),
+			want:    logrus.InfoLevel,
+		},
+		{
+			name:    "400 should be logged at Warn level for non-health requests",
+			path:    "/info",
+			handler: statusHandler(http.StatusBadRequest),
+			want:    logrus.WarnLevel,
+		},
+		{
+			name:    "500 should be logged at Error level for non-health requests",
+			path:    "/info",
+			handler: statusHandler(http.StatusInternalServerError),
+			want:    logrus.ErrorLevel,
+		},
+		{
+			name:    "400 should be logged at Warn level even for /health requests",
+			path:    "/health",
+			handler: statusHandler(http.StatusBadRequest),
+			want:    logrus.WarnLevel,
+		},
+		{
+			name:    "500 should be logged at Error level even for /health requests",
+			path:    "/health",
+			handler: statusHandler(http.StatusInternalServerError),
+			want:    logrus.ErrorLevel,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			for _, b := range []bool{true, false} {
+				logger, hook := test.NewNullLogger()
+				logger.SetLevel(logrus.TraceLevel)
+				l := &LoggerHandler{
+					logger: logger,
+					options: options{
+						onlyTraceHealthEndpoint: b,
+					},
+					next: tt.handler,
+				}
+
+				r := httptest.NewRequest("GET", tt.path, nil)
+				w := httptest.NewRecorder()
+				l.ServeHTTP(w, r)
+
+				if assert.Equals(t, 1, len(hook.AllEntries())) {
+					assert.Equals(t, tt.want, hook.LastEntry().Level)
+				}
+			}
+		})
+	}
+}