feat: allow skipping http loggin per request (#268)

Provide configuration points to allow application to skip logging on
specific requests. Additionally, allow configuration of the log fields
as well.

Signed-off-by: Lucas Roesler <[email protected]>

Author: LucasRoesler

pkg/http/middlewares/logging.go

@@ -2,16 +2,26 @@ package middlewares
 
 import (
 	"net/http"
+	"strings"
 	"time"
 
+	"github.com/go-chi/chi/middleware"
 	"github.com/sirupsen/logrus"
-	"github.com/urfave/negroni"
-
-	server "github.com/contiamo/go-base/v4/pkg/http"
 )
 
 // WithLogging configures a logrus middleware for that server.
 //
+// You can control the log fields or if the log should be skipped by setting
+// the Fields and the Ignore function respectively.
+//
+//      log := middlewares.WithLogging(config.ApplicationName)
+//      log.Fields = func(r *http.Request) logrus.Fields {
+//        // custom logic here
+//      }
+//      log.Ignore = func(r *http.Request) bool {
+// 	      // custom logic here
+//      }
+//
 // When `tracing.SpanHook` is enabled and the tracing middleware is enabled
 // before the logging middleware, the traceId and spanId are attaced the the logs.
 //
@@ -33,30 +43,48 @@ import (
 // 			log.WrapHandler,
 // 			metrics.WrapHandler,
 // 		)
-func WithLogging(app string) server.Option {
-	return &loggingOption{app}
+func WithLogging(app string) *LoggingOption {
+	return &LoggingOption{
+		app: app,
+	}
 }
 
-type loggingOption struct{ app string }
+type LoggingOption struct {
+	app string
+	// Ignore determines if the log should be skipped for the given request.
+	//
+	// When nil, the default logic is used, which ignores requests in which the
+	// User-Agent contains: "healthcheck" or "kube-probe".
+	Ignore func(r *http.Request) bool
+	// Fields extracts log fields from the given trequest to include in the log entry.
+	//
+	// When nil, the default logic is used, which includes the request method and path.
+	Fields func(r *http.Request) logrus.Fields
+}
+
+func (opt *LoggingOption) WrapHandler(handler http.Handler) http.Handler {
+	ignore := opt.Ignore
+	if ignore == nil {
+		ignore = defaultIgnore
+	}
 
-func (opt *loggingOption) WrapHandler(handler http.Handler) http.Handler {
+	fields := opt.Fields
+	if fields == nil {
+		fields = defaultFields
+	}
 	h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		start := time.Now()
-		handler.ServeHTTP(w, r)
+
+		resp := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+		handler.ServeHTTP(resp, r)
 		// when the tracing middleware is initialized first _and_
 		// the tracing.SpanHook is configured, then the logger will
 		// also emit the trace and span ids as fields
 		logger := logrus.
 			WithContext(r.Context()).
-			WithFields(logrus.Fields{
-				"app":  opt.app,
-				"path": r.URL.EscapedPath(),
-			})
-		resp, ok := w.(negroni.ResponseWriter)
-		if !ok {
-			logger.Warn("wrong request type")
-			return
-		}
+			WithField("app", opt.app).
+			WithFields(fields(r))
+
 		duration := time.Since(start)
 		status := resp.Status()
 		if status == 0 {
@@ -66,13 +94,37 @@ func (opt *loggingOption) WrapHandler(handler http.Handler) http.Handler {
 			"duration_millis": duration.Nanoseconds() / 1000000,
 			"status_code":     status,
 		})
-		if status >= 200 && status < 400 {
-			logger.Info("successfully handled request")
-		} else {
+		if !isSuccess(status) {
 			logger.Warn("problem while handling request")
+			return
+		}
+
+		if !ignore(r) {
+			logger.Info("successfully handled request")
 		}
 	})
-	n := negroni.New()
-	n.UseHandler(h)
-	return n
+
+	return h
+}
+
+func defaultFields(r *http.Request) logrus.Fields {
+	return logrus.Fields{
+		"method": r.Method,
+		"path":   r.URL.EscapedPath(),
+	}
+}
+
+func defaultIgnore(r *http.Request) bool {
+	agent := strings.ToLower(r.Header.Get("User-Agent"))
+
+	switch {
+	case strings.Contains(agent, "healthcheck"), strings.Contains(agent, "kube-probe"):
+		return true
+	default:
+		return false
+	}
+}
+
+func isSuccess(status int) bool {
+	return status >= 200 && status < 400
 }

pkg/http/middlewares/logging_test.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"net/http"
 	"net/http/httptest"
+	"strings"
 	"testing"
 	"time"
 
@@ -35,7 +36,11 @@ func Test_LoggingMiddleware(t *testing.T) {
 		require.NoError(t, err)
 		defer resp.Body.Close()
 
-		require.Contains(t, buf.String(), "successfully handled request")
+		data := buf.String()
+		require.Equal(t, 1, strings.Count(data, "\n"))
+		require.Contains(t, data, `level=info`)
+		require.Contains(t, data, `msg="successfully handled request"`)
+		require.Contains(t, data, `app=test duration_millis=0 method=GET path=/logging status_code=200`)
 	})
 
 	t.Run("should support websockets", func(t *testing.T) {
@@ -52,6 +57,61 @@ func Test_LoggingMiddleware(t *testing.T) {
 		require.NoError(t, err)
 
 		time.Sleep(100 * time.Millisecond)
-		require.Contains(t, buf.String(), "successfully handled request")
+		data := buf.String()
+		require.Equal(t, 1, strings.Count(data, "\n"))
+		require.Contains(t, data, `level=info`)
+		require.Contains(t, data, `msg="successfully handled request"`)
+		require.Contains(t, data, `app=test duration_millis=0 method=GET path=/ws/echo status_code=200`)
+	})
+
+	t.Run("should ignore healthchecks", func(t *testing.T) {
+		buf, restore := utils.SetupLoggingBuffer()
+		defer restore()
+
+		srv, err := createServer([]server.Option{WithLogging("test")})
+		require.NoError(t, err)
+
+		ts := httptest.NewServer(srv.Handler)
+		defer ts.Close()
+
+		req, err := http.NewRequest(http.MethodGet, ts.URL+"/logging", nil)
+		require.NoError(t, err)
+		req = req.WithContext(ctx)
+		req.Header.Set("User-Agent", "ELB-HealthChecker")
+
+		resp, err := http.DefaultClient.Do(req)
+		require.NoError(t, err)
+		defer resp.Body.Close()
+
+		require.Equal(t, 200, resp.StatusCode)
+
+		require.Equal(t, buf.String(), "")
+	})
+
+	t.Run("should log on error codes", func(t *testing.T) {
+		buf, restore := utils.SetupLoggingBuffer()
+		defer restore()
+
+		srv, err := createServer([]server.Option{WithLogging("test")})
+		require.NoError(t, err)
+
+		ts := httptest.NewServer(srv.Handler)
+		defer ts.Close()
+
+		req, err := http.NewRequest(http.MethodGet, ts.URL+"/error", nil)
+		require.NoError(t, err)
+		req = req.WithContext(ctx)
+
+		resp, err := http.DefaultClient.Do(req)
+		require.NoError(t, err)
+		defer resp.Body.Close()
+
+		require.Equal(t, 400, resp.StatusCode)
+
+		data := buf.String()
+		require.Equal(t, 1, strings.Count(data, "\n"), data)
+		require.Contains(t, data, `level=warn`)
+		require.Contains(t, data, `msg="problem while handling request"`)
+		require.Contains(t, data, `app=test duration_millis=0 method=GET path=/error status_code=400`)
 	})
 }

pkg/http/middlewares/middleware_test.go

@@ -37,6 +37,10 @@ func createServer(opts []server.Option) (*http.Server, error) {
 
 	mux.Handle("/metrics", promhttp.Handler())
 	mux.HandleFunc("/ws/", echoWS)
+	mux.HandleFunc("/error", func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusBadRequest)
+		_, _ = io.Copy(w, r.Body)
+	})
 	mux.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
 		if r.URL.Path == "/panic" {
 			panic("PANIC!!!")

pkg/http/middlewares/tracing.go

@@ -31,7 +31,7 @@ type tracingOption struct {
 }
 
 func (opt *tracingOption) WrapHandler(handler http.Handler) http.Handler {
-	mw := middleware(
+	mw := traceMiddleware(
 		opentracing.GlobalTracer(),
 		handler,
 		operationNameFunc(opt.opNameFunc),
@@ -90,7 +90,7 @@ func mwComponentName(componentName string) mwOption {
 // Example:
 //	 http.ListenAndServe("localhost:80", nethttp.Middleware(tracer, http.DefaultServeMux))
 //
-// The options allow fine tuning the behavior of the middleware.
+// The options allow fine tuning the behavior of the traceMiddleware.
 //
 // Example:
 //   mw := nethttp.Middleware(
@@ -103,7 +103,7 @@ func mwComponentName(componentName string) mwOption {
 //			sp.SetTag("http.uri", r.URL.EscapedPath())
 //		}),
 //   )
-func middleware(tr opentracing.Tracer, h http.Handler, options ...mwOption) http.Handler {
+func traceMiddleware(tr opentracing.Tracer, h http.Handler, options ...mwOption) http.Handler {
 	opts := mwOptions{
 		opNameFunc: func(r *http.Request) string {
 			return "HTTP " + r.Method