Use logrus as http request logger

core/echo.go

@@ -3,10 +3,13 @@ package core
 import (
 	"errors"
 	"fmt"
-	"github.com/labstack/echo/v4"
-	"github.com/labstack/echo/v4/middleware"
+	"net/http"
 	"strings"
 	"sync"
+
+	"github.com/labstack/echo/v4"
+	"github.com/labstack/echo/v4/middleware"
+	"github.com/sirupsen/logrus"
 )
 
 // EchoServer implements both the EchoRouter interface and Start function to aid testing.
@@ -106,15 +109,67 @@ func getGroup(path string) string {
 	return ""
 }
 
+var _logger = logrus.StandardLogger().WithField("module", "http-server")
+
+// Logger returns a logger which should be used for logging in this engine. It adds fields so
+// log entries from this engine can be recognized as such.
+func Logger() *logrus.Entry {
+	return _logger
+}
+
+// loggerConfig Contains the configuration for the loggerMiddleware.
+// Currently, this only allows for configuration of skip paths
+type loggerConfig struct {
+	// Skipper defines a function to skip middleware.
+	Skipper middleware.Skipper
+	logger  *logrus.Entry
+}
+
+// loggerMiddleware Is a custom logger middleware.
+// Should be added as the outer middleware to catch all errors and potential status rewrites
+// The current RequestLogger is not usable with our custom problem errors.
+// See https://github.com/labstack/echo/issues/2015
+func loggerMiddleware(config loggerConfig) echo.MiddlewareFunc {
+	return func(next echo.HandlerFunc) echo.HandlerFunc {
+		return func(c echo.Context) (err error) {
+			if config.Skipper != nil && config.Skipper(c) {
+				return next(c)
+			}
+			err = next(c)
+			req := c.Request()
+			res := c.Response()
+
+			status := res.Status
+			if err != nil {
+				switch errWithStatus := err.(type) {
+				case *echo.HTTPError:
+					status = errWithStatus.Code
+				case httpStatusCodeError:
+					status = errWithStatus.statusCode
+				default:
+					status = http.StatusInternalServerError
+				}
+			}
+
+			config.logger.WithFields(logrus.Fields{
+				"remote_ip": c.RealIP(),
+				"method":    req.Method,
+				"uri":       req.RequestURI,
+				"status":    status,
+			}).Info("request")
+			return
+		}
+	}
+}
+
 func createEchoServer(cfg HTTPConfig, strictmode bool) (*echo.Echo, error) {
 	echoServer := echo.New()
 	echoServer.HideBanner = true
-	// Register Echo logger middleware but do not log calls to the status endpoint,
-	// since that gets called by the Docker healthcheck very, very often which leads to lots of clutter in the log.
-	loggerConfig := middleware.DefaultLoggerConfig
-	loggerConfig.Skipper = requestsStatusEndpoint
-	echoServer.Use(middleware.LoggerWithConfig(loggerConfig))
+
+	// ErrorHandler
 	echoServer.HTTPErrorHandler = createHTTPErrorHandler()
+
+	// CORS Configuration
 	if cfg.CORS.Enabled() {
 		if strictmode {
 			for _, origin := range cfg.CORS.Origin {
@@ -125,7 +180,12 @@ func createEchoServer(cfg HTTPConfig, strictmode bool) (*echo.Echo, error) {
 		}
 		echoServer.Use(middleware.CORSWithConfig(middleware.CORSConfig{AllowOrigins: cfg.CORS.Origin}))
 	}
+
+	// Use middleware to decode URL encoded path parameters like did%3Anuts%3A123 -> did:nuts:123
 	echoServer.Use(DecodeURIPath)
+
+	echoServer.Use(loggerMiddleware(loggerConfig{Skipper: requestsStatusEndpoint, logger: Logger()}))
+
 	return echoServer, nil
 }
 

core/echo_errors.go

@@ -3,9 +3,10 @@ package core
 import (
 	"errors"
 	"fmt"
+	"net/http"
+
 	"github.com/labstack/echo/v4"
 	"github.com/sirupsen/logrus"
-	"net/http"
 	"schneider.vip/problem"
 )
 

core/echo_test.go

@@ -1,12 +1,17 @@
 package core
 
 import (
+	"errors"
 	"fmt"
+	"net/http"
+	"testing"
+
 	"github.com/golang/mock/gomock"
 	"github.com/labstack/echo/v4"
+	"github.com/nuts-foundation/nuts-node/mock"
+	"github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
-	"net/http"
-	"testing"
 )
 
 func Test_MultiEcho_Bind(t *testing.T) {
@@ -152,3 +157,83 @@ func Test_requestsStatusEndpoint(t *testing.T) {
 		assert.False(t, requestsStatusEndpoint(ctx))
 	})
 }
+
+func Test_loggerMiddleware(t *testing.T) {
+	t.Run("it logs", func(t *testing.T) {
+		ctrl := gomock.NewController(t)
+		response  := &echo.Response{}
+		echoMock := mock.NewMockContext(ctrl)
+		echoMock.EXPECT().NoContent(http.StatusNoContent).Do(func(status int) {response.Status = status})
+		echoMock.EXPECT().Request().Return(&http.Request{RequestURI: "/test"})
+		echoMock.EXPECT().Response().Return(response)
+		echoMock.EXPECT().RealIP().Return("::1")
+
+		logger, hook := test.NewNullLogger()
+		logFunc := loggerMiddleware(loggerConfig{logger: logger.WithFields(logrus.Fields{})})
+		err := logFunc(func(context echo.Context) error {
+			return context.NoContent(http.StatusNoContent)
+		})(echoMock)
+
+		assert.NoError(t, err)
+		assert.Len(t, hook.Entries, 1)
+		assert.Equal(t, "::1", hook.LastEntry().Data["remote_ip"])
+		assert.Equal(t, http.StatusNoContent, hook.LastEntry().Data["status"])
+		assert.Equal(t, "/test", hook.LastEntry().Data["uri"])
+		ctrl.Finish()
+	})
+
+	t.Run("it handles echo.HTTPErrors", func(t *testing.T) {
+		ctrl := gomock.NewController(t)
+		echoMock := mock.NewMockContext(ctrl)
+		echoMock.EXPECT().Request().Return(&http.Request{})
+		echoMock.EXPECT().Response().Return(&echo.Response{Status: http.StatusOK})
+		echoMock.EXPECT().RealIP().Return("::1")
+
+		logger, hook := test.NewNullLogger()
+		logFunc := loggerMiddleware(loggerConfig{logger: logger.WithFields(logrus.Fields{})})
+		_ = logFunc(func(context echo.Context) error {
+			return echo.NewHTTPError(http.StatusForbidden)
+		})(echoMock)
+
+		assert.Len(t, hook.Entries, 1)
+		assert.Equal(t, http.StatusForbidden, hook.LastEntry().Data["status"])
+		ctrl.Finish()
+
+	})
+
+	t.Run("it handles httpStatusCodeError", func(t *testing.T) {
+		ctrl := gomock.NewController(t)
+		echoMock := mock.NewMockContext(ctrl)
+		echoMock.EXPECT().Request().Return(&http.Request{})
+		echoMock.EXPECT().Response().Return(&echo.Response{Status: http.StatusOK})
+		echoMock.EXPECT().RealIP().Return("::1")
+
+		logger, hook := test.NewNullLogger()
+		logFunc := loggerMiddleware(loggerConfig{logger: logger.WithFields(logrus.Fields{})})
+		_ = logFunc(func(context echo.Context) error {
+			return NotFoundError("not found")
+		})(echoMock)
+
+		assert.Len(t, hook.Entries, 1)
+		assert.Equal(t, http.StatusNotFound, hook.LastEntry().Data["status"])
+		ctrl.Finish()
+	})
+
+	t.Run("it handles go errors", func(t *testing.T) {
+		ctrl := gomock.NewController(t)
+		echoMock := mock.NewMockContext(ctrl)
+		echoMock.EXPECT().Request().Return(&http.Request{})
+		echoMock.EXPECT().Response().Return(&echo.Response{Status: http.StatusOK})
+		echoMock.EXPECT().RealIP().Return("::1")
+
+		logger, hook := test.NewNullLogger()
+		logFunc := loggerMiddleware(loggerConfig{logger: logger.WithFields(logrus.Fields{})})
+		_ = logFunc(func(context echo.Context) error {
+			return errors.New("failed")
+		})(echoMock)
+
+		assert.Len(t, hook.Entries, 1)
+		assert.Equal(t, http.StatusInternalServerError, hook.LastEntry().Data["status"])
+		ctrl.Finish()
+	})
+}