From 43fd27ebdf4a334b9bca13f2d3cd606aa04995e7 Mon Sep 17 00:00:00 2001 From: stevenvegt Date: Tue, 26 Oct 2021 14:55:58 +0200 Subject: [PATCH 1/6] Use logrus as http request logger --- core/echo.go | 45 ++++++++++++++++++++++++++++++++++++++------- 1 file changed, 38 insertions(+), 7 deletions(-) diff --git a/core/echo.go b/core/echo.go index 1bf76c1839..7b78ce4940 100644 --- a/core/echo.go +++ b/core/echo.go @@ -3,10 +3,12 @@ package core import ( "errors" "fmt" - "github.com/labstack/echo/v4" - "github.com/labstack/echo/v4/middleware" "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 +108,42 @@ 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 +} + 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)) + + // Register logrus as the Echo logger middleware. + // Skip log calls to the status endpoint (it gets called often by the Docker healthcheck and pollutes the log) + requestLoggerConfig := middleware.RequestLoggerConfig{ + Skipper: requestsStatusEndpoint, + LogURI: true, + LogStatus: true, + LogMethod: true, + LogRemoteIP: true, + LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error { + Logger().WithFields(logrus.Fields{ + "remote_ip": values.RemoteIP, + "method": values.Method, + "uri": values.URI, + "status": values.Status, + }).Info("request") + + return nil + }, + } + echoServer.Use(middleware.RequestLoggerWithConfig(requestLoggerConfig)) + + // ErrorHandler echoServer.HTTPErrorHandler = createHTTPErrorHandler() + + // CORS Configuration if cfg.CORS.Enabled() { if strictmode { for _, origin := range cfg.CORS.Origin { @@ -125,6 +154,8 @@ 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) return echoServer, nil } From 955e844218529fd4fb8263651e72602be0b6f2f8 Mon Sep 17 00:00:00 2001 From: stevenvegt Date: Wed, 27 Oct 2021 09:02:22 +0200 Subject: [PATCH 2/6] Fix status codes Uses a custom logger middleware since the echo RequestLogger only know how to handle echo.HTTPErrors and logged wrong http status codes. --- core/echo.go | 67 +++++++++++++++++++++++++++++++-------------- core/echo_errors.go | 6 +++- 2 files changed, 52 insertions(+), 21 deletions(-) diff --git a/core/echo.go b/core/echo.go index 7b78ce4940..5ac13f83e9 100644 --- a/core/echo.go +++ b/core/echo.go @@ -3,6 +3,7 @@ package core import ( "errors" "fmt" + "net/http" "strings" "sync" @@ -115,30 +116,53 @@ func Logger() *logrus.Entry { return _logger } -func createEchoServer(cfg HTTPConfig, strictmode bool) (*echo.Echo, error) { - echoServer := echo.New() - echoServer.HideBanner = true +// 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 +} + +// 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(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 + } + } - // Register logrus as the Echo logger middleware. - // Skip log calls to the status endpoint (it gets called often by the Docker healthcheck and pollutes the log) - requestLoggerConfig := middleware.RequestLoggerConfig{ - Skipper: requestsStatusEndpoint, - LogURI: true, - LogStatus: true, - LogMethod: true, - LogRemoteIP: true, - LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error { Logger().WithFields(logrus.Fields{ - "remote_ip": values.RemoteIP, - "method": values.Method, - "uri": values.URI, - "status": values.Status, + "remote_ip": c.RealIP(), + "method": req.Method, + "uri": req.RequestURI, + "status": status, }).Info("request") - - return nil - }, + return + } } - echoServer.Use(middleware.RequestLoggerWithConfig(requestLoggerConfig)) +} + +func createEchoServer(cfg HTTPConfig, strictmode bool) (*echo.Echo, error) { + echoServer := echo.New() + echoServer.HideBanner = true // ErrorHandler echoServer.HTTPErrorHandler = createHTTPErrorHandler() @@ -157,6 +181,9 @@ func createEchoServer(cfg HTTPConfig, strictmode bool) (*echo.Echo, error) { // Use middleware to decode URL encoded path parameters like did%3Anuts%3A123 -> did:nuts:123 echoServer.Use(DecodeURIPath) + + echoServer.Use(loggerMiddleware(loggerConfig{Skipper: requestsStatusEndpoint})) + return echoServer, nil } diff --git a/core/echo_errors.go b/core/echo_errors.go index 094377ee48..ea5ea9188d 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" ) @@ -21,6 +22,8 @@ const OperationIDContextKey = "!!OperationId" const ModuleNameContextKey = "!!ModuleName" const unmappedStatusCode = 0 + + func createHTTPErrorHandler() echo.HTTPErrorHandler { return func(err error, ctx echo.Context) { // HTTPErrors occur e.g. when a parameter bind fails. We map this to a httpStatusCodeError so its status code @@ -58,6 +61,7 @@ func createHTTPErrorHandler() echo.HTTPErrorHandler { // Error returns an error that maps to a HTTP status func Error(statusCode int, errStr string, args ...interface{}) error { return httpStatusCodeError{msg: fmt.Errorf(errStr, args...).Error(), err: getErrArg(args), statusCode: statusCode} + return echo.NewHTTPError(statusCode, ) } // NotFoundError returns an error that maps to a HTTP 404 Status Not Found. From ba2cd66f7b635ae54e23ae820806ec5ded613d1f Mon Sep 17 00:00:00 2001 From: stevenvegt Date: Wed, 27 Oct 2021 09:09:23 +0200 Subject: [PATCH 3/6] Go fmt --- core/echo.go | 7 ++++--- core/echo_errors.go | 4 +--- 2 files changed, 5 insertions(+), 6 deletions(-) diff --git a/core/echo.go b/core/echo.go index 5ac13f83e9..b26f9c4fbc 100644 --- a/core/echo.go +++ b/core/echo.go @@ -110,6 +110,7 @@ func getGroup(path string) string { } 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 { @@ -151,9 +152,9 @@ func loggerMiddleware(config loggerConfig) echo.MiddlewareFunc { Logger().WithFields(logrus.Fields{ "remote_ip": c.RealIP(), - "method": req.Method, - "uri": req.RequestURI, - "status": status, + "method": req.Method, + "uri": req.RequestURI, + "status": status, }).Info("request") return } diff --git a/core/echo_errors.go b/core/echo_errors.go index ea5ea9188d..e0614c2fe9 100644 --- a/core/echo_errors.go +++ b/core/echo_errors.go @@ -22,8 +22,6 @@ const OperationIDContextKey = "!!OperationId" const ModuleNameContextKey = "!!ModuleName" const unmappedStatusCode = 0 - - func createHTTPErrorHandler() echo.HTTPErrorHandler { return func(err error, ctx echo.Context) { // HTTPErrors occur e.g. when a parameter bind fails. We map this to a httpStatusCodeError so its status code @@ -61,7 +59,7 @@ func createHTTPErrorHandler() echo.HTTPErrorHandler { // Error returns an error that maps to a HTTP status func Error(statusCode int, errStr string, args ...interface{}) error { return httpStatusCodeError{msg: fmt.Errorf(errStr, args...).Error(), err: getErrArg(args), statusCode: statusCode} - return echo.NewHTTPError(statusCode, ) + return echo.NewHTTPError(statusCode) } // NotFoundError returns an error that maps to a HTTP 404 Status Not Found. From cc2ec9fed899a2cd48db00b1d60ba403d76f4115 Mon Sep 17 00:00:00 2001 From: stevenvegt Date: Wed, 27 Oct 2021 10:58:02 +0200 Subject: [PATCH 4/6] Add tests for logger --- core/echo.go | 7 ++-- core/echo_test.go | 89 +++++++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 91 insertions(+), 5 deletions(-) diff --git a/core/echo.go b/core/echo.go index b26f9c4fbc..61c1248fea 100644 --- a/core/echo.go +++ b/core/echo.go @@ -122,6 +122,7 @@ func Logger() *logrus.Entry { type loggerConfig struct { // Skipper defines a function to skip middleware. Skipper middleware.Skipper + logger *logrus.Entry } // loggerMiddleware Is a custom logger middleware. @@ -131,7 +132,7 @@ type loggerConfig struct { func loggerMiddleware(config loggerConfig) echo.MiddlewareFunc { return func(next echo.HandlerFunc) echo.HandlerFunc { return func(c echo.Context) (err error) { - if config.Skipper(c) { + if config.Skipper != nil && config.Skipper(c) { return next(c) } err = next(c) @@ -150,7 +151,7 @@ func loggerMiddleware(config loggerConfig) echo.MiddlewareFunc { } } - Logger().WithFields(logrus.Fields{ + config.logger.WithFields(logrus.Fields{ "remote_ip": c.RealIP(), "method": req.Method, "uri": req.RequestURI, @@ -183,7 +184,7 @@ func createEchoServer(cfg HTTPConfig, strictmode bool) (*echo.Echo, error) { // Use middleware to decode URL encoded path parameters like did%3Anuts%3A123 -> did:nuts:123 echoServer.Use(DecodeURIPath) - echoServer.Use(loggerMiddleware(loggerConfig{Skipper: requestsStatusEndpoint})) + echoServer.Use(loggerMiddleware(loggerConfig{Skipper: requestsStatusEndpoint, logger: Logger()})) return echoServer, nil } 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() + }) +} From 6f0f7dc54917f09b36a736280bc0929d38f292b7 Mon Sep 17 00:00:00 2001 From: stevenvegt Date: Wed, 27 Oct 2021 10:59:27 +0200 Subject: [PATCH 5/6] go fmt --- core/echo.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/echo.go b/core/echo.go index 61c1248fea..07d37bd8de 100644 --- a/core/echo.go +++ b/core/echo.go @@ -132,7 +132,7 @@ type loggerConfig struct { 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) { + if config.Skipper != nil && config.Skipper(c) { return next(c) } err = next(c) From 1bb51521387a6f9f2ddebe3809fc61c8047847a4 Mon Sep 17 00:00:00 2001 From: stevenvegt Date: Thu, 28 Oct 2021 09:54:36 +0200 Subject: [PATCH 6/6] Remove debug code --- core/echo_errors.go | 1 - 1 file changed, 1 deletion(-) diff --git a/core/echo_errors.go b/core/echo_errors.go index e0614c2fe9..3eb029c99e 100644 --- a/core/echo_errors.go +++ b/core/echo_errors.go @@ -59,7 +59,6 @@ func createHTTPErrorHandler() echo.HTTPErrorHandler { // Error returns an error that maps to a HTTP status func Error(statusCode int, errStr string, args ...interface{}) error { return httpStatusCodeError{msg: fmt.Errorf(errStr, args...).Error(), err: getErrArg(args), statusCode: statusCode} - return echo.NewHTTPError(statusCode) } // NotFoundError returns an error that maps to a HTTP 404 Status Not Found.