Replace Echo logger with slog. (#67)

* Replace Echo logger with slog.

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 {
+logger := slog.New(logHandler).With("id", requestId)
-    ctx.Logger().Info("something happened")
+log.Set(ctx, logger)
+```
 
-    if err := someOperation(); err != nil {
+Access and use the logger:
-        ctx.Logger().Errorf("the operation failed: %v", err)
+```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
 

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

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)
 	}
 }
 

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
 	}
 

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)
+		log.Ctx(ctx).Error(err.Error())
-	} else {
-		ctx.Logger().Info(err)
 	}
 
+	// 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,
+		)
 	}
 }

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,
 		}),

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()
+}

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)
+}

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
+// SetLogger initializes a logger for the current request and stores it in the context.
-// This requires that middleware that includes the request ID first execute
+// It's recommended to have this executed after Echo's RequestID() middleware because it will add
-func LogRequestID() echo.MiddlewareFunc {
+// 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 {
+		return func(ctx echo.Context) error {
-			rID := c.Response().Header().Get(echo.HeaderXRequestID)
+			// Include the request ID in the logger
-			format := `{"time":"${time_rfc3339_nano}","id":"%s","level":"${level}","prefix":"${prefix}","file":"${short_file}","line":"${line}"}`
+			rID := ctx.Response().Header().Get(echo.HeaderXRequestID)
-			c.Logger().SetHeader(fmt.Sprintf(format, rID))
+			logger := log.Ctx(ctx).With("request_id", rID)
-			return next(c)
+
+			// 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
 		}
 	}
 }

pkg/middleware/log_test.go

@@ -1,27 +1,111 @@
 package middleware
 
 import (
-	"bytes"
+	"context"
-	"fmt"
+	"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
+	h := new(mockLogHandler)
-	ctx.Logger().SetOutput(&buf)
+	logger := slog.New(h)
-	ctx.Logger().Info("test")
+	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)
 }

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,
+		)
 	}
 }

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()
-
+	c.Web.HideBanner = true
-	// 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.Validator = c.Validator
 }
 

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
 	}
 

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)