Skip to content

Commit

Permalink
Remove logrus, use slog
Browse files Browse the repository at this point in the history 
Required replacing logrus' testing tools
with a new `logctx.Hook` type.

Also remove sqlw since alternatives like pgx have become
so popular and use different logging patterns,
which now that there is slog as a common library,
won't require so many workarounds like sqlw.
  • Loading branch information
@rgalanakis
rgalanakis committed Jul 31, 2024
1 parent f0b7ff2 commit 490ca58
Show file tree
Hide file tree
Showing 14 changed files with 395 additions and 622 deletions.
11 changes: 6 additions & 5 deletions api/api.go
View file
Original file line number Diff line number Diff line change
@@ -1,12 +1,12 @@
/*
Package api is a standalone API package/pattern built on echo and logrus.
Package api is a standalone API package/pattern built on echo.
It sets up /statusz and /healthz endpoints,
and sets up logging middleware that takes care of the following important,
and fundamentally (in Go) interconnected tasks:
- Extract (or add) a trace ID header to the request and response.
- The trace ID can be retrieved through api.TraceID(context) of the echo.Context for the request.
- Use that trace ID header as context for the logrus logger.
- Use that trace ID header as context for the logger.
- Handle request logging (metadata about the request and response,
and log at the level appropriate for the status code).
- The request logger can be retrieved api.Logger(echo.Context).
Expand All @@ -19,15 +19,16 @@ package api
import (
"github.com/labstack/echo/v4"
"github.com/labstack/echo/v4/middleware"
"github.com/sirupsen/logrus"
"github.com/lithictech/go-aperitif/logctx"
"log/slog"
"net/http"
"os"
)

type Config struct {
// If not provided, create an echo.New.
App *echo.Echo
Logger *logrus.Entry
Logger *slog.Logger
LoggingMiddlwareConfig LoggingMiddlwareConfig
// Origins for echo's CORS middleware.
// If it and CorsConfig are empty, do not add the middleware.
Expand Down Expand Up @@ -57,7 +58,7 @@ type Config struct {

func New(cfg Config) *echo.Echo {
if cfg.Logger == nil {
cfg.Logger = unconfiguredLogger()
cfg.Logger = logctx.UnconfiguredLogger()
}
if cfg.HealthHandler == nil {
if cfg.HealthResponse == nil {
Expand Down
110 changes: 52 additions & 58 deletions api/api_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,8 +11,7 @@ import (
. "github.com/onsi/ginkgo/v2"
. "github.com/onsi/gomega"
. "github.com/rgalanakis/golangal"
"github.com/sirupsen/logrus"
"github.com/sirupsen/logrus/hooks/test"
"log/slog"
"net/http"
"net/http/httptest"
"testing"
Expand All @@ -25,15 +24,14 @@ func TestAPI(t *testing.T) {

var _ = Describe("API", func() {
var e *echo.Echo
var logger *logrus.Logger
var logHook *test.Hook
var logEntry *logrus.Entry

var logger *slog.Logger
var logHook *logctx.Hook

BeforeEach(func() {
logger, logHook = test.NewNullLogger()
logEntry = logger.WithFields(nil)
logger, logHook = logctx.NewNullLogger()
e = api.New(api.Config{
Logger: logEntry,
Logger: logger,
HealthResponse: map[string]interface{}{"o": "k"},
StatusResponse: map[string]interface{}{"it": "me"},
})
Expand All @@ -48,7 +46,7 @@ var _ = Describe("API", func() {

It("can use custom health and status fields", func() {
e = api.New(api.Config{
Logger: logEntry,
Logger: logger,
HealthHandler: func(c echo.Context) error {
return c.String(200, "yo")
},
Expand Down Expand Up @@ -117,58 +115,56 @@ var _ = Describe("API", func() {
Describe("logging", func() {
It("does not corrupt the input logger (by reassigning the closure)", func() {
e.GET("/before-first-call", func(c echo.Context) error {
Expect(api.Logger(c).Data).ToNot(HaveKey("request_status"))
Expect(api.Logger(c).Handler().(*logctx.Hook).AttrMap()).ToNot(HaveKey("request_status"))
return c.String(401, "ok")
})
e.GET("/after-first-call", func(c echo.Context) error {
Expect(api.Logger(c).Data).ToNot(HaveKey("request_status"))
Expect(api.Logger(c).Handler().(*logctx.Hook).AttrMap()).ToNot(HaveKey("request_status"))
return c.String(403, "ok")
})
Expect(Serve(e, GetRequest("/before-first-call"))).To(HaveResponseCode(401))
Expect(Serve(e, GetRequest("/after-first-call"))).To(HaveResponseCode(403))
Expect(logHook.Entries).To(HaveLen(2))
Expect(logHook.Records()).To(HaveLen(2))
})
It("logs normal requests at info", func() {
e.GET("/", func(c echo.Context) error {
return c.String(200, "ok")
})
Expect(Serve(e, GetRequest("/"))).To(HaveResponseCode(200))
Expect(logHook.Entries).To(HaveLen(1))
Expect(logHook.Entries[0].Level).To(Equal(logrus.InfoLevel))
Expect(logHook.Records()).To(HaveLen(1))
Expect(logHook.Records()[0].Record.Level).To(Equal(slog.LevelInfo))
})
It("logs 500+ at error", func() {
e.GET("/", func(c echo.Context) error {
return c.String(500, "oh")
})
Expect(Serve(e, GetRequest("/"))).To(HaveResponseCode(500))
Expect(logHook.Entries).To(HaveLen(1))
Expect(logHook.Entries[0].Level).To(Equal(logrus.ErrorLevel))
Expect(logHook.Records()).To(HaveLen(1))
Expect(logHook.Records()[0].Record.Level).To(Equal(slog.LevelError))
})
It("logs 400 to 499 as warn", func() {
e.GET("/", func(c echo.Context) error {
return c.String(400, "client err")
})
Expect(Serve(e, GetRequest("/"))).To(HaveResponseCode(400))
Expect(logHook.Entries).To(HaveLen(1))
Expect(logHook.Entries[0].Level).To(Equal(logrus.WarnLevel))
Expect(logHook.Records()).To(HaveLen(1))
Expect(logHook.Records()[0].Record.Level).To(Equal(slog.LevelWarn))
})
It("logs status and health as debug", func() {
logger.SetLevel(logrus.DebugLevel)
Expect(Serve(e, GetRequest("/healthz"))).To(HaveResponseCode(200))
Expect(Serve(e, GetRequest("/statusz"))).To(HaveResponseCode(200))
Expect(logHook.Entries).To(HaveLen(2))
Expect(logHook.Entries[0].Level).To(Equal(logrus.DebugLevel))
Expect(logHook.Entries[1].Level).To(Equal(logrus.DebugLevel))
Expect(logHook.Records()).To(HaveLen(2))
Expect(logHook.Records()[0].Record.Level).To(Equal(slog.LevelDebug))
Expect(logHook.Records()[1].Record.Level).To(Equal(slog.LevelDebug))
})
It("logs options as debug", func() {
logger.SetLevel(logrus.DebugLevel)
Expect(Serve(e, NewRequest("OPTIONS", "/foo", nil))).To(HaveResponseCode(404))
Expect(logHook.Entries).To(HaveLen(1))
Expect(logHook.Entries[0].Level).To(Equal(logrus.DebugLevel))
Expect(logHook.Records()).To(HaveLen(1))
Expect(logHook.Records()[0].Record.Level).To(Equal(slog.LevelDebug))
})
It("can log request and response headers", func() {
e = api.New(api.Config{
Logger: logEntry,
Logger: logger,
LoggingMiddlwareConfig: api.LoggingMiddlwareConfig{
RequestHeaders: true,
ResponseHeaders: true,
Expand All @@ -179,24 +175,24 @@ var _ = Describe("API", func() {
return c.String(200, "ok")
})
Expect(Serve(e, GetRequest("/", SetReqHeader("ReqHead", "ReqHeadVal")))).To(HaveResponseCode(200))
Expect(logHook.Entries).To(HaveLen(1))
Expect(logHook.Entries[0].Data).To(And(
Expect(logHook.Records()).To(HaveLen(1))
Expect(logHook.Records()[0].AttrMap()).To(And(
HaveKeyWithValue("request_header.Reqhead", "ReqHeadVal"),
HaveKeyWithValue("response_header.Reshead", "ResHeadVal"),
))
})
It("can use custom DoLog, BeforeRequest, and AfterRequest hooks", func() {
doLogCalled := false
e = api.New(api.Config{
Logger: logEntry,
Logger: logger,
LoggingMiddlwareConfig: api.LoggingMiddlwareConfig{
BeforeRequest: func(_ echo.Context, e *logrus.Entry) *logrus.Entry {
return e.WithField("before", 1)
BeforeRequest: func(_ echo.Context, e *slog.Logger) *slog.Logger {
return e.With("before", 1)
},
AfterRequest: func(_ echo.Context, e *logrus.Entry) *logrus.Entry {
return e.WithField("after", 2)
AfterRequest: func(_ echo.Context, e *slog.Logger) *slog.Logger {
return e.With("after", 2)
},
DoLog: func(c echo.Context, e *logrus.Entry) {
DoLog: func(c echo.Context, e *slog.Logger) {
doLogCalled = true
api.LoggingMiddlewareDefaultDoLog(c, e)
},
Expand All @@ -207,9 +203,9 @@ var _ = Describe("API", func() {
})
Expect(Serve(e, GetRequest("/"))).To(HaveResponseCode(400))
Expect(doLogCalled).To(BeTrue())
Expect(logHook.Entries[len(logHook.Entries)-1].Data).To(And(
HaveKeyWithValue("before", 1),
HaveKeyWithValue("after", 2),
Expect(logHook.LastRecord().AttrMap()).To(And(
HaveKeyWithValue("before", BeEquivalentTo(1)),
HaveKeyWithValue("after", BeEquivalentTo(2)),
))
})
})
Expand Down Expand Up @@ -284,16 +280,17 @@ var _ = Describe("API", func() {
r, err := http.NewRequest("GET", "", nil)
Expect(err).ToNot(HaveOccurred())
ctx := e.NewContext(r, httptest.NewRecorder())
logger := logrus.New().WithField("a", 2)
logger, _ := logctx.NewNullLogger()
logger = logger.With("a", 2)
api.SetLogger(ctx, logger)
tid := api.TraceId(ctx)

c := api.StdContext(ctx)
tkey, tval := logctx.ActiveTraceId(c)
Expect(tkey).To(Equal(logctx.RequestTraceIdKey))
Expect(tval).To(Equal(tid))
Expect(logctx.Logger(c).Data).To(And(
HaveKeyWithValue("a", 2),
Expect(logctx.Logger(c).Handler().(*logctx.Hook).AttrMap()).To(And(
HaveKeyWithValue("a", BeEquivalentTo(2)),
HaveKeyWithValue(BeEquivalentTo(logctx.RequestTraceIdKey), tid),
))
})
Expand All @@ -320,27 +317,24 @@ var _ = Describe("API", func() {
})

Describe("DebugMiddleware", func() {
BeforeEach(func() {
logger.SetLevel(logrus.DebugLevel)
})
It("noops if not enabled", func() {
e.Use(api.DebugMiddleware(api.DebugMiddlewareConfig{Enabled: false, DumpResponseBody: true}))
e.GET("/foo", func(c echo.Context) error {
return c.String(200, "ok")
})
Serve(e, NewRequest("POST", "/endpoint", nil))
Expect(logHook.Entries).To(HaveLen(1))
Expect(logHook.Entries[0].Message).To(Equal("request_finished"))
Expect(logHook.Records()).To(HaveLen(1))
Expect(logHook.Records()[0].Record.Message).To(Equal("request_finished"))
})
It("dumps what is enabled", func() {
e.Use(api.DebugMiddleware(api.DebugMiddlewareConfig{Enabled: true, DumpResponseBody: true, DumpResponseHeaders: true}))
e.GET("/endpoint", func(c echo.Context) error {
return c.String(200, "ok")
})
Serve(e, NewRequest("GET", "/endpoint", nil))
Expect(logHook.Entries).To(HaveLen(2))
Expect(logHook.Entries[0].Message).To(Equal("request_debug"))
Expect(logHook.Entries[0].Data).To(And(
Expect(logHook.Records()).To(HaveLen(2))
Expect(logHook.Records()[0].Record.Message).To(Equal("request_debug"))
Expect(logHook.Records()[0].AttrMap()).To(And(
HaveKeyWithValue("debug_response_headers", HaveKey("Content-Type")),
HaveKeyWithValue("debug_response_body", ContainSubstring("ok")),
))
Expand All @@ -351,9 +345,9 @@ var _ = Describe("API", func() {
return c.String(200, "ok")
})
Serve(e, NewRequest("GET", "/endpoint", nil, SetReqHeader("Foo", "x")))
Expect(logHook.Entries).To(HaveLen(2))
Expect(logHook.Entries[0].Message).To(Equal("request_debug"))
Expect(logHook.Entries[0].Data).To(And(
Expect(logHook.Records()).To(HaveLen(2))
Expect(logHook.Records()[0].Record.Message).To(Equal("request_debug"))
Expect(logHook.Records()[0].AttrMap()).To(And(
HaveKeyWithValue("debug_request_headers", HaveKey("Foo")),
HaveKeyWithValue("debug_response_headers", HaveKey("Content-Type")),
HaveKeyWithValue("debug_request_body", ""),
Expand All @@ -367,13 +361,13 @@ var _ = Describe("API", func() {
})
Serve(e, NewRequest("GET", "/endpoint", nil, SetReqHeader("Foo", "x")))
Serve(e, NewRequest("GET", "/endpoint", nil, SetReqHeader("Foo", "x")))
Expect(logHook.Entries).To(HaveLen(4))
Expect(logHook.Entries[0].Message).To(Equal("request_debug"))
Expect(logHook.Entries[0].Data).ToNot(HaveKey("memory_sys"))
Expect(logHook.Entries[1].Message).To(Equal("request_finished"))
Expect(logHook.Entries[2].Message).To(Equal("request_debug"))
Expect(logHook.Entries[2].Data).To(HaveKey("memory_sys"))
Expect(logHook.Entries[3].Message).To(Equal("request_finished"))
Expect(logHook.Records()).To(HaveLen(4))
Expect(logHook.Records()[0].Record.Message).To(Equal("request_debug"))
Expect(logHook.Records()[0].AttrMap()).ToNot(HaveKey("memory_sys"))
Expect(logHook.Records()[1].Record.Message).To(Equal("request_finished"))
Expect(logHook.Records()[2].Record.Message).To(Equal("request_debug"))
Expect(logHook.Records()[2].AttrMap()).To(HaveKey("memory_sys"))
Expect(logHook.Records()[3].Record.Message).To(Equal("request_finished"))
})
})
})
48 changes: 24 additions & 24 deletions api/debug.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,40 +41,40 @@ func DebugMiddleware(cfg DebugMiddlewareConfig) echo.MiddlewareFunc {
atomic.AddUint64(&requestCounter, 1)
log := logctx.Logger(StdContext(c))
if cfg.DumpRequestBody {
log = log.WithField("debug_request_body", string(reqBody))
log = log.With("debug_request_body", string(reqBody))
}
if cfg.DumpResponseBody {
log = log.WithField("debug_response_body", string(resBody))
log = log.With("debug_response_body", string(resBody))
}
if cfg.DumpRequestHeaders {
log = log.WithField("debug_request_headers", headerToMap(c.Request().Header))
log = log.With("debug_request_headers", headerToMap(c.Request().Header))
}
if cfg.DumpResponseHeaders {
log = log.WithField("debug_response_headers", headerToMap(c.Response().Header()))
log = log.With("debug_response_headers", headerToMap(c.Response().Header()))
}
if cfg.DumpMemoryEvery > 0 && (requestCounter%dumpEveryUint) == 0 {
var ms runtime.MemStats
runtime.ReadMemStats(&ms)
log = log.WithFields(map[string]interface{}{
"memory_alloc": ms.Alloc,
"memory_total_alloc": ms.TotalAlloc,
"memory_sys": ms.Sys,
"memory_mallocs": ms.Mallocs,
"memory_frees": ms.Frees,
"memory_heap_alloc": ms.HeapAlloc,
"memory_heap_sys": ms.HeapSys,
"memory_heap_idle": ms.HeapIdle,
"memory_heap_inuse": ms.HeapInuse,
"memory_heap_released": ms.HeapReleased,
"memory_heap_objects": ms.HeapObjects,
"memory_stack_inuse": ms.StackInuse,
"memory_stack_sys": ms.StackSys,
"memory_other_sys": ms.OtherSys,
"memory_next_gc": ms.NextGC,
"memory_last_gc": ms.LastGC,
"memory_pause_total_ns": ms.PauseTotalNs,
"memory_num_gc": ms.NumGC,
})
log = log.With(
"memory_alloc", ms.Alloc,
"memory_total_alloc", ms.TotalAlloc,
"memory_sys", ms.Sys,
"memory_mallocs", ms.Mallocs,
"memory_frees", ms.Frees,
"memory_heap_alloc", ms.HeapAlloc,
"memory_heap_sys", ms.HeapSys,
"memory_heap_idle", ms.HeapIdle,
"memory_heap_inuse", ms.HeapInuse,
"memory_heap_released", ms.HeapReleased,
"memory_heap_objects", ms.HeapObjects,
"memory_stack_inuse", ms.StackInuse,
"memory_stack_sys", ms.StackSys,
"memory_other_sys", ms.OtherSys,
"memory_next_gc", ms.NextGC,
"memory_last_gc", ms.LastGC,
"memory_pause_total_ns", ms.PauseTotalNs,
"memory_num_gc", ms.NumGC,
)
}
log.Debug("request_debug")
})
Expand Down
Loading

0 comments on commit 490ca58

Please sign in to comment.