From b4346a5613a988bb588b9e7ccf3bf04dcc5ad9de Mon Sep 17 00:00:00 2001 From: Marcus Efraimsson Date: Mon, 4 Apr 2022 12:36:17 +0200 Subject: [PATCH] Logging: Fixes filtering logs based on gokitlog levels (#47195) --- pkg/infra/log/level/level.go | 24 ++++- pkg/infra/log/level/level_test.go | 154 ++++++++++++++++++++++++++++++ 2 files changed, 177 insertions(+), 1 deletion(-) create mode 100644 pkg/infra/log/level/level_test.go diff --git a/pkg/infra/log/level/level.go b/pkg/infra/log/level/level.go index d6fdccfdaa1..dbb23c674ca 100644 --- a/pkg/infra/log/level/level.go +++ b/pkg/infra/log/level/level.go @@ -1,6 +1,9 @@ package level -import "github.com/go-kit/log" +import ( + "github.com/go-kit/log" + gokitlevel "github.com/go-kit/log/level" +) // Error returns a logger that includes a Key/ErrorValue pair. func Error(logger log.Logger) log.Logger { @@ -53,6 +56,12 @@ func (l *logger) Log(keyvals ...interface{}) error { levelAllowed = l.allowed&v.level != 0 break } + + if v, ok := keyvals[i].(gokitlevel.Value); ok { + hasLevel = true + levelAllowed = l.allowed&levelFromGokitLevel(v) != 0 + break + } } if !hasLevel && l.squelchNoLevel { return l.errNoLevel @@ -203,3 +212,16 @@ type levelValue struct { func (v *levelValue) String() string { return v.name } func (v *levelValue) levelVal() {} + +func levelFromGokitLevel(l gokitlevel.Value) level { + switch l.String() { + case gokitlevel.ErrorValue().String(): + return levelError + case gokitlevel.WarnValue().String(): + return levelWarn + case gokitlevel.DebugValue().String(): + return levelDebug + } + + return levelInfo +} diff --git a/pkg/infra/log/level/level_test.go b/pkg/infra/log/level/level_test.go new file mode 100644 index 00000000000..2e655aa2c9a --- /dev/null +++ b/pkg/infra/log/level/level_test.go @@ -0,0 +1,154 @@ +package level_test + +import ( + "testing" + + gokitlog "github.com/go-kit/log" + gokitlevel "github.com/go-kit/log/level" + "github.com/grafana/grafana/pkg/infra/log" + "github.com/grafana/grafana/pkg/infra/log/level" + "github.com/stretchr/testify/require" +) + +func TestNewFilter(t *testing.T) { + newFilteredLoggerScenario(t, "Given all levels is allowed should log all messages", level.AllowAll(), func(t *testing.T, ctx *scenarioContext) { + logTestMessages(t, ctx) + + require.Len(t, ctx.loggedArgs, 8) + require.Equal(t, "lvl", ctx.loggedArgs[0][2].(string)) + require.Equal(t, "info", ctx.loggedArgs[0][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[1][2].(string)) + require.Equal(t, "warn", ctx.loggedArgs[1][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[2][2].(string)) + require.Equal(t, "eror", ctx.loggedArgs[2][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[3][2].(string)) + require.Equal(t, "dbug", ctx.loggedArgs[3][3].(level.Value).String()) + + require.Equal(t, "level", ctx.loggedArgs[4][0].(string)) + require.Equal(t, "info", ctx.loggedArgs[4][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[5][0].(string)) + require.Equal(t, "warn", ctx.loggedArgs[5][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[6][0].(string)) + require.Equal(t, "error", ctx.loggedArgs[6][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[7][0].(string)) + require.Equal(t, "debug", ctx.loggedArgs[7][1].(gokitlevel.Value).String()) + }) + + newFilteredLoggerScenario(t, "Given error, warnings, info, debug is allowed should log all messages", level.AllowDebug(), func(t *testing.T, ctx *scenarioContext) { + logTestMessages(t, ctx) + + require.Len(t, ctx.loggedArgs, 8) + require.Equal(t, "lvl", ctx.loggedArgs[0][2].(string)) + require.Equal(t, "info", ctx.loggedArgs[0][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[1][2].(string)) + require.Equal(t, "warn", ctx.loggedArgs[1][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[2][2].(string)) + require.Equal(t, "eror", ctx.loggedArgs[2][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[3][2].(string)) + require.Equal(t, "dbug", ctx.loggedArgs[3][3].(level.Value).String()) + + require.Equal(t, "level", ctx.loggedArgs[4][0].(string)) + require.Equal(t, "info", ctx.loggedArgs[4][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[5][0].(string)) + require.Equal(t, "warn", ctx.loggedArgs[5][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[6][0].(string)) + require.Equal(t, "error", ctx.loggedArgs[6][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[7][0].(string)) + require.Equal(t, "debug", ctx.loggedArgs[7][1].(gokitlevel.Value).String()) + }) + + newFilteredLoggerScenario(t, "Given error, warnings is allowed should log error and warning messages", level.AllowWarn(), func(t *testing.T, ctx *scenarioContext) { + logTestMessages(t, ctx) + + require.Len(t, ctx.loggedArgs, 4) + require.Equal(t, "lvl", ctx.loggedArgs[0][2].(string)) + require.Equal(t, "warn", ctx.loggedArgs[0][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[1][2].(string)) + require.Equal(t, "eror", ctx.loggedArgs[1][3].(level.Value).String()) + + require.Equal(t, "level", ctx.loggedArgs[2][0].(string)) + require.Equal(t, "warn", ctx.loggedArgs[2][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[3][0].(string)) + require.Equal(t, "error", ctx.loggedArgs[3][1].(gokitlevel.Value).String()) + }) + + newFilteredLoggerScenario(t, "Given error allowed should log error messages", level.AllowError(), func(t *testing.T, ctx *scenarioContext) { + logTestMessages(t, ctx) + + require.Len(t, ctx.loggedArgs, 2) + require.Equal(t, "lvl", ctx.loggedArgs[0][2].(string)) + require.Equal(t, "eror", ctx.loggedArgs[0][3].(level.Value).String()) + + require.Equal(t, "level", ctx.loggedArgs[1][0].(string)) + require.Equal(t, "error", ctx.loggedArgs[1][1].(gokitlevel.Value).String()) + }) + + newFilteredLoggerScenario(t, "Given error, warnings, info is allowed should log error, warning and info messages", level.AllowInfo(), func(t *testing.T, ctx *scenarioContext) { + logTestMessages(t, ctx) + + require.Len(t, ctx.loggedArgs, 6) + require.Equal(t, "lvl", ctx.loggedArgs[0][2].(string)) + require.Equal(t, "info", ctx.loggedArgs[0][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[1][2].(string)) + require.Equal(t, "warn", ctx.loggedArgs[1][3].(level.Value).String()) + require.Equal(t, "lvl", ctx.loggedArgs[2][2].(string)) + require.Equal(t, "eror", ctx.loggedArgs[2][3].(level.Value).String()) + + require.Equal(t, "level", ctx.loggedArgs[3][0].(string)) + require.Equal(t, "info", ctx.loggedArgs[3][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[4][0].(string)) + require.Equal(t, "warn", ctx.loggedArgs[4][1].(gokitlevel.Value).String()) + require.Equal(t, "level", ctx.loggedArgs[5][0].(string)) + require.Equal(t, "error", ctx.loggedArgs[5][1].(gokitlevel.Value).String()) + }) + + newFilteredLoggerScenario(t, "Given no levels is allowed should not log any messages", level.AllowNone(), func(t *testing.T, ctx *scenarioContext) { + logTestMessages(t, ctx) + + require.Len(t, ctx.loggedArgs, 0) + }) +} + +func logTestMessages(t *testing.T, ctx *scenarioContext) { + t.Helper() + + ctx.logger.Info("info msg") + ctx.logger.Warn("warn msg") + ctx.logger.Error("error msg") + ctx.logger.Debug("debug msg") + err := gokitlevel.Info(ctx.logger).Log("msg", "gokit info msg") + require.NoError(t, err) + err = gokitlevel.Warn(ctx.logger).Log("msg", "gokit warn msg") + require.NoError(t, err) + err = gokitlevel.Error(ctx.logger).Log("msg", "gokit error msg") + require.NoError(t, err) + err = gokitlevel.Debug(ctx.logger).Log("msg", "gokit debug msg") + require.NoError(t, err) +} + +type scenarioContext struct { + loggedArgs [][]interface{} + logger log.Logger +} + +func newFilteredLoggerScenario(t *testing.T, desc string, option level.Option, fn func(t *testing.T, ctx *scenarioContext)) { + t.Helper() + + ctx := &scenarioContext{ + loggedArgs: [][]interface{}{}, + } + + l := gokitlog.LoggerFunc(func(i ...interface{}) error { + ctx.loggedArgs = append(ctx.loggedArgs, i) + return nil + }) + filteredLogger := level.NewFilter(l, option) + testLogger := log.New("test") + testLogger.Swap(filteredLogger) + + ctx.logger = testLogger + + t.Run(desc, func(t *testing.T) { + fn(t, ctx) + }) +}