diff --git a/logging/handler.go b/logging/handler.go index c59736d9..dd969f89 100644 --- a/logging/handler.go +++ b/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 - logger *logrus.Logger - next http.Handler + name string + logger *logrus.Logger + 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: diff --git a/logging/handler_test.go b/logging/handler_test.go new file mode 100644 index 00000000..6cafc10c --- /dev/null +++ b/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) + } + } + }) + } +}