From 64470aa6dda800b5134be1d1c2bc7b498cec67ec Mon Sep 17 00:00:00 2001 From: Norbert Kwizera Date: Fri, 6 Oct 2023 12:26:43 +0200 Subject: [PATCH] Start switching to use slog --- .github/workflows/ci.yml | 2 +- cmd/courier/main.go | 26 ++++++--- go.mod | 2 +- go.sum | 2 + handlers/jiochat/handler_test.go | 5 +- handlers/test.go | 5 +- handlers/wechat/handler_test.go | 5 +- queue/queue.go | 7 +-- server.go | 6 ++- server_test.go | 7 +-- utils/logrus.go | 92 ++++++++++++++++++++++++++++++++ 11 files changed, 137 insertions(+), 22 deletions(-) create mode 100644 utils/logrus.go diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 283974b5b..d359379ef 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -1,7 +1,7 @@ name: CI on: [push, pull_request] env: - go-version: "1.20.x" + go-version: "1.21.x" jobs: test: name: Test diff --git a/cmd/courier/main.go b/cmd/courier/main.go index 467fb7572..577a2e89c 100644 --- a/cmd/courier/main.go +++ b/cmd/courier/main.go @@ -1,6 +1,7 @@ package main import ( + "log/slog" "os" "os/signal" "syscall" @@ -8,6 +9,7 @@ import ( "github.com/evalphobia/logrus_sentry" _ "github.com/lib/pq" "github.com/nyaruka/courier" + "github.com/nyaruka/courier/utils" "github.com/sirupsen/logrus" // load channel handler packages @@ -88,10 +90,17 @@ func main() { logrus.SetOutput(os.Stdout) level, err := logrus.ParseLevel(config.LogLevel) if err != nil { - logrus.Fatalf("Invalid log level '%s'", level) + slog.Error("invalid log level", "level", level) + os.Exit(1) } logrus.SetLevel(level) + // configure golang std structured logging to route to logrus + slog.SetDefault(slog.New(utils.NewLogrusHandler(logrus.StandardLogger()))) + + log := slog.With("comp", "main") + log.Info("starting courier", "version", version) + // if we have a DSN entry, try to initialize it if config.SentryDSN != "" { hook, err := logrus_sentry.NewSentryHook(config.SentryDSN, []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel}) @@ -100,7 +109,8 @@ func main() { hook.StacktraceConfiguration.Skip = 4 hook.StacktraceConfiguration.Context = 5 if err != nil { - logrus.Fatalf("Invalid sentry DSN: '%s': %s", config.SentryDSN, err) + log.Error("unable to configure sentry hook", "dsn", config.SentryDSN, "error", err) + os.Exit(1) } logrus.StandardLogger().Hooks.Add(hook) } @@ -108,18 +118,22 @@ func main() { // load our backend backend, err := courier.NewBackend(config) if err != nil { - logrus.Fatalf("Error creating backend: %s", err) + log.Error("error creating backend", "error", err) + os.Exit(1) } server := courier.NewServer(config, backend) err = server.Start() if err != nil { - logrus.Fatalf("Error starting server: %s", err) + log.Error("unable to start server", "error", err) + os.Exit(1) } - ch := make(chan os.Signal) + ch := make(chan os.Signal, 1) signal.Notify(ch, syscall.SIGINT, syscall.SIGTERM) - logrus.WithField("comp", "main").WithField("signal", <-ch).Info("stopping") + slog.Info("stopping", "comp", "main", "signal", <-ch) + logrus.WithField("comp", "main").WithField("signal", <-ch) server.Stop() + } diff --git a/go.mod b/go.mod index 4fe048ab5..70ee91d1d 100644 --- a/go.mod +++ b/go.mod @@ -1,6 +1,6 @@ module github.com/nyaruka/courier -go 1.20 +go 1.21 require ( github.com/antchfx/xmlquery v1.3.17 diff --git a/go.sum b/go.sum index 6a187c876..602b309d8 100644 --- a/go.sum +++ b/go.sum @@ -25,6 +25,7 @@ github.com/getsentry/raven-go v0.2.0/go.mod h1:KungGk8q33+aIAZUIVWZDr2OfAEBsO49P github.com/go-chi/chi v4.1.2+incompatible h1:fGFk2Gmi/YKXk0OmGfBh0WgmN3XB8lVnEyNz34tQRec= github.com/go-chi/chi v4.1.2+incompatible/go.mod h1:eB3wogJHnLi3x/kFX2A+IbTBlXxmMeXJVKy9tTv1XzQ= github.com/go-playground/assert/v2 v2.2.0 h1:JvknZsQTYeFEAhQwI4qEt9cyV5ONwRHC+lYKSsYSR8s= +github.com/go-playground/assert/v2 v2.2.0/go.mod h1:VDjEfimB/XKnb+ZQfWdccd7VUvScMdVu0Titje2rxJ4= github.com/go-playground/locales v0.14.1 h1:EWaQ/wswjilfKLTECiXz7Rh+3BjFhfDFKv/oXslEjJA= github.com/go-playground/locales v0.14.1/go.mod h1:hxrqLVvrK65+Rwrd5Fc6F2O76J/NuW9t0sjnWqG1slY= github.com/go-playground/universal-translator v0.18.1 h1:Bcnm0ZwsGyWbCzImXv+pAJnYK9S473LQFuzCbDbfSFY= @@ -46,6 +47,7 @@ github.com/gomodule/redigo v1.8.9 h1:Sl3u+2BI/kk+VEatbj0scLdrFhjPmbxOc1myhDP41ws github.com/gomodule/redigo v1.8.9/go.mod h1:7ArFNvsTjH8GMMzB4uy1snslv2BwmginuMs06a1uzZE= github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.8 h1:e6P7q2lk1O+qJJb4BtCQXlK8vWEO8V1ZeuEdJNOqZyg= +github.com/google/go-cmp v0.5.8/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/gorilla/schema v1.2.0 h1:YufUaxZYCKGFuAq3c96BOhjgd5nmXiOY9NGzF247Tsc= github.com/gorilla/schema v1.2.0/go.mod h1:kgLaKoK1FELgZqMAVxx/5cbj0kT+57qxUrAlIO2eleU= github.com/jmespath/go-jmespath v0.4.0 h1:BEgLn5cpjn8UN1mAw4NjwDrS35OdebyEtFe+9YPoQUg= diff --git a/handlers/jiochat/handler_test.go b/handlers/jiochat/handler_test.go index 88f36f18e..0a6fca552 100644 --- a/handlers/jiochat/handler_test.go +++ b/handlers/jiochat/handler_test.go @@ -13,6 +13,8 @@ import ( "testing" "time" + "log/slog" + "github.com/nyaruka/courier" . "github.com/nyaruka/courier/handlers" "github.com/nyaruka/courier/test" @@ -260,8 +262,7 @@ func buildMockJCAPI(testCases []IncomingTestCase) *httptest.Server { func newServer(backend courier.Backend) courier.Server { // for benchmarks, log to null - logger := logrus.New() - logger.Out = io.Discard + logger := slog.Default() logrus.SetOutput(io.Discard) config := courier.NewConfig() config.DB = "postgres://courier_test:temba@localhost:5432/courier_test?sslmode=disable" diff --git a/handlers/test.go b/handlers/test.go index e8b212403..2e1b1b022 100644 --- a/handlers/test.go +++ b/handlers/test.go @@ -14,6 +14,8 @@ import ( "testing" "time" + "log/slog" + _ "github.com/lib/pq" // postgres driver "github.com/nyaruka/courier" "github.com/nyaruka/courier/test" @@ -147,8 +149,7 @@ func testHandlerRequest(tb testing.TB, s courier.Server, path string, headers ma func newServer(backend courier.Backend) courier.Server { // for benchmarks, log to null - logger := logrus.New() - logger.Out = io.Discard + logger := slog.Default() logrus.SetOutput(io.Discard) config := courier.NewConfig() diff --git a/handlers/wechat/handler_test.go b/handlers/wechat/handler_test.go index e1d6d1f75..e3438a5b3 100644 --- a/handlers/wechat/handler_test.go +++ b/handlers/wechat/handler_test.go @@ -13,6 +13,8 @@ import ( "testing" "time" + "log/slog" + "github.com/nyaruka/courier" . "github.com/nyaruka/courier/handlers" "github.com/nyaruka/courier/test" @@ -212,8 +214,7 @@ func buildMockWCAPI(testCases []IncomingTestCase) *httptest.Server { func newServer(backend courier.Backend) courier.Server { // for benchmarks, log to null - logger := logrus.New() - logger.Out = io.Discard + logger := slog.Default() logrus.SetOutput(io.Discard) config := courier.NewConfig() config.DB = "postgres://courier_test:temba@localhost:5432/courier_test?sslmode=disable" diff --git a/queue/queue.go b/queue/queue.go index 2dd5b3123..02fabe800 100644 --- a/queue/queue.go +++ b/queue/queue.go @@ -5,8 +5,9 @@ import ( "sync" "time" + "log/slog" + "github.com/gomodule/redigo/redis" - "github.com/sirupsen/logrus" ) // Priority represents the priority of an item in a queue @@ -201,7 +202,7 @@ func PopFromQueue(conn redis.Conn, qType string) (WorkerToken, string, error) { epochMS := strconv.FormatFloat(float64(time.Now().UnixNano()/int64(time.Microsecond))/float64(1000000), 'f', 6, 64) values, err := redis.Strings(luaPop.Do(conn, epochMS, qType)) if err != nil { - logrus.Error(err) + slog.Error("error poping from queue", "error", err) return "", "", err } return WorkerToken(values[0]), values[1], nil @@ -275,7 +276,7 @@ func StartDethrottler(redis *redis.Pool, quitter chan bool, wg *sync.WaitGroup, conn := redis.Get() _, err := luaDethrottle.Do(conn, qType) if err != nil { - logrus.WithError(err).Error("error dethrottling") + slog.Error("error dethrottling", "error", err) } conn.Close() diff --git a/server.go b/server.go index 073eb567c..3ea1a4f27 100644 --- a/server.go +++ b/server.go @@ -14,6 +14,8 @@ import ( "sync" "time" + "log/slog" + "github.com/go-chi/chi" "github.com/go-chi/chi/middleware" "github.com/nyaruka/courier/utils" @@ -56,13 +58,13 @@ type Server interface { // afterwards, which is when configuration options are checked. func NewServer(config *Config, backend Backend) Server { // create our top level router - logger := logrus.New() + logger := slog.Default() return NewServerWithLogger(config, backend, logger) } // NewServerWithLogger creates a new Server for the passed in configuration. The server will have to be started // afterwards, which is when configuration options are checked. -func NewServerWithLogger(config *Config, backend Backend, logger *logrus.Logger) Server { +func NewServerWithLogger(config *Config, backend Backend, logger *slog.Logger) Server { router := chi.NewRouter() router.Use(middleware.Compress(flate.DefaultCompression)) router.Use(middleware.StripSlashes) diff --git a/server_test.go b/server_test.go index da5a12fa9..3f28485d7 100644 --- a/server_test.go +++ b/server_test.go @@ -6,17 +6,18 @@ import ( "testing" "time" + "log/slog" + "github.com/nyaruka/courier" "github.com/nyaruka/courier/test" "github.com/nyaruka/gocommon/httpx" "github.com/nyaruka/gocommon/uuids" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) func TestServer(t *testing.T) { - logger := logrus.New() + logger := slog.Default() config := courier.NewConfig() config.StatusUsername = "admin" config.StatusPassword = "password123" @@ -89,7 +90,7 @@ func TestFetchAttachment(t *testing.T) { defer uuids.SetGenerator(uuids.DefaultGenerator) uuids.SetGenerator(uuids.NewSeededGenerator(1234)) - logger := logrus.New() + logger := slog.Default() config := courier.NewConfig() config.AuthToken = "sesame" diff --git a/utils/logrus.go b/utils/logrus.go new file mode 100644 index 000000000..2650bf9bb --- /dev/null +++ b/utils/logrus.go @@ -0,0 +1,92 @@ +// Structured logging handler for logrus so we can rewrite code to use slog package incrementally. Once all logging is +// happening via slog, we just need to hook up Sentry directly to that, and then we can get rid of this file. +package utils + +import ( + "context" + "log/slog" + "slices" + "strings" + + "github.com/sirupsen/logrus" +) + +var levels = map[slog.Level]logrus.Level{ + slog.LevelError: logrus.ErrorLevel, + slog.LevelWarn: logrus.WarnLevel, + slog.LevelInfo: logrus.InfoLevel, + slog.LevelDebug: logrus.DebugLevel, +} + +type LogrusHandler struct { + logger *logrus.Logger + groups []string + attrs []slog.Attr +} + +func NewLogrusHandler(logger *logrus.Logger) *LogrusHandler { + return &LogrusHandler{logger: logger} +} + +func (l *LogrusHandler) clone() *LogrusHandler { + return &LogrusHandler{ + logger: l.logger, + groups: slices.Clip(l.groups), + attrs: slices.Clip(l.attrs), + } +} + +func (l *LogrusHandler) Enabled(ctx context.Context, level slog.Level) bool { + return levels[level] <= l.logger.GetLevel() +} + +func (l *LogrusHandler) Handle(ctx context.Context, r slog.Record) error { + log := logrus.NewEntry(l.logger) + if r.Time.IsZero() { + log = log.WithTime(r.Time) + } + + f := logrus.Fields{} + for _, a := range l.attrs { + if a.Key != "" { + f[a.Key] = a.Value + } + } + log = log.WithFields(f) + + r.Attrs(func(attr slog.Attr) bool { + if attr.Key == "" { + return true + } + log = log.WithField(attr.Key, attr.Value) + return true + }) + log.Logf(levels[r.Level], r.Message) + return nil +} + +func (l *LogrusHandler) groupPrefix() string { + if len(l.groups) > 0 { + return strings.Join(l.groups, ":") + ":" + } + return "" +} + +func (l *LogrusHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + newHandler := l.clone() + for _, a := range attrs { + newHandler.attrs = append(newHandler.attrs, slog.Attr{ + Key: l.groupPrefix() + a.Key, + Value: a.Value, + }) + } + return newHandler +} + +func (l *LogrusHandler) WithGroup(name string) slog.Handler { + newHandler := l.clone() + newHandler.groups = append(newHandler.groups, name) + return newHandler +} + +var _ slog.Handler = &LogrusHandler{}