diff --git a/core/echo.go b/core/echo.go index 1bf76c1839..07d37bd8de 100644 --- a/core/echo.go +++ b/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 } diff --git a/core/echo_errors.go b/core/echo_errors.go index 094377ee48..3eb029c99e 100644 --- a/core/echo_errors.go +++ b/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" ) diff --git a/core/echo_test.go b/core/echo_test.go index f943921b0f..cdc238225f 100644 --- a/core/echo_test.go +++ b/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() + }) +}