Replace Echo logger with slog. (#67)

* Replace Echo logger with slog.

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

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