From 9acf73a4d92d519523d7eded18015d3494aace7d Mon Sep 17 00:00:00 2001 From: Mike Stefanello Date: Fri, 14 Jun 2024 21:01:48 -0400 Subject: [PATCH] Replace Echo logger with slog. (#67) * Replace Echo logger with slog. --- README.md | 44 +++++++++++--- pkg/context/context.go | 3 + pkg/controller/controller.go | 5 +- pkg/handlers/auth.go | 25 ++++++-- pkg/handlers/error.go | 12 ++-- pkg/handlers/router.go | 4 +- pkg/log/log.go | 22 +++++++ pkg/log/log_test.go | 21 +++++++ pkg/middleware/log.go | 78 ++++++++++++++++++++++--- pkg/middleware/log_test.go | 108 +++++++++++++++++++++++++++++++---- pkg/msg/msg.go | 9 ++- pkg/services/container.go | 21 ++++--- pkg/services/mail.go | 5 +- pkg/tests/tests.go | 15 +++++ 14 files changed, 315 insertions(+), 57 deletions(-) create mode 100644 pkg/log/log.go create mode 100644 pkg/log/log_test.go diff --git a/README.md b/README.md index 7aefe2e..bea883f 100644 --- a/README.md +++ b/README.md @@ -1209,23 +1209,49 @@ To use _Let's Encrypt_ follow [this guide](https://echo.labstack.com/cookbook/au ## Logging -Logging is provided by [Echo](https://echo.labstack.com/guide/customization/#logging) and is accessible within the _Echo_ instance, which is located in the `Web` field of the `Container`, or within any of the _context_ parameters, for example: +By default, the [Echo logger](https://echo.labstack.com/guide/customization/#logging) is not used for the following reasons: +1) It does not support structured logging, which makes it difficult to deal with variables, especially if you intend to store a logger in context with pre-populated attributes. +2) The upcoming v5 release of Echo will not contain a logger. +3) It should be easy to use whatever logger you prefer (even if that is Echo's logger). + +The provided implementation uses the relatively new [log/slog](https://go.dev/blog/slog) library which was added to Go in version 1.21 but swapping that out for whichever you prefer is very easy. + +### Context + +The simple `pkg/log` package provides the ability to set and get a logger from the Echo context. This is especially useful when you use the provided logger middleware (see below). If you intend to use a different logger, modify these methods to receive and return the logger of your choice. + +### Usage + +Adding a logger to the context: ```go -func (c *home) Get(ctx echo.Context) error { - ctx.Logger().Info("something happened") +logger := slog.New(logHandler).With("id", requestId) +log.Set(ctx, logger) +``` - if err := someOperation(); err != nil { - ctx.Logger().Errorf("the operation failed: %v", err) - } +Access and use the logger: +```go +func (h *handler) Page(ctx echo.Context) error { + log.Ctx(ctx).Info("send a message to the log", + "value_one", valueOne, + "value_two", valueTwo, + ) } ``` -The logger can be swapped out for another, as long as it implements Echo's logging [interface](https://github.com/labstack/echo/blob/master/log.go). There are projects that provide this bridge for popular logging packages such as [zerolog](https://github.com/rs/zerolog). +### Log level -### Request ID +When the _Container_ configuration is initialized (`initConfig()`), the `slog` default log level is set based on the environment. `INFO` is used for production and `DEBUG` for everything else. -By default, Echo's [request ID middleware](https://echo.labstack.com/middleware/request-id/) is enabled on the router but it only adds a request ID to the log entry for the HTTP request itself. Log entries that are created during the course of that request do not contain the request ID. `LogRequestID()` is custom middleware included which adds that request ID to all logs created throughout the request. +### Middleware + +The `SetLogger()` middleware has been added to the router which sets an initialized logger on the request context. It's recommended that this remains after Echo's `RequestID()` middleware because it will add the request ID to the logger which means that all logs produced for that given request will contain the same ID, so they can be linked together. If you want to include more attributes on all request logs, set those fields here. + +The `LogRequest()` middleware is a replacement for Echo's `Logger()` middleware which produces a log of every request made, but uses our logger rather than Echo's. + +``` +2024/06/14 19:44:16 INFO request_id=snoonQoyRSEBcQthnIzIWIeVRxmutyAV ip=::1 host=localhost:8000 method=GET path=/about referer=http://localhost:8000/ status=200 bytes_in=0 bytes_out=6695 latency=18.022502ms +``` ## Roadmap diff --git a/pkg/context/context.go b/pkg/context/context.go index 71c465f..7271f29 100644 --- a/pkg/context/context.go +++ b/pkg/context/context.go @@ -17,6 +17,9 @@ const ( // PasswordTokenKey is the key value used to store a password token in context PasswordTokenKey = "password_token" + + // LoggerKey is the key value used to store a structured logger in context + LoggerKey = "logger" ) // IsCanceledError determines if an error is due to a context cancelation diff --git a/pkg/controller/controller.go b/pkg/controller/controller.go index 9917f97..f40d35c 100644 --- a/pkg/controller/controller.go +++ b/pkg/controller/controller.go @@ -7,6 +7,7 @@ import ( "github.com/mikestefanello/pagoda/pkg/context" "github.com/mikestefanello/pagoda/pkg/htmx" + "github.com/mikestefanello/pagoda/pkg/log" "github.com/mikestefanello/pagoda/pkg/middleware" "github.com/mikestefanello/pagoda/pkg/services" "github.com/mikestefanello/pagoda/templates" @@ -134,9 +135,9 @@ func (c *Controller) cachePage(ctx echo.Context, page Page, html *bytes.Buffer) switch { case err == nil: - ctx.Logger().Info("cached page") + log.Ctx(ctx).Debug("cached page") case !context.IsCanceledError(err): - ctx.Logger().Errorf("failed to cache page: %v", err) + log.Ctx(ctx).Error("failed to cache page", "error", err) } } diff --git a/pkg/handlers/auth.go b/pkg/handlers/auth.go index d324c4f..3fa1ee3 100644 --- a/pkg/handlers/auth.go +++ b/pkg/handlers/auth.go @@ -11,6 +11,7 @@ import ( "github.com/mikestefanello/pagoda/pkg/context" "github.com/mikestefanello/pagoda/pkg/controller" "github.com/mikestefanello/pagoda/pkg/form" + "github.com/mikestefanello/pagoda/pkg/log" "github.com/mikestefanello/pagoda/pkg/middleware" "github.com/mikestefanello/pagoda/pkg/msg" "github.com/mikestefanello/pagoda/pkg/services" @@ -145,7 +146,9 @@ func (c *Auth) ForgotPasswordSubmit(ctx echo.Context) error { return c.Fail(err, "error generating password reset token") } - ctx.Logger().Infof("generated password reset token for user %d", u.ID) + log.Ctx(ctx).Info("generated password reset token", + "user_id", u.ID, + ) // Email the user url := ctx.Echo().Reverse(routeNameResetPassword, u.ID, pt.ID, token) @@ -271,7 +274,10 @@ func (c *Auth) RegisterSubmit(ctx echo.Context) error { switch err.(type) { case nil: - ctx.Logger().Infof("user created: %s", u.Name) + log.Ctx(ctx).Info("user created", + "user_name", u.Name, + "user_id", u.ID, + ) case *ent.ConstraintError: msg.Warning(ctx, "A user with this email address already exists. Please log in.") return c.Redirect(ctx, routeNameLogin) @@ -282,7 +288,10 @@ func (c *Auth) RegisterSubmit(ctx echo.Context) error { // Log the user in err = c.auth.Login(ctx, u.ID) if err != nil { - ctx.Logger().Errorf("unable to log in: %v", err) + log.Ctx(ctx).Error("unable to log user in", + "error", err, + "user_id", u.ID, + ) msg.Info(ctx, "Your account has been created.") return c.Redirect(ctx, routeNameLogin) } @@ -299,7 +308,10 @@ func (c *Auth) sendVerificationEmail(ctx echo.Context, usr *ent.User) { // Generate a token token, err := c.auth.GenerateEmailVerificationToken(usr.Email) if err != nil { - ctx.Logger().Errorf("unable to generate email verification token: %v", err) + log.Ctx(ctx).Error("unable to generate email verification token", + "user_id", usr.ID, + "error", err, + ) return } @@ -313,7 +325,10 @@ func (c *Auth) sendVerificationEmail(ctx echo.Context, usr *ent.User) { Send(ctx) if err != nil { - ctx.Logger().Errorf("unable to send email verification link: %v", err) + log.Ctx(ctx).Error("unable to send email verification link", + "user_id", usr.ID, + "error", err, + ) return } diff --git a/pkg/handlers/error.go b/pkg/handlers/error.go index 443b07a..7b451c0 100644 --- a/pkg/handlers/error.go +++ b/pkg/handlers/error.go @@ -6,6 +6,7 @@ import ( "github.com/labstack/echo/v4" "github.com/mikestefanello/pagoda/pkg/context" "github.com/mikestefanello/pagoda/pkg/controller" + "github.com/mikestefanello/pagoda/pkg/log" "github.com/mikestefanello/pagoda/templates" ) @@ -18,17 +19,18 @@ func (e *Error) Page(err error, ctx echo.Context) { return } + // Determine the error status code code := http.StatusInternalServerError if he, ok := err.(*echo.HTTPError); ok { code = he.Code } + // Log the error if code >= 500 { - ctx.Logger().Error(err) - } else { - ctx.Logger().Info(err) + log.Ctx(ctx).Error(err.Error()) } + // Render the error page page := controller.NewPage(ctx) page.Layout = templates.LayoutMain page.Name = templates.PageError @@ -37,6 +39,8 @@ func (e *Error) Page(err error, ctx echo.Context) { page.HTMX.Request.Enabled = false if err = e.RenderPage(ctx, page); err != nil { - ctx.Logger().Error(err) + log.Ctx(ctx).Error("failed to render error page", + "error", err, + ) } } diff --git a/pkg/handlers/router.go b/pkg/handlers/router.go index cb3c4c5..c77713d 100644 --- a/pkg/handlers/router.go +++ b/pkg/handlers/router.go @@ -35,9 +35,9 @@ func BuildRouter(c *services.Container) error { echomw.Recover(), echomw.Secure(), echomw.RequestID(), + middleware.SetLogger(), + middleware.LogRequest(), echomw.Gzip(), - echomw.Logger(), - middleware.LogRequestID(), echomw.TimeoutWithConfig(echomw.TimeoutConfig{ Timeout: c.Config.App.Timeout, }), diff --git a/pkg/log/log.go b/pkg/log/log.go new file mode 100644 index 0000000..b609815 --- /dev/null +++ b/pkg/log/log.go @@ -0,0 +1,22 @@ +package log + +import ( + "log/slog" + + "github.com/labstack/echo/v4" + "github.com/mikestefanello/pagoda/pkg/context" +) + +// Set sets a logger in the context +func Set(ctx echo.Context, logger *slog.Logger) { + ctx.Set(context.LoggerKey, logger) +} + +// Ctx returns the logger stored in context, or provides the default logger if one is not present +func Ctx(ctx echo.Context) *slog.Logger { + if l, ok := ctx.Get(context.LoggerKey).(*slog.Logger); ok { + return l + } + + return slog.Default() +} diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go new file mode 100644 index 0000000..d9486a8 --- /dev/null +++ b/pkg/log/log_test.go @@ -0,0 +1,21 @@ +package log + +import ( + "testing" + + "github.com/labstack/echo/v4" + "github.com/mikestefanello/pagoda/pkg/tests" + "github.com/stretchr/testify/assert" +) + +func TestCtxSet(t *testing.T) { + ctx, _ := tests.NewContext(echo.New(), "/") + logger := Ctx(ctx) + assert.NotNil(t, logger) + + logger = logger.With("a", "b") + Set(ctx, logger) + + got := Ctx(ctx) + assert.Equal(t, got, logger) +} diff --git a/pkg/middleware/log.go b/pkg/middleware/log.go index 2c36431..b8f8d4b 100644 --- a/pkg/middleware/log.go +++ b/pkg/middleware/log.go @@ -1,20 +1,80 @@ package middleware import ( - "fmt" + "strconv" + "time" "github.com/labstack/echo/v4" + "github.com/mikestefanello/pagoda/pkg/log" ) -// LogRequestID includes the request ID in all logs for the given request -// This requires that middleware that includes the request ID first execute -func LogRequestID() echo.MiddlewareFunc { +// SetLogger initializes a logger for the current request and stores it in the context. +// It's recommended to have this executed after Echo's RequestID() middleware because it will add +// the request ID to the logger so that all log messages produced from this request have the +// request ID in it. You can modify this code to include any other fields that you want to always +// appear. +func SetLogger() echo.MiddlewareFunc { return func(next echo.HandlerFunc) echo.HandlerFunc { - return func(c echo.Context) error { - rID := c.Response().Header().Get(echo.HeaderXRequestID) - format := `{"time":"${time_rfc3339_nano}","id":"%s","level":"${level}","prefix":"${prefix}","file":"${short_file}","line":"${line}"}` - c.Logger().SetHeader(fmt.Sprintf(format, rID)) - return next(c) + return func(ctx echo.Context) error { + // Include the request ID in the logger + rID := ctx.Response().Header().Get(echo.HeaderXRequestID) + logger := log.Ctx(ctx).With("request_id", rID) + + // TODO include other fields you may want in all logs for this request + log.Set(ctx, logger) + return next(ctx) + } + } +} + +// LogRequest logs the current request +// Echo provides middleware similar to this, but we want to use our own logger +func LogRequest() echo.MiddlewareFunc { + return func(next echo.HandlerFunc) echo.HandlerFunc { + return func(ctx echo.Context) (err error) { + req := ctx.Request() + res := ctx.Response() + + // Track how long the request takes to complete + start := time.Now() + if err = next(ctx); err != nil { + ctx.Error(err) + } + stop := time.Now() + + sub := log.Ctx(ctx).With( + "ip", ctx.RealIP(), + "host", req.Host, + "method", req.Method, + "path", func() string { + p := req.URL.Path + if p == "" { + p = "/" + } + return p + }(), + "referer", req.Referer(), + "status", res.Status, + "bytes_in", func() string { + cl := req.Header.Get(echo.HeaderContentLength) + if cl == "" { + cl = "0" + } + return cl + }(), + "bytes_out", strconv.FormatInt(res.Size, 10), + "latency", stop.Sub(start).String(), + ) + + // TODO is there a (better) way to log without a message? + + if res.Status >= 500 { + sub.Error("") + } else { + sub.Info("") + } + + return nil } } } diff --git a/pkg/middleware/log_test.go b/pkg/middleware/log_test.go index a6b294a..3cf136f 100644 --- a/pkg/middleware/log_test.go +++ b/pkg/middleware/log_test.go @@ -1,27 +1,111 @@ package middleware import ( - "bytes" - "fmt" + "context" + "log/slog" + "net/http" "testing" - "github.com/mikestefanello/pagoda/pkg/tests" - "github.com/labstack/echo/v4" + echomw "github.com/labstack/echo/v4/middleware" + "github.com/mikestefanello/pagoda/pkg/log" + "github.com/mikestefanello/pagoda/pkg/tests" + "github.com/stretchr/testify/require" "github.com/stretchr/testify/assert" - - echomw "github.com/labstack/echo/v4/middleware" ) +type mockLogHandler struct { + msg string + level string + group string + attr []slog.Attr +} + +func (m *mockLogHandler) Enabled(_ context.Context, l slog.Level) bool { + return true +} + +func (m *mockLogHandler) Handle(_ context.Context, r slog.Record) error { + m.level = r.Level.String() + m.msg = r.Message + return nil +} + +func (m *mockLogHandler) WithAttrs(as []slog.Attr) slog.Handler { + if m.attr == nil { + m.attr = make([]slog.Attr, 0) + } + m.attr = append(m.attr, as...) + return m +} + +func (m *mockLogHandler) WithGroup(name string) slog.Handler { + m.group = name + return m +} + +func (m *mockLogHandler) GetAttr(key string) string { + if m.attr == nil { + return "" + } + for _, attr := range m.attr { + if attr.Key == key { + return attr.Value.String() + } + } + + return "" +} + func TestLogRequestID(t *testing.T) { ctx, _ := tests.NewContext(c.Web, "/") - _ = tests.ExecuteMiddleware(ctx, echomw.RequestID()) - _ = tests.ExecuteMiddleware(ctx, LogRequestID()) - var buf bytes.Buffer - ctx.Logger().SetOutput(&buf) - ctx.Logger().Info("test") + h := new(mockLogHandler) + logger := slog.New(h) + log.Set(ctx, logger) + + require.NoError(t, tests.ExecuteMiddleware(ctx, echomw.RequestID())) + require.NoError(t, tests.ExecuteMiddleware(ctx, SetLogger())) + + log.Ctx(ctx).Info("test") rID := ctx.Response().Header().Get(echo.HeaderXRequestID) - assert.Contains(t, buf.String(), fmt.Sprintf(`id":"%s"`, rID)) + assert.Equal(t, rID, h.GetAttr("request_id")) +} + +func TestLogRequest(t *testing.T) { + statusCode := 200 + h := new(mockLogHandler) + + exec := func() { + ctx, _ := tests.NewContext(c.Web, "http://test.localhost/abc") + logger := slog.New(h).With("previous", "param") + log.Set(ctx, logger) + ctx.Request().Header.Set("Referer", "ref.com") + ctx.Request().Header.Set(echo.HeaderXRealIP, "21.12.12.21") + + require.NoError(t, tests.ExecuteHandler(ctx, func(ctx echo.Context) error { + return ctx.String(statusCode, "hello") + }, + SetLogger(), + LogRequest(), + )) + } + + exec() + assert.Equal(t, "param", h.GetAttr("previous")) + assert.Equal(t, "21.12.12.21", h.GetAttr("ip")) + assert.Equal(t, "test.localhost", h.GetAttr("host")) + assert.Equal(t, "/abc", h.GetAttr("path")) + assert.Equal(t, http.MethodGet, h.GetAttr("method")) + assert.Equal(t, "ref.com", h.GetAttr("referer")) + assert.Equal(t, "200", h.GetAttr("status")) + assert.Equal(t, "0", h.GetAttr("bytes_in")) + assert.Equal(t, "5", h.GetAttr("bytes_out")) + assert.NotEmpty(t, h.GetAttr("latency")) + assert.Equal(t, "INFO", h.level) + + statusCode = 500 + exec() + assert.Equal(t, "ERROR", h.level) } diff --git a/pkg/msg/msg.go b/pkg/msg/msg.go index ec07b2c..e6309b9 100644 --- a/pkg/msg/msg.go +++ b/pkg/msg/msg.go @@ -4,6 +4,7 @@ import ( "github.com/gorilla/sessions" "github.com/labstack/echo-contrib/session" "github.com/labstack/echo/v4" + "github.com/mikestefanello/pagoda/pkg/log" ) // Type is a message type @@ -79,7 +80,9 @@ func Get(ctx echo.Context, typ Type) []string { func getSession(ctx echo.Context) (*sessions.Session, error) { sess, err := session.Get(sessionName, ctx) if err != nil { - ctx.Logger().Errorf("cannot load flash message session: %v", err) + log.Ctx(ctx).Error("cannot load flash message session", + "error", err, + ) } return sess, err } @@ -87,6 +90,8 @@ func getSession(ctx echo.Context) (*sessions.Session, error) { // save saves the flash message session func save(ctx echo.Context, sess *sessions.Session) { if err := sess.Save(ctx.Request(), ctx.Response()); err != nil { - ctx.Logger().Errorf("failed to set flash message: %v", err) + log.Ctx(ctx).Error("failed to set flash message", + "error", err, + ) } } diff --git a/pkg/services/container.go b/pkg/services/container.go index 3384c0b..ca47e56 100644 --- a/pkg/services/container.go +++ b/pkg/services/container.go @@ -4,6 +4,7 @@ import ( "context" "database/sql" "fmt" + "log/slog" "entgo.io/ent/dialect" entsql "entgo.io/ent/dialect/sql" @@ -12,8 +13,6 @@ import ( // Required by ent _ "github.com/jackc/pgx/v4/stdlib" "github.com/labstack/echo/v4" - "github.com/labstack/gommon/log" - "github.com/mikestefanello/pagoda/config" "github.com/mikestefanello/pagoda/ent" @@ -96,6 +95,14 @@ func (c *Container) initConfig() { panic(fmt.Sprintf("failed to load config: %v", err)) } c.Config = &cfg + + // Configure logging + switch cfg.App.Environment { + case config.EnvProduction: + slog.SetLogLoggerLevel(slog.LevelInfo) + default: + slog.SetLogLoggerLevel(slog.LevelDebug) + } } // initValidator initializes the validator @@ -106,15 +113,7 @@ func (c *Container) initValidator() { // initWeb initializes the web framework func (c *Container) initWeb() { c.Web = echo.New() - - // Configure logging - switch c.Config.App.Environment { - case config.EnvProduction: - c.Web.Logger.SetLevel(log.WARN) - default: - c.Web.Logger.SetLevel(log.DEBUG) - } - + c.Web.HideBanner = true c.Web.Validator = c.Validator } diff --git a/pkg/services/mail.go b/pkg/services/mail.go index 2cd1853..b4b21c3 100644 --- a/pkg/services/mail.go +++ b/pkg/services/mail.go @@ -5,6 +5,7 @@ import ( "fmt" "github.com/mikestefanello/pagoda/config" + "github.com/mikestefanello/pagoda/pkg/log" "github.com/labstack/echo/v4" ) @@ -84,7 +85,9 @@ func (m *MailClient) send(email *mail, ctx echo.Context) error { // Check if mail sending should be skipped if m.skipSend() { - ctx.Logger().Debugf("skipping email sent to: %s", email.to) + log.Ctx(ctx).Debug("skipping email delivery", + "to", email.to, + ) return nil } diff --git a/pkg/tests/tests.go b/pkg/tests/tests.go index aa43980..1266ce4 100644 --- a/pkg/tests/tests.go +++ b/pkg/tests/tests.go @@ -41,6 +41,21 @@ func ExecuteMiddleware(ctx echo.Context, mw echo.MiddlewareFunc) error { return handler(ctx) } +// ExecuteHandler executes a handler with an optional stack of middleware +func ExecuteHandler(ctx echo.Context, handler echo.HandlerFunc, mw ...echo.MiddlewareFunc) error { + return ExecuteMiddleware(ctx, func(next echo.HandlerFunc) echo.HandlerFunc { + return func(ctx echo.Context) error { + run := handler + + for _, w := range mw { + run = w(run) + } + + return run(ctx) + } + }) +} + // AssertHTTPErrorCode asserts an HTTP status code on a given Echo HTTP error func AssertHTTPErrorCode(t *testing.T, err error, code int) { httpError, ok := err.(*echo.HTTPError)