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,17 @@
 package main
 
 import (
+	ulog "log"
+	"log/slog"
 	"os"
 	"os/signal"
+	goruntime "runtime"
 	"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 +92,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 +111,48 @@ 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)
-	signal.Notify(ch, syscall.SIGINT, syscall.SIGTERM)
-	logrus.WithField("comp", "main").WithField("signal", <-ch).Info("stopping")
+	handleSignals(server)
+}
+
+// handleSignals takes care of trapping quit, interrupt or terminate signals and doing the right thing
+func handleSignals(server courier.Server) {
+	sigs := make(chan os.Signal, 1)
+	signal.Notify(sigs, syscall.SIGINT, syscall.SIGTERM, syscall.SIGQUIT)
 
-	server.Stop()
+	for {
+		sig := <-sigs
+		log := slog.With("comp", "main", "signal", sig)
+
+		switch sig {
+		case syscall.SIGQUIT:
+			buf := make([]byte, 1<<20)
+			stacklen := goruntime.Stack(buf, true)
+			log.Info("received quit signal, dumping stack")
+			ulog.Printf("\n%s", buf[:stacklen])
+		case syscall.SIGINT, syscall.SIGTERM:
+			log.Info("received exit signal, exiting")
+			server.Stop()
+			return
+		}
+	}
 }

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

@@ -20,6 +20,7 @@ import (
 	"github.com/nyaruka/gocommon/urns"
 	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
+	"golang.org/x/exp/slog"
 )
 
 var testChannels = []courier.Channel{
@@ -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

@@ -23,6 +23,7 @@ import (
 	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"golang.org/x/exp/slog"
 )
 
 // RequestPrepFunc is our type for a hook for tests to use before a request is fired in a test
@@ -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

@@ -20,6 +20,7 @@ import (
 	"github.com/nyaruka/gocommon/urns"
 	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
+	"golang.org/x/exp/slog"
 )
 
 var testChannels = []courier.Channel{
@@ -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

@@ -6,7 +6,7 @@ import (
 	"time"
 
 	"github.com/gomodule/redigo/redis"
-	"github.com/sirupsen/logrus"
+	"golang.org/x/exp/slog"
 )
 
 // 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 poping 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

@@ -22,6 +22,7 @@ import (
 	"github.com/nyaruka/gocommon/jsonx"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
+	"golang.org/x/exp/slog"
 )
 
 // for use in request.Context
@@ -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

@@ -10,13 +10,13 @@ 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"
+	"golang.org/x/exp/slog"
 )
 
 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"