diff --git a/pkg/api/frontend_logging_test.go b/pkg/api/frontend_logging_test.go index 84d8953f7aa..3658645372a 100644 --- a/pkg/api/frontend_logging_test.go +++ b/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") diff --git a/pkg/infra/log/composite_logger_test.go b/pkg/infra/log/composite_logger_test.go new file mode 100644 index 00000000000..8ab1ead9502 --- /dev/null +++ b/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)) +} diff --git a/pkg/infra/log/log.go b/pkg/infra/log/log.go index da9395c410d..cc49d8c03bb 100644 --- a/pkg/infra/log/log.go +++ b/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 loggersToReload []ReloadableHandler -var root *logManager +var ( + loggersToClose []DisposableHandler + 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}) + lm.loggersByName[name].Swap(&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) + 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 } @@ -154,34 +137,28 @@ func (lm *logManager) New(ctx ...interface{}) *ConcreteLogger { } type ConcreteLogger struct { - ctx []interface{} - logger gokitlog.Logger - mutex sync.RWMutex + ctx []interface{} + gokitlog.SwapLogger } 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, + ctx: ctx, + 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 { - cl.mutex.Lock() - defer cl.mutex.Unlock() - return cl.logger +func (cl ConcreteLogger) GetLogger() gokitlog.Logger { + return &cl.SwapLogger } 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.logger, "t", gokitlog.TimestampFormat(time.Now, "2006-01-02T15:04:05.99-0700")) - cl.mutex.RUnlock() - + logger := gokitlog.With(&cl.SwapLogger, "t", gokitlog.TimestampFormat(now, "2006-01-02T15:04:05.99-0700")) 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...) + return newConcreteLogger(gokitlog.With(&cl.SwapLogger), ctx...) } func New(ctx ...interface{}) *ConcreteLogger { - return root.New(ctx...) -} + if len(ctx) == 0 { + return root.New() + } -type LogWithFilters struct { - val gokitlog.Logger - filters map[string]level.Option - maxLevel level.Option + ctx = append([]interface{}{"logger"}, ctx...) + return root.New(ctx...) } 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": diff --git a/pkg/infra/log/log_test.go b/pkg/infra/log/log_test.go new file mode 100644 index 00000000000..553a77fe2e5 --- /dev/null +++ b/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") + }) + }) +} diff --git a/pkg/login/social/generic_oauth_test.go b/pkg/login/social/generic_oauth_test.go index ab9990b4f16..878a4216293 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.SetLogger(level.NewFilter(logger.GetLogger(), level.AllowInfo())) + logger.Swap(level.NewFilter(logger.GetLogger(), level.AllowInfo())) return logger } diff --git a/pkg/server/server.go b/pkg/server/server.go index 4cab5583c44..ee975ba3431 100644 --- a/pkg/server/server.go +++ b/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 }) } diff --git a/pkg/services/login/loginservice/loginservice_test.go b/pkg/services/login/loginservice/loginservice_test.go index aef102c6193..faceae8d15f 100644 --- a/pkg/services/login/loginservice/loginservice_test.go +++ b/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()