Replace logrus with slog (#617)

Currently, we use both our own github.com/ubuntu/authd/internal/log
package (with logrus as the backend) and log/slog in authd. We want to
use slog as the backend for out custom log package and consistently use
that (instead of mixing uses of the custom log package and direct uses
of slog).

UDENG-4622

cmd/authd/daemon/config.go

@@ -87,18 +87,13 @@ func installConfigFlag(cmd *cobra.Command) *string {
 
 // SetVerboseMode change ErrorFormat and logs between very, middly and non verbose.
 func setVerboseMode(level int) {
-	var reportCaller bool
 	switch level {
 	case 0:
 		log.SetLevel(consts.DefaultLogLevel)
 	case 1:
 		log.SetLevel(log.InfoLevel)
-	case 3:
-		reportCaller = true
-		fallthrough
 	default:
 		log.SetLevel(log.DebugLevel)
 		slog.SetLogLoggerLevel(slog.LevelDebug)
 	}
-	log.SetReportCaller(reportCaller)
 }

cmd/authd/main.go

@@ -32,15 +32,6 @@ type app interface {
 func run(a app) int {
 	defer installSignalHandler(a)()
 
-	log.SetFormatter(&log.TextFormatter{
-		DisableLevelTruncation: true,
-		DisableTimestamp:       true,
-
-		// ForceColors is necessary on Windows, not only to have colors but to
-		// prevent logrus from falling back to structured logs.
-		ForceColors: true,
-	})
-
 	if err := a.Run(); err != nil {
 		log.Error(context.Background(), err)
 

go.mod

@@ -11,7 +11,6 @@ require (
 	github.com/google/uuid v1.6.0
 	github.com/msteinert/pam/v2 v2.0.0
 	github.com/muesli/termenv v0.15.2
-	github.com/sirupsen/logrus v1.9.3
 	github.com/skip2/go-qrcode v0.0.0-20200617195104-da1b6568686e
 	github.com/spf13/cobra v1.8.1
 	github.com/spf13/viper v1.19.0
@@ -51,6 +50,7 @@ require (
 	github.com/sagikazarmark/locafero v0.4.0 // indirect
 	github.com/sagikazarmark/slog-shim v0.1.0 // indirect
 	github.com/sahilm/fuzzy v0.1.1 // indirect
+	github.com/sirupsen/logrus v1.9.3 // indirect
 	github.com/sourcegraph/conc v0.3.0 // indirect
 	github.com/spf13/afero v1.11.0 // indirect
 	github.com/spf13/cast v1.6.0 // indirect

internal/consts/consts.go

@@ -1,7 +1,7 @@
 // Package consts defines the constants used by the project
 package consts
 
-import log "github.com/sirupsen/logrus"
+import log "github.com/ubuntu/authd/internal/log"
 
 var (
 	// Version is the version of the executable.

internal/log/log.go

@@ -4,65 +4,97 @@ package log
 import (
 	"context"
 	"fmt"
+	"io"
+	"log/slog"
 	"maps"
 	"sync"
-
-	"github.com/sirupsen/logrus"
+	"sync/atomic"
 )
 
 type (
-	// TextFormatter is the text formatter for the logs.
-	TextFormatter = logrus.TextFormatter
-
 	// Level is the log level for the logs.
-	Level = logrus.Level
+	Level = slog.Level
 
 	// Handler is the log handler function.
 	Handler = func(_ context.Context, _ Level, format string, args ...interface{})
 )
 
-var (
-	// GetLevel gets the standard logger level.
-	GetLevel = logrus.GetLevel
-	// IsLevelEnabled checks if the log level is greater than the level param.
-	IsLevelEnabled = logrus.IsLevelEnabled
-	// SetFormatter sets the standard logger formatter.
-	SetFormatter = logrus.SetFormatter
-	// SetLevel sets the standard logger level.
-	SetLevel = logrus.SetLevel
-	// SetOutput sets the log output.
-	SetOutput = logrus.SetOutput
-	// SetReportCaller sets whether the standard logger will include the calling method as a field.
-	SetReportCaller = logrus.SetReportCaller
-)
+var logLevelMu = sync.RWMutex{}
+var logLevel slog.Level
+
+var hasCustomOutput atomic.Pointer[io.Writer]
 
 const (
 	// ErrorLevel level. Logs. Used for errors that should definitely be noted.
 	// Commonly used for hooks to send errors to an error tracking service.
-	ErrorLevel = logrus.ErrorLevel
+	ErrorLevel = slog.LevelError
 	// WarnLevel level. Non-critical entries that deserve eyes.
-	WarnLevel = logrus.WarnLevel
+	WarnLevel = slog.LevelWarn
 	// InfoLevel level. General operational entries about what's going on inside the application.
-	InfoLevel = logrus.InfoLevel
+	InfoLevel = slog.LevelInfo
 	// DebugLevel level. Usually only enabled when debugging. Very verbose logging.
-	DebugLevel = logrus.DebugLevel
+	DebugLevel = slog.LevelDebug
 )
 
-func logFuncAdapter(logrusFunc func(args ...interface{})) Handler {
-	return func(_ context.Context, _ Level, format string, args ...interface{}) {
-		logrusFunc(fmt.Sprintf(format, args...))
+func logFuncAdapter(slogFunc func(ctx context.Context, msg string, args ...interface{})) Handler {
+	return func(ctx context.Context, _ Level, format string, args ...interface{}) {
+		slogFunc(ctx, fmt.Sprintf(format, args...))
 	}
 }
 
+var allLevels = []slog.Level{
+	slog.LevelDebug,
+	slog.LevelInfo,
+	slog.LevelWarn,
+	slog.LevelError,
+}
+
 var defaultHandlers = map[Level]Handler{
-	DebugLevel: logFuncAdapter(logrus.Debug),
-	InfoLevel:  logFuncAdapter(logrus.Info),
-	WarnLevel:  logFuncAdapter(logrus.Warn),
-	ErrorLevel: logFuncAdapter(logrus.Error),
+	DebugLevel: logFuncAdapter(slog.DebugContext),
+	InfoLevel:  logFuncAdapter(slog.InfoContext),
+	WarnLevel:  logFuncAdapter(slog.WarnContext),
+	ErrorLevel: logFuncAdapter(slog.ErrorContext),
 }
 var handlers = maps.Clone(defaultHandlers)
 var handlersMu = sync.RWMutex{}
 
+// GetLevel gets the standard logger level.
+func GetLevel() Level {
+	logLevelMu.RLock()
+	defer logLevelMu.RUnlock()
+	return logLevel
+}
+
+// IsLevelEnabled checks if the log level is greater than the level param.
+func IsLevelEnabled(level Level) bool {
+	return isLevelEnabled(context.Background(), level)
+}
+
+func isLevelEnabled(context context.Context, level Level) bool {
+	return slog.Default().Enabled(context, level)
+}
+
+// SetLevel sets the standard logger level.
+func SetLevel(level Level) (oldLevel Level) {
+	logLevelMu.Lock()
+	defer func() {
+		logLevelMu.Unlock()
+		if outPtr := hasCustomOutput.Load(); outPtr != nil {
+			SetOutput(*outPtr)
+		}
+	}()
+	logLevel = level
+	return slog.SetLogLoggerLevel(level)
+}
+
+// SetOutput sets the log output.
+func SetOutput(out io.Writer) {
+	hasCustomOutput.Store(&out)
+	slog.SetDefault(slog.New(slog.NewTextHandler(out, &slog.HandlerOptions{
+		Level: GetLevel(),
+	})))
+}
+
 // SetLevelHandler allows to define the default handler function for a given level.
 func SetLevelHandler(level Level, handler Handler) {
 	handlersMu.Lock()
@@ -85,21 +117,21 @@ func SetHandler(handler Handler) {
 		handlers = maps.Clone(defaultHandlers)
 		return
 	}
-	for _, level := range logrus.AllLevels {
+	for _, level := range allLevels {
 		handlers[level] = handler
 	}
 }
 
 func log(context context.Context, level Level, args ...interface{}) {
-	if !IsLevelEnabled(level) {
+	if !isLevelEnabled(context, level) {
 		return
 	}
 
 	logf(context, level, fmt.Sprint(args...))
 }
 
 func logf(context context.Context, level Level, format string, args ...interface{}) {
-	if !IsLevelEnabled(level) {
+	if !isLevelEnabled(context, level) {
 		return
 	}
 

internal/log/log_test.go

@@ -10,10 +10,10 @@ import (
 )
 
 var supportedLevels = []log.Level{
-	log.ErrorLevel,
-	log.WarnLevel,
-	log.InfoLevel,
 	log.DebugLevel,
+	log.InfoLevel,
+	log.WarnLevel,
+	log.ErrorLevel,
 }
 
 func TestLevelEnabled(t *testing.T) {
@@ -146,17 +146,22 @@ func TestSetHandler(t *testing.T) {
 		require.Equal(t, wantLevel, l, "Log level should match %v", l)
 		require.Equal(t, fmt.Sprint(wantArgs...), format, "Format should match")
 	})
-	for _, level := range supportedLevels {
+	for idx, level := range supportedLevels {
 		t.Run(fmt.Sprintf("Set log handler, testing level %s", level), func(t *testing.T) {})
 
 		wantLevel = level
 		handlerCalled = false
 		log.SetLevel(level)
+		fmt.Println("Logging at level", level)
 		callLogHandler(wantCtx, level, wantArgs...)
 		require.True(t, handlerCalled, "Handler should have been called")
 
 		handlerCalled = false
-		log.SetLevel(level - 1)
+		nextLevel := level + 1
+		if idx < len(supportedLevels)-1 {
+			nextLevel = supportedLevels[idx+1]
+		}
+		log.SetLevel(nextLevel)
 		callLogHandler(wantCtx, level, wantArgs...)
 		require.False(t, handlerCalled, "Handler should not have been called")
 	}
@@ -180,7 +185,7 @@ func TestSetHandler(t *testing.T) {
 		require.Equal(t, wantFormat, format, "Format should match")
 		require.Equal(t, wantArgs, args, "Arguments should match")
 	})
-	for _, level := range supportedLevels {
+	for idx, level := range supportedLevels {
 		t.Run(fmt.Sprintf("Set log handler, testing level %s", level), func(t *testing.T) {})
 
 		wantLevel = level
@@ -190,7 +195,11 @@ func TestSetHandler(t *testing.T) {
 		require.True(t, handlerCalled, "Handler should have been called")
 
 		handlerCalled = false
-		log.SetLevel(level - 1)
+		nextLevel := level + 1
+		if idx < len(supportedLevels)-1 {
+			nextLevel = supportedLevels[idx+1]
+		}
+		log.SetLevel(nextLevel)
 		callLogHandlerf(wantCtx, level, wantFormat, wantArgs...)
 		require.False(t, handlerCalled, "Handler should not have been called")
 	}

internal/services/errmessages/redactor.go

@@ -5,8 +5,8 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log/slog"
 
+	"github.com/ubuntu/authd/internal/log"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/status"
@@ -18,7 +18,7 @@ import (
 func RedactErrorInterceptor(ctx context.Context, req any, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) {
 	m, err := handler(ctx, req)
 	if err != nil {
-		slog.Warn(err.Error())
+		log.Warning(context.TODO(), err.Error())
 		var redactedError ErrToDisplay
 		if !errors.As(err, &redactedError) {
 			return m, err

internal/services/manager.go

@@ -3,7 +3,6 @@ package services
 
 import (
 	"context"
-	"log/slog"
 
 	"github.com/ubuntu/authd"
 	"github.com/ubuntu/authd/internal/brokers"
@@ -69,7 +68,7 @@ func (m Manager) RegisterGRPCServices(ctx context.Context) *grpc.Server {
 
 // stop stops the underlying cache.
 func (m *Manager) stop() error {
-	slog.Debug("Closing grpc manager and cache")
+	log.Debug(context.TODO(), "Closing grpc manager and cache")
 
 	return m.userManager.Stop()
 }

internal/users/cache/delete.go

@@ -1,13 +1,14 @@
 package cache
 
 import (
+	"context"
 	"encoding/json"
 	"errors"
 	"fmt"
-	"log/slog"
 	"slices"
 	"strconv"
 
+	"github.com/ubuntu/authd/internal/log"
 	"github.com/ubuntu/decorate"
 	"go.etcd.io/bbolt"
 )
@@ -107,7 +108,7 @@ func deleteUser(buckets map[string]bucketWithName, uid uint32) (err error) {
 
 // deleteOrphanedUsers removes users from the UserByID bucket that are not in the UserByName bucket.
 func deleteOrphanedUsers(db *bbolt.DB) error {
-	slog.Debug("Cleaning up orphaned user records")
+	log.Debug(context.TODO(), "Cleaning up orphaned user records")
 
 	err := db.Update(func(tx *bbolt.Tx) error {
 		buckets, err := getAllBuckets(tx)
@@ -118,17 +119,17 @@ func deleteOrphanedUsers(db *bbolt.DB) error {
 		return buckets[userByIDBucketName].ForEach(func(k, v []byte) error {
 			var user UserDB
 			if err := json.Unmarshal(v, &user); err != nil {
-				slog.Warn(fmt.Sprintf("Error loading user record {%s: %s}: %v", string(k), string(v), err))
+				log.Warningf(context.TODO(), "Error loading user record {%s: %s}: %v", k, v, err)
 				return nil
 			}
 
 			user2, err := getFromBucket[userDB](buckets[userByNameBucketName], user.Name)
 			if err != nil && !errors.Is(err, NoDataFoundError{}) {
-				slog.Warn(fmt.Sprintf("Error loading user record %q: %v", user.Name, err))
+				log.Warningf(context.TODO(), "Error loading user record %q: %v", user.Name, err)
 				return nil
 			}
 			if errors.Is(err, NoDataFoundError{}) || user2.UID != user.UID {
-				slog.Warn(fmt.Sprintf("Removing orphaned user record %q with UID %d", user.Name, user.UID))
+				log.Warningf(context.TODO(), "Removing orphaned user record %q with UID %d", user.Name, user.UID)
 				return deleteOrphanedUser(buckets, user.UID)
 			}
 
@@ -139,7 +140,7 @@ func deleteOrphanedUsers(db *bbolt.DB) error {
 		return err
 	}
 
-	slog.Debug("Done cleaning up orphaned user records")
+	log.Debug(context.TODO(), "Done cleaning up orphaned user records")
 	return nil
 }
 

internal/users/cache/update.go

@@ -5,7 +5,6 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
-	"log/slog"
 	"slices"
 	"strconv"
 	"time"
@@ -66,13 +65,13 @@ func updateUser(buckets map[string]bucketWithName, userContent userDB) error {
 
 	// If a user with the same UID exists, we need to ensure that it's the same user or fail the update otherwise.
 	if existingUser.Name != "" && existingUser.Name != userContent.Name {
-		slog.Error(fmt.Sprintf("UID for user %q already in use by user %q", userContent.Name, existingUser.Name))
+		log.Errorf(context.TODO(), "UID for user %q already in use by user %q", userContent.Name, existingUser.Name)
 		return errors.New("UID already in use by a different user")
 	}
 
 	// Ensure that we use the same homedir as the one we have in cache.
 	if existingUser.Dir != "" && existingUser.Dir != userContent.Dir {
-		slog.Warn(fmt.Sprintf("User %q already has a homedir. The existing %q one will be kept instead of %q", userContent.Name, existingUser.Dir, userContent.Dir))
+		log.Warningf(context.TODO(), "User %q already has a homedir. The existing %q one will be kept instead of %q", userContent.Name, existingUser.Dir, userContent.Dir)
 		userContent.Dir = existingUser.Dir
 	}
 
@@ -94,7 +93,7 @@ func updateGroups(buckets map[string]bucketWithName, groupContents []GroupDB) er
 
 		// If a group with the same GID exists, we need to ensure that it's the same group or fail the update otherwise.
 		if existingGroup.Name != "" && existingGroup.Name != groupContent.Name {
-			slog.Error(fmt.Sprintf("GID %d for group %q already in use by group %q", groupContent.GID, groupContent.Name, existingGroup.Name))
+			log.Errorf(context.TODO(), "GID %d for group %q already in use by group %q", groupContent.GID, groupContent.Name, existingGroup.Name)
 			return fmt.Errorf("GID for group %q already in use by a different group", groupContent.Name)
 		}