Chore: Fix log filters (#44681)

pkg/api/frontend_logging_test.go

@@ -42,7 +42,7 @@ func logSentryEventScenario(t *testing.T, desc string, event frontendlogging.Fro
 		}))
 
 		origHandler := frontendLogger.GetLogger()
-		frontendLogger.AddLogger(newfrontendLogger, "info", map[string]level.Option{})
+		frontendLogger.SetLogger(level.NewFilter(newfrontendLogger, level.AllowInfo()))
 		sourceMapReads := []SourceMapReadRecord{}
 
 		t.Cleanup(func() {

pkg/infra/log/composite_logger.go

@@ -0,0 +1,25 @@
+package log
+
+import gokitlog "github.com/go-kit/log"
+
+type compositeLogger struct {
+	loggers []gokitlog.Logger
+}
+
+func newCompositeLogger(loggers ...gokitlog.Logger) *compositeLogger {
+	if len(loggers) == 0 {
+		loggers = []gokitlog.Logger{}
+	}
+
+	return &compositeLogger{loggers: loggers}
+}
+
+func (l *compositeLogger) Log(keyvals ...interface{}) error {
+	for _, logger := range l.loggers {
+		if err := logger.Log(keyvals...); err != nil {
+			return err
+		}
+	}
+
+	return nil
+}

pkg/infra/log/interface.go

@@ -12,7 +12,7 @@ const (
 
 type Logger interface {
 	// New returns a new Logger that has this logger's context plus the given context
-	New(ctx ...interface{}) MultiLoggers
+	New(ctx ...interface{}) *ConcreteLogger
 
 	Log(keyvals ...interface{}) error
 

pkg/infra/log/log.go

@@ -7,9 +7,12 @@ package log
 import (
 	"fmt"
 	"io"
+	"log"
 	"os"
 	"path/filepath"
+	"sort"
 	"strings"
+	"sync"
 	"time"
 
 	gokitlog "github.com/go-kit/log"
@@ -25,8 +28,7 @@ import (
 
 var loggersToClose []DisposableHandler
 var loggersToReload []ReloadableHandler
-var filters map[string]level.Option
+var root *logManager
-var Root MultiLoggers
 
 const (
 	// top 7 calls in the stack are within logger
@@ -37,11 +39,212 @@ const (
 func init() {
 	loggersToClose = make([]DisposableHandler, 0)
 	loggersToReload = make([]ReloadableHandler, 0)
-	filters = map[string]level.Option{}
 
 	// Use console by default
 	format := getLogFormat("console")
-	Root.AddLogger(format(os.Stderr), "info", filters)
+	logger := level.NewFilter(format(os.Stderr), level.AllowInfo())
+	root = newManager(logger)
+}
+
+// logManager manage loggers
+type logManager struct {
+	*ConcreteLogger
+	loggersByName map[string]*ConcreteLogger
+	logFilters    []LogWithFilters
+	mutex         sync.RWMutex
+}
+
+func newManager(logger gokitlog.Logger) *logManager {
+	return &logManager{
+		ConcreteLogger: newConcreteLogger(logger),
+		loggersByName:  map[string]*ConcreteLogger{},
+	}
+}
+
+func (lm *logManager) initialize(loggers []LogWithFilters) {
+	lm.mutex.Lock()
+	defer lm.mutex.Unlock()
+
+	defaultLoggers := make([]gokitlog.Logger, len(loggers))
+	for index, logger := range loggers {
+		defaultLoggers[index] = level.NewFilter(logger.val, logger.maxLevel)
+	}
+
+	lm.ConcreteLogger.SetLogger(&compositeLogger{loggers: defaultLoggers})
+	lm.logFilters = loggers
+
+	loggersByName := []string{}
+	for k := range lm.loggersByName {
+		loggersByName = append(loggersByName, k)
+	}
+	sort.Strings(loggersByName)
+
+	for _, name := range loggersByName {
+		ctxLoggers := make([]gokitlog.Logger, len(loggers))
+
+		for index, logger := range loggers {
+			if filterLevel, exists := logger.filters[name]; !exists {
+				ctxLoggers[index] = level.NewFilter(logger.val, logger.maxLevel)
+			} else {
+				ctxLoggers[index] = level.NewFilter(logger.val, 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.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)
+	if !ok {
+		return lm.ConcreteLogger
+	}
+
+	if logger, exists := lm.loggersByName[loggerName]; exists {
+		return logger
+	}
+
+	ctx = append([]interface{}{"logger"}, ctx...)
+
+	if len(lm.logFilters) == 0 {
+		ctxLogger := newConcreteLogger(lm.logger, ctx...)
+		lm.loggersByName[loggerName] = ctxLogger
+		return ctxLogger
+	}
+
+	compositeLogger := newCompositeLogger()
+	for _, logWithFilter := range lm.logFilters {
+		filterLevel, ok := logWithFilter.filters[loggerName]
+		if ok {
+			logWithFilter.val = level.NewFilter(logWithFilter.val, filterLevel)
+		} else {
+			logWithFilter.val = level.NewFilter(logWithFilter.val, logWithFilter.maxLevel)
+		}
+
+		compositeLogger.loggers = append(compositeLogger.loggers, logWithFilter.val)
+	}
+
+	ctxLogger := newConcreteLogger(compositeLogger, ctx...)
+	lm.loggersByName[loggerName] = ctxLogger
+	return ctxLogger
+}
+
+type ConcreteLogger struct {
+	ctx    []interface{}
+	logger gokitlog.Logger
+	mutex  sync.RWMutex
+}
+
+func newConcreteLogger(logger gokitlog.Logger, ctx ...interface{}) *ConcreteLogger {
+	if len(ctx) == 0 {
+		ctx = []interface{}{}
+	} else {
+		logger = gokitlog.With(logger, ctx...)
+	}
+
+	return &ConcreteLogger{
+		ctx:    ctx,
+		logger: logger,
+	}
+}
+
+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 {
+	cl.mutex.Lock()
+	defer cl.mutex.Unlock()
+	return cl.logger
+}
+
+func (cl *ConcreteLogger) Warn(msg string, args ...interface{}) {
+	_ = cl.log(msg, level.WarnValue(), args...)
+}
+
+func (cl *ConcreteLogger) Debug(msg string, args ...interface{}) {
+	// args = append([]interface{}{level.Key(), level.DebugValue(), "msg", msg}, args...)
+	_ = cl.log(msg, level.DebugValue(), args...)
+}
+
+func (cl *ConcreteLogger) Error(msg string, args ...interface{}) {
+	_ = cl.log(msg, level.ErrorValue(), args...)
+}
+
+func (cl *ConcreteLogger) Info(msg string, args ...interface{}) {
+	_ = cl.log(msg, level.InfoValue(), args...)
+}
+
+func (cl *ConcreteLogger) log(msg string, logLevel level.Value, args ...interface{}) error {
+	cl.mutex.RLock()
+	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{}{}
+
+	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...)
 }
 
 type LogWithFilters struct {
@@ -50,111 +253,23 @@ type LogWithFilters struct {
 	maxLevel level.Option
 }
 
-type MultiLoggers struct {
+func with(ctxLogger *ConcreteLogger, withFunc func(gokitlog.Logger, ...interface{}) gokitlog.Logger, ctx []interface{}) *ConcreteLogger {
-	loggers []LogWithFilters
-}
-
-func (ml *MultiLoggers) AddLogger(val gokitlog.Logger, levelName string, filters map[string]level.Option) {
-	logger := LogWithFilters{val: val, filters: filters, maxLevel: getLogLevelFromString(levelName)}
-	ml.loggers = append(ml.loggers, logger)
-}
-
-func (ml *MultiLoggers) SetLogger(des MultiLoggers) {
-	ml.loggers = des.loggers
-}
-
-func (ml *MultiLoggers) GetLogger() MultiLoggers {
-	return *ml
-}
-
-func (ml MultiLoggers) Warn(msg string, args ...interface{}) {
-	args = append([]interface{}{level.Key(), level.WarnValue(), "msg", msg}, args...)
-	err := ml.Log(args...)
-	if err != nil {
-		_ = level.Error(Root).Log("Logging error", "error", err)
-	}
-}
-
-func (ml MultiLoggers) Debug(msg string, args ...interface{}) {
-	args = append([]interface{}{level.Key(), level.DebugValue(), "msg", msg}, args...)
-	err := ml.Log(args...)
-	if err != nil {
-		_ = level.Error(Root).Log("Logging error", "error", err)
-	}
-}
-
-func (ml MultiLoggers) Error(msg string, args ...interface{}) {
-	args = append([]interface{}{level.Key(), level.ErrorValue(), "msg", msg}, args...)
-	err := ml.Log(args...)
-	if err != nil {
-		_ = level.Error(Root).Log("Logging error", "error", err)
-	}
-}
-
-func (ml MultiLoggers) Info(msg string, args ...interface{}) {
-	args = append([]interface{}{level.Key(), level.InfoValue(), "msg", msg}, args...)
-	err := ml.Log(args...)
-	if err != nil {
-		_ = level.Error(Root).Log("Logging error", "error", err)
-	}
-}
-
-func (ml MultiLoggers) Log(keyvals ...interface{}) error {
-	for _, multilogger := range ml.loggers {
-		multilogger.val = gokitlog.With(multilogger.val, "t", gokitlog.TimestampFormat(time.Now, "2006-01-02T15:04:05.99-0700"))
-		if err := multilogger.val.Log(keyvals...); err != nil {
-			return err
-		}
-	}
-	return nil
-}
-
-// New creates a new logger from the existing one with additional context
-func (ml MultiLoggers) New(ctx ...interface{}) MultiLoggers {
-	return with(ml, gokitlog.With, ctx)
-}
-
-// New creates MultiLoggers with the provided context and caller that is added as a suffix.
-// The first element of the context must be the logger name
-func New(ctx ...interface{}) MultiLoggers {
 	if len(ctx) == 0 {
-		return Root
+		return ctxLogger
 	}
-	var newloger MultiLoggers
-	ctx = append([]interface{}{"logger"}, ctx...)
-	for _, logWithFilter := range Root.loggers {
-		logWithFilter.val = gokitlog.With(logWithFilter.val, ctx...)
-		v, ok := logWithFilter.filters[ctx[0].(string)]
-		if ok {
-			logWithFilter.val = level.NewFilter(logWithFilter.val, v)
-		} else {
-			logWithFilter.val = level.NewFilter(logWithFilter.val, logWithFilter.maxLevel)
-		}
-		newloger.loggers = append(newloger.loggers, logWithFilter)
-	}
-	return newloger
-}
 
-func with(loggers MultiLoggers, withFunc func(gokitlog.Logger, ...interface{}) gokitlog.Logger, ctx []interface{}) MultiLoggers {
+	ctxLogger.logger = withFunc(ctxLogger.logger, ctx...)
-	if len(ctx) == 0 {
+	return ctxLogger
-		return loggers
-	}
-	var newloger MultiLoggers
-	for _, l := range loggers.loggers {
-		l.val = withFunc(l.val, ctx...)
-		newloger.loggers = append(newloger.loggers, l)
-	}
-	return newloger
 }
 
 // WithPrefix adds context that will be added to the log message
-func WithPrefix(loggers MultiLoggers, ctx ...interface{}) MultiLoggers {
+func WithPrefix(ctxLogger *ConcreteLogger, ctx ...interface{}) *ConcreteLogger {
-	return with(loggers, gokitlog.WithPrefix, ctx)
+	return with(ctxLogger, gokitlog.WithPrefix, ctx)
 }
 
 // WithSuffix adds context that will be appended at the end of the log message
-func WithSuffix(loggers MultiLoggers, ctx ...interface{}) MultiLoggers {
+func WithSuffix(ctxLogger *ConcreteLogger, ctx ...interface{}) *ConcreteLogger {
-	return with(loggers, gokitlog.WithSuffix, ctx)
+	return with(ctxLogger, gokitlog.WithSuffix, ctx)
 }
 
 var logLevels = map[string]level.Option{
@@ -177,7 +292,7 @@ func getLogLevelFromString(levelName string) level.Option {
 	loglevel, ok := logLevels[levelName]
 
 	if !ok {
-		_ = level.Error(Root).Log("Unknown log level", "level", levelName)
+		_ = level.Error(root).Log("Unknown log level", "level", levelName)
 		return level.AllowError()
 	}
 
@@ -282,7 +397,7 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) error {
 		mode = strings.TrimSpace(mode)
 		sec, err := cfg.GetSection("log." + mode)
 		if err != nil {
-			_ = level.Error(Root).Log("Unknown log mode", "mode", mode)
+			_ = level.Error(root).Log("Unknown log mode", "mode", mode)
 			return errutil.Wrapf(err, "failed to get config section log.%s", mode)
 		}
 
@@ -301,7 +416,7 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) error {
 			fileName := sec.Key("file_name").MustString(filepath.Join(logsPath, "grafana.log"))
 			dpath := filepath.Dir(fileName)
 			if err := os.MkdirAll(dpath, os.ModePerm); err != nil {
-				_ = level.Error(Root).Log("Failed to create directory", "dpath", dpath, "err", err)
+				_ = level.Error(root).Log("Failed to create directory", "dpath", dpath, "err", err)
 				return errutil.Wrapf(err, "failed to create log directory %q", dpath)
 			}
 			fileHandler := NewFileWriter()
@@ -313,7 +428,7 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) error {
 			fileHandler.Daily = sec.Key("daily_rotate").MustBool(true)
 			fileHandler.Maxdays = sec.Key("max_days").MustInt64(7)
 			if err := fileHandler.Init(); err != nil {
-				_ = level.Error(Root).Log("Failed to initialize file handler", "dpath", dpath, "err", err)
+				_ = level.Error(root).Log("Failed to initialize file handler", "dpath", dpath, "err", err)
 				return errutil.Wrapf(err, "failed to initialize file handler")
 			}
 
@@ -336,20 +451,14 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) error {
 			}
 		}
 
-		// copy joined default + mode filters into filters
-		for key, value := range modeFilters {
-			if _, exist := filters[key]; !exist {
-				filters[key] = value
-			}
-		}
-
 		handler.filters = modeFilters
 		handler.maxLevel = leveloption
-		// handler = LogFilterHandler(leveloption, modeFilters, handler)
 		configLoggers = append(configLoggers, handler)
 	}
+
 	if len(configLoggers) > 0 {
-		Root.loggers = configLoggers
+		root.initialize(configLoggers)
 	}
+
 	return nil
 }

pkg/infra/log/syslog.go

@@ -62,7 +62,7 @@ func NewSyslog(sec *ini.Section, format Formatedlogger) *SysLogHandler {
 	handler.Tag = sec.Key("tag").MustString("")
 
 	if err := handler.Init(); err != nil {
-		_ = level.Error(Root).Log("Failed to init syslog log handler", "error", err)
+		_ = level.Error(root).Log("Failed to init syslog log handler", "error", err)
 		os.Exit(1)
 	}
 	handler.logger = gokitsyslog.NewSyslogLogger(handler.syslog, format, gokitsyslog.PrioritySelectorOption(selector))

pkg/infra/usagestats/service/service.go

@@ -25,7 +25,7 @@ type UsageStats struct {
 	kvStore       *kvstore.NamespacedKVStore
 	RouteRegister routing.RouteRegister
 
-	log log.MultiLoggers
+	log log.Logger
 
 	oauthProviders           map[string]bool
 	externalMetrics          []usagestats.MetricsFunc

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.AddLogger(logger, lev, map[string]level.Option{})
+	logger.SetLogger(level.NewFilter(logger.GetLogger(), level.AllowInfo()))
 	return logger
 }
 

pkg/middleware/recovery.go

@@ -107,7 +107,7 @@ func Recovery(cfg *setting.Cfg) web.Handler {
 		defer func() {
 			if r := recover(); r != nil {
 				var panicLogger log.Logger
-				panicLogger = log.Root
+				panicLogger = log.New("recovery")
 				// try to get request logger
 				ctx := contexthandler.FromContext(c.Req.Context())
 				if ctx != nil {

pkg/plugins/manager/loader/initializer/initializer_test.go

@@ -212,11 +212,11 @@ func (*testLicensingService) FeatureEnabled(feature string) bool {
 }
 
 type fakeLogger struct {
-	log.MultiLoggers
+	*log.ConcreteLogger
 }
 
-func (f fakeLogger) New(_ ...interface{}) log.MultiLoggers {
+func (f fakeLogger) New(_ ...interface{}) *log.ConcreteLogger {
-	return log.MultiLoggers{}
+	return &log.ConcreteLogger{}
 }
 
 func (f fakeLogger) Warn(_ string, _ ...interface{}) {

pkg/plugins/manager/loader/loader_test.go

@@ -1128,8 +1128,8 @@ type fakeLogger struct {
 	log.Logger
 }
 
-func (fl fakeLogger) New(_ ...interface{}) log.MultiLoggers {
+func (fl fakeLogger) New(_ ...interface{}) *log.ConcreteLogger {
-	return log.MultiLoggers{}
+	return &log.ConcreteLogger{}
 }
 
 func (fl fakeLogger) Info(_ string, _ ...interface{}) {

pkg/services/login/loginservice/loginservice_test.go

@@ -46,7 +46,7 @@ func Test_syncOrgRoles_doesNotBreakWhenTryingToRemoveLastOrgAdmin(t *testing.T)
 
 func Test_syncOrgRoles_whenTryingToRemoveLastOrgLogsError(t *testing.T) {
 	buf := &bytes.Buffer{}
-	logger.AddLogger(log.NewLogfmtLogger(buf), "info", map[string]level.Option{})
+	logger.SetLogger(level.NewFilter(log.NewLogfmtLogger(buf), level.AllowInfo()))
 
 	user := createSimpleUser()
 	externalUser := createSimpleExternalUser()

pkg/setting/setting.go

@@ -772,6 +772,8 @@ func (cfg *Cfg) loadConfiguration(args CommandLineArgs) (*ini.File, error) {
 		return nil, err
 	}
 
+	cfg.Logger.Info(fmt.Sprintf("Starting %s", ApplicationName), "version", BuildVersion, "commit", BuildCommit, "branch", BuildBranch, "compiled", time.Unix(BuildStamp, 0))
+
 	return parsedFile, err
 }