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 {
-    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
+
+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.
+
+### Middleware
 
-### Request ID
+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.
 
-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.
+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)
-	} 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,
+		)
 	}
 }

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