Chore: Logging improvements (#44925)

Fixing a couple bugs, adds some tests and hopefully decrease 
lock contention when logging.
Switching from using sync.RWMutex to go-kit SwapLogger.
Fixes bug when creating a new logger from an existing one that 
screwed up the keyvals and/or lost the logger name. 

Ref #44681

pkg/api/frontend_logging_test.go

@@ -42,11 +42,11 @@ func logSentryEventScenario(t *testing.T, desc string, event frontendlogging.Fro
 		}))
 
 		origHandler := frontendLogger.GetLogger()
-		frontendLogger.SetLogger(level.NewFilter(newfrontendLogger, level.AllowInfo()))
+		frontendLogger.Swap(level.NewFilter(newfrontendLogger, level.AllowInfo()))
 		sourceMapReads := []SourceMapReadRecord{}
 
 		t.Cleanup(func() {
-			frontendLogger.SetLogger(origHandler)
+			frontendLogger.Swap(origHandler)
 		})
 
 		sc := setupScenarioContext(t, "/log")

pkg/infra/log/composite_logger_test.go

@@ -0,0 +1,25 @@
+package log
+
+import (
+	"testing"
+
+	gokitlog "github.com/go-kit/log"
+	"github.com/stretchr/testify/require"
+)
+
+func TestCompositeLogger(t *testing.T) {
+	loggedArgs := [][]interface{}{}
+	l := gokitlog.LoggerFunc(func(i ...interface{}) error {
+		loggedArgs = append(loggedArgs, i)
+		return nil
+	})
+
+	cl := newCompositeLogger(l, l, l)
+	require.NotNil(t, cl)
+
+	err := cl.Log("msg", "hello")
+	require.NoError(t, err)
+	require.Len(t, loggedArgs, 3)
+	require.Equal(t, "msg", loggedArgs[0][0].(string))
+	require.Equal(t, "hello", loggedArgs[0][1].(string))
+}

pkg/infra/log/log.go

@@ -7,7 +7,6 @@ package log
 import (
 	"fmt"
 	"io"
-	"log"
 	"os"
 	"path/filepath"
 	"sort"
@@ -17,18 +16,20 @@ import (
 
 	gokitlog "github.com/go-kit/log"
 	"github.com/go-stack/stack"
-	"github.com/mattn/go-isatty"
-	"gopkg.in/ini.v1"
-
 	"github.com/grafana/grafana/pkg/infra/log/level"
 	"github.com/grafana/grafana/pkg/infra/log/term"
 	"github.com/grafana/grafana/pkg/util"
 	"github.com/grafana/grafana/pkg/util/errutil"
+	"github.com/mattn/go-isatty"
+	"gopkg.in/ini.v1"
 )
 
-var loggersToClose []DisposableHandler
+var (
-var loggersToReload []ReloadableHandler
+	loggersToClose  []DisposableHandler
-var root *logManager
+	loggersToReload []ReloadableHandler
+	root            *logManager
+	now             = time.Now
+)
 
 const (
 	// top 7 calls in the stack are within logger
@@ -50,7 +51,7 @@ func init() {
 type logManager struct {
 	*ConcreteLogger
 	loggersByName map[string]*ConcreteLogger
-	logFilters    []LogWithFilters
+	logFilters    []logWithFilters
 	mutex         sync.RWMutex
 }
 
@@ -61,7 +62,7 @@ func newManager(logger gokitlog.Logger) *logManager {
 	}
 }
 
-func (lm *logManager) initialize(loggers []LogWithFilters) {
+func (lm *logManager) initialize(loggers []logWithFilters) {
 	lm.mutex.Lock()
 	defer lm.mutex.Unlock()
 
@@ -70,7 +71,7 @@ func (lm *logManager) initialize(loggers []LogWithFilters) {
 		defaultLoggers[index] = level.NewFilter(logger.val, logger.maxLevel)
 	}
 
-	lm.ConcreteLogger.SetLogger(&compositeLogger{loggers: defaultLoggers})
+	lm.ConcreteLogger.Swap(&compositeLogger{loggers: defaultLoggers})
 	lm.logFilters = loggers
 
 	loggersByName := []string{}
@@ -83,43 +84,27 @@ func (lm *logManager) initialize(loggers []LogWithFilters) {
 		ctxLoggers := make([]gokitlog.Logger, len(loggers))
 
 		for index, logger := range loggers {
+			ctxLogger := gokitlog.With(logger.val, lm.loggersByName[name].ctx...)
 			if filterLevel, exists := logger.filters[name]; !exists {
-				ctxLoggers[index] = level.NewFilter(logger.val, logger.maxLevel)
+				ctxLoggers[index] = level.NewFilter(ctxLogger, logger.maxLevel)
 			} else {
-				ctxLoggers[index] = level.NewFilter(logger.val, filterLevel)
+				ctxLoggers[index] = level.NewFilter(ctxLogger, filterLevel)
-			}
 			}
-
-		lm.loggersByName[name].SetLogger(&compositeLogger{loggers: ctxLoggers})
-	}
-}
-
-func (lm *logManager) SetLogger(logger gokitlog.Logger) {
-	lm.ConcreteLogger.SetLogger(logger)
-}
-
-func (lm *logManager) GetLogger() gokitlog.Logger {
-	return lm.ConcreteLogger.GetLogger()
 		}
 
-func (lm *logManager) Log(args ...interface{}) error {
+		lm.loggersByName[name].Swap(&compositeLogger{loggers: ctxLoggers})
-	lm.mutex.RLock()
-	defer lm.mutex.RUnlock()
-	if err := lm.ConcreteLogger.Log(args...); err != nil {
-		log.Println("Logging error", "error", err)
 	}
-
-	return nil
 }
 
 func (lm *logManager) New(ctx ...interface{}) *ConcreteLogger {
-	lm.mutex.Lock()
-	defer lm.mutex.Unlock()
 	if len(ctx) == 0 {
 		return lm.ConcreteLogger
 	}
 
-	loggerName, ok := ctx[0].(string)
+	lm.mutex.Lock()
+	defer lm.mutex.Unlock()
+
+	loggerName, ok := ctx[1].(string)
 	if !ok {
 		return lm.ConcreteLogger
 	}
@@ -128,10 +113,8 @@ func (lm *logManager) New(ctx ...interface{}) *ConcreteLogger {
 		return logger
 	}
 
-	ctx = append([]interface{}{"logger"}, ctx...)
-
 	if len(lm.logFilters) == 0 {
-		ctxLogger := newConcreteLogger(lm.logger, ctx...)
+		ctxLogger := newConcreteLogger(&lm.SwapLogger, ctx...)
 		lm.loggersByName[loggerName] = ctxLogger
 		return ctxLogger
 	}
@@ -155,33 +138,27 @@ func (lm *logManager) New(ctx ...interface{}) *ConcreteLogger {
 
 type ConcreteLogger struct {
 	ctx []interface{}
-	logger gokitlog.Logger
+	gokitlog.SwapLogger
-	mutex  sync.RWMutex
 }
 
 func newConcreteLogger(logger gokitlog.Logger, ctx ...interface{}) *ConcreteLogger {
+	var swapLogger gokitlog.SwapLogger
+
 	if len(ctx) == 0 {
 		ctx = []interface{}{}
+		swapLogger.Swap(logger)
 	} else {
-		logger = gokitlog.With(logger, ctx...)
+		swapLogger.Swap(gokitlog.With(logger, ctx...))
 	}
 
 	return &ConcreteLogger{
 		ctx:        ctx,
-		logger: logger,
+		SwapLogger: swapLogger,
-	}
 	}
-
-func (cl *ConcreteLogger) SetLogger(logger gokitlog.Logger) {
-	cl.mutex.Lock()
-	cl.logger = gokitlog.With(logger, cl.ctx...)
-	cl.mutex.Unlock()
 }
 
-func (cl *ConcreteLogger) GetLogger() gokitlog.Logger {
+func (cl ConcreteLogger) GetLogger() gokitlog.Logger {
-	cl.mutex.Lock()
+	return &cl.SwapLogger
-	defer cl.mutex.Unlock()
-	return cl.logger
 }
 
 func (cl *ConcreteLogger) Warn(msg string, args ...interface{}) {
@@ -189,7 +166,6 @@ func (cl *ConcreteLogger) Warn(msg string, args ...interface{}) {
 }
 
 func (cl *ConcreteLogger) Debug(msg string, args ...interface{}) {
-	// args = append([]interface{}{level.Key(), level.DebugValue(), "msg", msg}, args...)
 	_ = cl.log(msg, level.DebugValue(), args...)
 }
 
@@ -202,55 +178,27 @@ func (cl *ConcreteLogger) Info(msg string, args ...interface{}) {
 }
 
 func (cl *ConcreteLogger) log(msg string, logLevel level.Value, args ...interface{}) error {
-	cl.mutex.RLock()
+	logger := gokitlog.With(&cl.SwapLogger, "t", gokitlog.TimestampFormat(now, "2006-01-02T15:04:05.99-0700"))
-	logger := gokitlog.With(cl.logger, "t", gokitlog.TimestampFormat(time.Now, "2006-01-02T15:04:05.99-0700"))
-	cl.mutex.RUnlock()
-
 	args = append([]interface{}{level.Key(), logLevel, "msg", msg}, args...)
 
 	return logger.Log(args...)
 }
 
-func (cl *ConcreteLogger) Log(keyvals ...interface{}) error {
-	cl.mutex.RLock()
-	defer cl.mutex.RUnlock()
-	return cl.logger.Log(keyvals...)
-}
-
 func (cl *ConcreteLogger) New(ctx ...interface{}) *ConcreteLogger {
 	if len(ctx) == 0 {
 		root.New()
 	}
 
-	keyvals := []interface{}{}
+	return newConcreteLogger(gokitlog.With(&cl.SwapLogger), ctx...)
-
-	if len(cl.ctx)%2 == 1 {
-		cl.ctx = append(cl.ctx, nil)
-	}
-
-	for i := 0; i < len(cl.ctx); i += 2 {
-		k, v := cl.ctx[i], cl.ctx[i+1]
-
-		if k == "logger" {
-			continue
-		}
-
-		keyvals = append(keyvals, k, v)
-	}
-
-	keyvals = append(keyvals, ctx...)
-
-	return root.New(keyvals...)
 }
 
 func New(ctx ...interface{}) *ConcreteLogger {
-	return root.New(ctx...)
+	if len(ctx) == 0 {
+		return root.New()
 	}
 
-type LogWithFilters struct {
+	ctx = append([]interface{}{"logger"}, ctx...)
-	val      gokitlog.Logger
+	return root.New(ctx...)
-	filters  map[string]level.Option
-	maxLevel level.Option
 }
 
 func with(ctxLogger *ConcreteLogger, withFunc func(gokitlog.Logger, ...interface{}) gokitlog.Logger, ctx []interface{}) *ConcreteLogger {
@@ -258,7 +206,7 @@ func with(ctxLogger *ConcreteLogger, withFunc func(gokitlog.Logger, ...interface
 		return ctxLogger
 	}
 
-	ctxLogger.logger = withFunc(ctxLogger.logger, ctx...)
+	ctxLogger.Swap(withFunc(&ctxLogger.SwapLogger, ctx...))
 	return ctxLogger
 }
 
@@ -384,6 +332,12 @@ func Reload() error {
 	return nil
 }
 
+type logWithFilters struct {
+	val      gokitlog.Logger
+	filters  map[string]level.Option
+	maxLevel level.Option
+}
+
 func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) error {
 	if err := Close(); err != nil {
 		return err
@@ -392,7 +346,7 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) error {
 	defaultLevelName, _ := getLogLevelFromConfig("log", "info", cfg)
 	defaultFilters := getFilters(util.SplitString(cfg.Section("log").Key("filters").String()))
 
-	var configLoggers []LogWithFilters
+	var configLoggers []logWithFilters
 	for _, mode := range modes {
 		mode = strings.TrimSpace(mode)
 		sec, err := cfg.GetSection("log." + mode)
@@ -407,7 +361,7 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) error {
 
 		format := getLogFormat(sec.Key("format").MustString(""))
 
-		var handler LogWithFilters
+		var handler logWithFilters
 
 		switch mode {
 		case "console":

pkg/infra/log/log_test.go

@@ -0,0 +1,109 @@
+package log
+
+import (
+	"fmt"
+	"testing"
+	"time"
+
+	gokitlog "github.com/go-kit/log"
+	"github.com/grafana/grafana/pkg/infra/log/level"
+	"github.com/stretchr/testify/require"
+)
+
+func TestLogger(t *testing.T) {
+	t.Run("Root logger should be initialized", func(t *testing.T) {
+		require.NotNil(t, root)
+		err := root.Log("msg", "hello")
+		require.NoError(t, err)
+	})
+
+	t.Run("When creating root logger should log as expected", func(t *testing.T) {
+		loggedArgs := [][]interface{}{}
+		l := gokitlog.LoggerFunc(func(i ...interface{}) error {
+			loggedArgs = append(loggedArgs, i)
+			return nil
+		})
+
+		mockedTime := time.Now()
+		origNow := now
+		now = func() time.Time {
+			return mockedTime
+		}
+		t.Cleanup(func() {
+			now = origNow
+		})
+
+		root = newManager(l)
+		log1 := New("one")
+		err := log1.Log("msg", "hello 1")
+		require.NoError(t, err)
+		log2 := New("two")
+		err = log2.Log("msg", "hello 2")
+		require.NoError(t, err)
+		log3 := New("three")
+		log3.Error("hello 3")
+		log4 := log3.New("key", "value")
+		err = log4.Log("msg", "hello 4")
+		require.NoError(t, err)
+
+		require.Len(t, loggedArgs, 4)
+		require.Len(t, loggedArgs[0], 4)
+		require.Equal(t, "logger", loggedArgs[0][0].(string))
+		require.Equal(t, "one", loggedArgs[0][1].(string))
+		require.Equal(t, "msg", loggedArgs[0][2].(string))
+		require.Equal(t, "hello 1", loggedArgs[0][3].(string))
+
+		require.Len(t, loggedArgs[1], 4)
+		require.Equal(t, "logger", loggedArgs[1][0].(string))
+		require.Equal(t, "two", loggedArgs[1][1].(string))
+		require.Equal(t, "msg", loggedArgs[1][2].(string))
+		require.Equal(t, "hello 2", loggedArgs[1][3].(string))
+
+		require.Len(t, loggedArgs[2], 8)
+		require.Equal(t, "logger", loggedArgs[2][0].(string))
+		require.Equal(t, "three", loggedArgs[2][1].(string))
+		require.Equal(t, "t", loggedArgs[2][2].(string))
+		require.Equal(t, mockedTime.Format("2006-01-02T15:04:05.99-0700"), loggedArgs[2][3].(fmt.Stringer).String())
+		require.Equal(t, "lvl", loggedArgs[2][4].(string))
+		require.Equal(t, level.ErrorValue(), loggedArgs[2][5].(level.Value))
+		require.Equal(t, "msg", loggedArgs[2][6].(string))
+		require.Equal(t, "hello 3", loggedArgs[2][7].(string))
+
+		require.Len(t, loggedArgs[3], 6)
+		require.Equal(t, "logger", loggedArgs[3][0].(string))
+		require.Equal(t, "three", loggedArgs[3][1].(string))
+		require.Equal(t, "key", loggedArgs[3][2].(string))
+		require.Equal(t, "value", loggedArgs[3][3].(string))
+		require.Equal(t, "msg", loggedArgs[3][4].(string))
+		require.Equal(t, "hello 4", loggedArgs[3][5].(string))
+
+		t.Run("When initializing root logger should swap loggers as expected", func(t *testing.T) {
+			swappedLoggedArgs := [][]interface{}{}
+			swapLogger := gokitlog.LoggerFunc(func(i ...interface{}) error {
+				swappedLoggedArgs = append(swappedLoggedArgs, i)
+				return nil
+			})
+
+			root.initialize([]logWithFilters{
+				{
+					val:      swapLogger,
+					maxLevel: level.AllowInfo(),
+				},
+				{
+					val:      swapLogger,
+					maxLevel: level.AllowAll(),
+				},
+			})
+
+			err := log1.Log("msg", "hello 1")
+			require.NoError(t, err)
+			err = log2.Log("msg", "hello 2")
+			require.NoError(t, err)
+			log3.Error("hello 3")
+			log3.Debug("debug")
+
+			require.Len(t, loggedArgs, 4)
+			require.Len(t, swappedLoggedArgs, 7, "expected 4 messages for AllowAll logger and 3 messages for AllowInfo logger")
+		})
+	})
+}

pkg/login/social/generic_oauth_test.go

@@ -17,7 +17,7 @@ import (
 
 func newLogger(name string, lev string) log.Logger {
 	logger := log.New(name)
-	logger.SetLogger(level.NewFilter(logger.GetLogger(), level.AllowInfo()))
+	logger.Swap(level.NewFilter(logger.GetLogger(), level.AllowInfo()))
 	return logger
 }
 

pkg/server/server.go

@@ -152,16 +152,16 @@ func (s *Server) Run() error {
 				return s.context.Err()
 			default:
 			}
-			s.log.Debug("Starting background service " + serviceName)
+			s.log.Debug("Starting background service", "service", serviceName)
 			err := service.Run(s.context)
 			// Do not return context.Canceled error since errgroup.Group only
 			// returns the first error to the caller - thus we can miss a more
 			// interesting error.
 			if err != nil && !errors.Is(err, context.Canceled) {
-				s.log.Error("Stopped background service "+serviceName, "reason", err)
+				s.log.Error("Stopped background service", "service", serviceName, "reason", err)
 				return fmt.Errorf("%s run error: %w", serviceName, err)
 			}
-			s.log.Debug("Stopped background service "+serviceName, "reason", err)
+			s.log.Debug("Stopped background service", "service", serviceName, "reason", err)
 			return nil
 		})
 	}

pkg/services/login/loginservice/loginservice_test.go

@@ -39,7 +39,7 @@ func Test_syncOrgRoles_doesNotBreakWhenTryingToRemoveLastOrgAdmin(t *testing.T)
 
 func Test_syncOrgRoles_whenTryingToRemoveLastOrgLogsError(t *testing.T) {
 	buf := &bytes.Buffer{}
-	logger.SetLogger(level.NewFilter(log.NewLogfmtLogger(buf), level.AllowInfo()))
+	logger.Swap(level.NewFilter(log.NewLogfmtLogger(buf), level.AllowInfo()))
 
 	user := createSimpleUser()
 	externalUser := createSimpleExternalUser()