From 9e0acc9ecef07f5f3b3e06aebfdb0f3d01219d54 Mon Sep 17 00:00:00 2001 From: "Grot (@grafanabot)" <43478413+grafanabot@users.noreply.github.com> Date: Thu, 3 Feb 2022 16:34:18 +0100 Subject: [PATCH] Chore: Fix log filters (#44681) (#44853) (cherry picked from commit bc7e55d99bb43f3f870c3ebe7b960e147462b9dd) Co-authored-by: Marcus Efraimsson --- pkg/api/frontend_logging_test.go | 2 +- pkg/infra/log/composite_logger.go | 25 ++ pkg/infra/log/interface.go | 2 +- pkg/infra/log/log.go | 335 ++++++++++++------ pkg/infra/log/syslog.go | 2 +- pkg/infra/usagestats/service/service.go | 2 +- pkg/login/social/generic_oauth_test.go | 2 +- pkg/middleware/recovery.go | 2 +- .../loader/initializer/initializer_test.go | 6 +- pkg/plugins/manager/loader/loader_test.go | 4 +- .../login/loginservice/loginservice_test.go | 2 +- pkg/setting/setting.go | 2 + 12 files changed, 261 insertions(+), 125 deletions(-) create mode 100644 pkg/infra/log/composite_logger.go diff --git a/pkg/api/frontend_logging_test.go b/pkg/api/frontend_logging_test.go index a8e204fdd25..84d8953f7aa 100644 --- a/pkg/api/frontend_logging_test.go +++ b/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() { diff --git a/pkg/infra/log/composite_logger.go b/pkg/infra/log/composite_logger.go new file mode 100644 index 00000000000..5c238673347 --- /dev/null +++ b/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 +} diff --git a/pkg/infra/log/interface.go b/pkg/infra/log/interface.go index 523f9a3bc33..c0909d682cb 100644 --- a/pkg/infra/log/interface.go +++ b/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 diff --git a/pkg/infra/log/log.go b/pkg/infra/log/log.go index ba531ca633f..a4d38d84256 100644 --- a/pkg/infra/log/log.go +++ b/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 MultiLoggers +var root *logManager 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 { - 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 { +func with(ctxLogger *ConcreteLogger, withFunc func(gokitlog.Logger, ...interface{}) gokitlog.Logger, ctx []interface{}) *ConcreteLogger { 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 { - if len(ctx) == 0 { - return loggers - } - var newloger MultiLoggers - for _, l := range loggers.loggers { - l.val = withFunc(l.val, ctx...) - newloger.loggers = append(newloger.loggers, l) - } - return newloger + ctxLogger.logger = withFunc(ctxLogger.logger, ctx...) + return ctxLogger } // WithPrefix adds context that will be added to the log message -func WithPrefix(loggers MultiLoggers, ctx ...interface{}) MultiLoggers { - return with(loggers, gokitlog.WithPrefix, ctx) +func WithPrefix(ctxLogger *ConcreteLogger, ctx ...interface{}) *ConcreteLogger { + 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 { - return with(loggers, gokitlog.WithSuffix, ctx) +func WithSuffix(ctxLogger *ConcreteLogger, ctx ...interface{}) *ConcreteLogger { + 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 } diff --git a/pkg/infra/log/syslog.go b/pkg/infra/log/syslog.go index b1d818f5d58..150a8c6fae3 100644 --- a/pkg/infra/log/syslog.go +++ b/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)) diff --git a/pkg/infra/usagestats/service/service.go b/pkg/infra/usagestats/service/service.go index 13ac15b2be1..bea01a403b4 100644 --- a/pkg/infra/usagestats/service/service.go +++ b/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 diff --git a/pkg/login/social/generic_oauth_test.go b/pkg/login/social/generic_oauth_test.go index 9be66f1e3ac..ab9990b4f16 100644 --- a/pkg/login/social/generic_oauth_test.go +++ b/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 } diff --git a/pkg/middleware/recovery.go b/pkg/middleware/recovery.go index ea8483a6911..fe5d3a22597 100644 --- a/pkg/middleware/recovery.go +++ b/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 { diff --git a/pkg/plugins/manager/loader/initializer/initializer_test.go b/pkg/plugins/manager/loader/initializer/initializer_test.go index 8b6412e8372..d63a34384c3 100644 --- a/pkg/plugins/manager/loader/initializer/initializer_test.go +++ b/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 { - return log.MultiLoggers{} +func (f fakeLogger) New(_ ...interface{}) *log.ConcreteLogger { + return &log.ConcreteLogger{} } func (f fakeLogger) Warn(_ string, _ ...interface{}) { diff --git a/pkg/plugins/manager/loader/loader_test.go b/pkg/plugins/manager/loader/loader_test.go index 59cb67d8e86..b21a9b6f02f 100644 --- a/pkg/plugins/manager/loader/loader_test.go +++ b/pkg/plugins/manager/loader/loader_test.go @@ -1128,8 +1128,8 @@ type fakeLogger struct { log.Logger } -func (fl fakeLogger) New(_ ...interface{}) log.MultiLoggers { - return log.MultiLoggers{} +func (fl fakeLogger) New(_ ...interface{}) *log.ConcreteLogger { + return &log.ConcreteLogger{} } func (fl fakeLogger) Info(_ string, _ ...interface{}) { diff --git a/pkg/services/login/loginservice/loginservice_test.go b/pkg/services/login/loginservice/loginservice_test.go index 5cbd5acb510..14f1c146b0f 100644 --- a/pkg/services/login/loginservice/loginservice_test.go +++ b/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() diff --git a/pkg/setting/setting.go b/pkg/setting/setting.go index 713bfc31d3f..aa7375f0e33 100644 --- a/pkg/setting/setting.go +++ b/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 }