Start switching to use slog

.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

cmd/courier/main.go

@@ -1,13 +1,15 @@
 package main
 
 import (
+	"log/slog"
 	"os"
 	"os/signal"
 	"syscall"
 
 	"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,26 +109,31 @@ 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)
 	}
 
 	// 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()
+
 }

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

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=

handlers/jiochat/handler_test.go

@@ -5,6 +5,7 @@ import (
 	"crypto/sha1"
 	"encoding/hex"
 	"io"
+	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
@@ -260,8 +261,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"

handlers/test.go

@@ -6,6 +6,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"log/slog"
 	"mime/multipart"
 	"net/http"
 	"net/http/httptest"
@@ -147,8 +148,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()

handlers/wechat/handler_test.go

@@ -5,6 +5,7 @@ import (
 	"crypto/sha1"
 	"encoding/hex"
 	"io"
+	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
@@ -212,8 +213,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"

queue/queue.go

@@ -1,12 +1,12 @@
 package queue
 
 import (
+	"log/slog"
 	"strconv"
 	"sync"
 	"time"
 
 	"github.com/gomodule/redigo/redis"
-	"github.com/sirupsen/logrus"
 )
 
 // Priority represents the priority of an item in a queue
@@ -201,7 +201,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 popping from queue", "error", err)
 		return "", "", err
 	}
 	return WorkerToken(values[0]), values[1], nil
@@ -275,7 +275,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()
 

server.go

@@ -6,6 +6,7 @@ import (
 	"context"
 	"fmt"
 	"log"
+	"log/slog"
 	"net/http"
 	"os"
 	"runtime/debug"
@@ -56,13 +57,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)

server_test.go

@@ -1,6 +1,7 @@
 package courier_test
 
 import (
+	"log/slog"
 	"net/http"
 	"strings"
 	"testing"
@@ -10,13 +11,12 @@ import (
 	"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 +89,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"
 

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