From 88323a30b78f12eecc70cc127b0c4477e5e4bf9e Mon Sep 17 00:00:00 2001 From: Emil Tullstedt Date: Tue, 27 Dec 2022 16:42:03 +0100 Subject: [PATCH] Logging: Fix running tests multiple times (#60559) - Create new ctxLogProviders for each scenario to support go test -count=n for n>1. Currently, it just kept adding providers for every new run, which would make it add way more key-value pairs to the provider than necessary. - Adding a helper method to the scenario to make it easier to set up tests for logging and easier to read the tests. I also flattened the test file, to reduce the complexity of each test function. --- pkg/infra/log/log_test.go | 390 ++++++++++++++++++-------------------- 1 file changed, 187 insertions(+), 203 deletions(-) diff --git a/pkg/infra/log/log_test.go b/pkg/infra/log/log_test.go index 18d7b06b2e0..f81643cafce 100644 --- a/pkg/infra/log/log_test.go +++ b/pkg/infra/log/log_test.go @@ -7,9 +7,10 @@ import ( "time" gokitlog "github.com/go-kit/log" + "github.com/go-kit/log/level" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "github.com/go-kit/log/level" "github.com/grafana/grafana/pkg/util" ) @@ -19,215 +20,180 @@ func TestLogger(t *testing.T) { err := root.Log("msg", "hello") require.NoError(t, err) }) +} + +func TestNew(t *testing.T) { + scenario := newLoggerScenario(t) + + 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) + log3.Error("hello 3 again") + + require.Len(t, scenario.loggedArgs, 5, "lines logged") + scenario.ValidateLineEquality(t, 0, []any{ + "logger", "one", + "t", scenario.mockedTime, + "msg", "hello 1", + }) + + scenario.ValidateLineEquality(t, 1, []any{ + "logger", "two", + "t", scenario.mockedTime, + "msg", "hello 2", + }) + + scenario.ValidateLineEquality(t, 2, []any{ + "logger", "three", + "t", scenario.mockedTime, + level.Key(), level.ErrorValue(), + "msg", "hello 3", + }) + + scenario.ValidateLineEquality(t, 3, []any{ + "logger", "three", + "key", "value", + "t", scenario.mockedTime, + "msg", "hello 4", + }) + + scenario.ValidateLineEquality(t, 4, []any{ + "logger", "three", + "t", scenario.mockedTime, + level.Key(), level.ErrorValue(), + "msg", "hello 3 again", + }) + + 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(), + }, + }) - newLoggerScenario(t, "When creating root logger should log as expected", func(t *testing.T, ctx *scenarioContext) { - 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) - log3.Error("hello 3 again") + log3.Debug("debug") - require.Len(t, ctx.loggedArgs, 5) - require.Len(t, ctx.loggedArgs[0], 6) - require.Equal(t, "logger", ctx.loggedArgs[0][0].(string)) - require.Equal(t, "one", ctx.loggedArgs[0][1].(string)) - require.Equal(t, "t", ctx.loggedArgs[0][2].(string)) - require.Equal(t, ctx.mockedTime.Format(time.RFC3339Nano), ctx.loggedArgs[0][3].(fmt.Stringer).String()) - require.Equal(t, "msg", ctx.loggedArgs[0][4].(string)) - require.Equal(t, "hello 1", ctx.loggedArgs[0][5].(string)) - - require.Len(t, ctx.loggedArgs[1], 6) - require.Equal(t, "logger", ctx.loggedArgs[1][0].(string)) - require.Equal(t, "two", ctx.loggedArgs[1][1].(string)) - require.Equal(t, "t", ctx.loggedArgs[0][2].(string)) - require.Equal(t, ctx.mockedTime.Format(time.RFC3339Nano), ctx.loggedArgs[0][3].(fmt.Stringer).String()) - require.Equal(t, "msg", ctx.loggedArgs[1][4].(string)) - require.Equal(t, "hello 2", ctx.loggedArgs[1][5].(string)) - - require.Len(t, ctx.loggedArgs[2], 8) - require.Equal(t, "logger", ctx.loggedArgs[2][0].(string)) - require.Equal(t, "three", ctx.loggedArgs[2][1].(string)) - require.Equal(t, "t", ctx.loggedArgs[2][2].(string)) - require.Equal(t, ctx.mockedTime.Format(time.RFC3339Nano), ctx.loggedArgs[2][3].(fmt.Stringer).String()) - require.Equal(t, level.Key().(string), ctx.loggedArgs[2][4].(string)) - require.Equal(t, level.ErrorValue(), ctx.loggedArgs[2][5].(level.Value)) - require.Equal(t, "msg", ctx.loggedArgs[2][6].(string)) - require.Equal(t, "hello 3", ctx.loggedArgs[2][7].(string)) - - require.Len(t, ctx.loggedArgs[3], 8) - require.Equal(t, "logger", ctx.loggedArgs[3][0].(string)) - require.Equal(t, "three", ctx.loggedArgs[3][1].(string)) - require.Equal(t, "key", ctx.loggedArgs[3][2].(string)) - require.Equal(t, "value", ctx.loggedArgs[3][3].(string)) - require.Equal(t, "t", ctx.loggedArgs[3][4].(string)) - require.Equal(t, ctx.mockedTime.Format(time.RFC3339Nano), ctx.loggedArgs[3][5].(fmt.Stringer).String()) - require.Equal(t, "msg", ctx.loggedArgs[3][6].(string)) - require.Equal(t, "hello 4", ctx.loggedArgs[3][7].(string)) - - require.Len(t, ctx.loggedArgs[4], 8) - require.Equal(t, "logger", ctx.loggedArgs[4][0].(string)) - require.Equal(t, "three", ctx.loggedArgs[4][1].(string)) - require.Equal(t, "t", ctx.loggedArgs[4][2].(string)) - require.Equal(t, ctx.mockedTime.Format(time.RFC3339Nano), ctx.loggedArgs[4][3].(fmt.Stringer).String()) - require.Equal(t, level.Key().(string), ctx.loggedArgs[4][4].(string)) - require.Equal(t, level.ErrorValue(), ctx.loggedArgs[4][5].(level.Value)) - require.Equal(t, "msg", ctx.loggedArgs[4][6].(string)) - require.Equal(t, "hello 3 again", ctx.loggedArgs[4][7].(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, ctx.loggedArgs, 5) - require.Len(t, swappedLoggedArgs, 7, "expected 4 messages for AllowAll logger and 3 messages for AllowInfo logger") - }) - }) - - newLoggerScenario(t, "Logger with contextual arguments", func(t *testing.T, sCtx *scenarioContext) { - ctx := context.Background() - rootLogger := New("root") - rootLoggerCtx := rootLogger.FromContext(ctx) - rootLoggerCtx.Debug("hello root") - childLogger := rootLogger.New("childKey", "childValue") - childLoggerCtx := childLogger.FromContext(ctx) - childLoggerCtx.Error("hello child") - - RegisterContextualLogProvider(func(ctx context.Context) ([]interface{}, bool) { - return []interface{}{"ctxKey", "ctxValue"}, true - }) - - rootLoggerCtx = rootLogger.FromContext(ctx) - rootLoggerCtx.Debug("hello contextual root") - childLoggerCtx = childLogger.FromContext(ctx) - childLoggerCtx.Error("hello contextual child") - - newRootLogger := New("root") - newRootLogger.Debug("hello root") - - require.Len(t, sCtx.loggedArgs, 5) - require.Len(t, sCtx.loggedArgs[0], 8) - require.Equal(t, "logger", sCtx.loggedArgs[0][0].(string)) - require.Equal(t, "root", sCtx.loggedArgs[0][1].(string)) - require.Equal(t, "t", sCtx.loggedArgs[0][2].(string)) - require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[0][3].(fmt.Stringer).String()) - require.Equal(t, level.Key().(string), sCtx.loggedArgs[0][4].(string)) - require.Equal(t, level.DebugValue(), sCtx.loggedArgs[0][5].(level.Value)) - require.Equal(t, "msg", sCtx.loggedArgs[0][6].(string)) - require.Equal(t, "hello root", sCtx.loggedArgs[0][7].(string)) - - require.Len(t, sCtx.loggedArgs[1], 10) - require.Equal(t, "logger", sCtx.loggedArgs[1][0].(string)) - require.Equal(t, "root", sCtx.loggedArgs[1][1].(string)) - require.Equal(t, "childKey", sCtx.loggedArgs[1][2].(string)) - require.Equal(t, "childValue", sCtx.loggedArgs[1][3].(string)) - require.Equal(t, "t", sCtx.loggedArgs[1][4].(string)) - require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[1][5].(fmt.Stringer).String()) - require.Equal(t, level.Key().(string), sCtx.loggedArgs[1][6].(string)) - require.Equal(t, level.ErrorValue(), sCtx.loggedArgs[1][7].(level.Value)) - require.Equal(t, "msg", sCtx.loggedArgs[1][8].(string)) - require.Equal(t, "hello child", sCtx.loggedArgs[1][9].(string)) - - require.Len(t, sCtx.loggedArgs[2], 10) - require.Equal(t, "logger", sCtx.loggedArgs[2][0].(string)) - require.Equal(t, "root", sCtx.loggedArgs[2][1].(string)) - require.Equal(t, "ctxKey", sCtx.loggedArgs[2][2].(string)) - require.Equal(t, "ctxValue", sCtx.loggedArgs[2][3].(string)) - require.Equal(t, "t", sCtx.loggedArgs[2][4].(string)) - require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[2][5].(fmt.Stringer).String()) - require.Equal(t, level.Key().(string), sCtx.loggedArgs[2][6].(string)) - require.Equal(t, level.DebugValue(), sCtx.loggedArgs[2][7].(level.Value)) - require.Equal(t, "msg", sCtx.loggedArgs[2][8].(string)) - require.Equal(t, "hello contextual root", sCtx.loggedArgs[2][9].(string)) - - require.Len(t, sCtx.loggedArgs[3], 12) - require.Equal(t, "logger", sCtx.loggedArgs[3][0].(string)) - require.Equal(t, "root", sCtx.loggedArgs[3][1].(string)) - require.Equal(t, "childKey", sCtx.loggedArgs[3][2].(string)) - require.Equal(t, "childValue", sCtx.loggedArgs[3][3].(string)) - require.Equal(t, "ctxKey", sCtx.loggedArgs[3][4].(string)) - require.Equal(t, "ctxValue", sCtx.loggedArgs[3][5].(string)) - require.Equal(t, "t", sCtx.loggedArgs[3][6].(string)) - require.Equal(t, sCtx.mockedTime.Format(time.RFC3339Nano), sCtx.loggedArgs[3][7].(fmt.Stringer).String()) - require.Equal(t, level.Key().(string), sCtx.loggedArgs[3][8].(string)) - require.Equal(t, level.ErrorValue(), sCtx.loggedArgs[3][9].(level.Value)) - require.Equal(t, "msg", sCtx.loggedArgs[3][10].(string)) - require.Equal(t, "hello contextual child", sCtx.loggedArgs[3][11].(string)) - - require.Len(t, sCtx.loggedArgs[4], 8) + require.Len(t, scenario.loggedArgs, 5, "lines logged before swapping logger") + require.Len(t, swappedLoggedArgs, 7, "expected 4 messages for AllowAll logger and 3 messages for AllowInfo logger") }) } -func TestWithPrefix(t *testing.T) { - newLoggerScenario(t, "WithPrefix should prepend context to beginning of log message", func(t *testing.T, ctx *scenarioContext) { - ls := WithPrefix(New("test"), "k1", "v1") - ls.Info("hello", "k2", "v2") - require.Len(t, ctx.loggedArgs, 1) - require.Len(t, ctx.loggedArgs[0], 12) +func TestContextualArguments(t *testing.T) { + scenario := newLoggerScenario(t) + ctx := context.Background() - args := ctx.loggedArgs[0] - require.Equal(t, "logger", args[0].(string)) - require.Equal(t, "test", args[1].(string)) - require.Equal(t, "k1", args[2].(string)) - require.Equal(t, "v1", args[3].(string)) - require.Equal(t, "t", args[4].(string)) - require.Equal(t, ctx.mockedTime.Format(time.RFC3339Nano), args[5].(fmt.Stringer).String()) - require.Equal(t, level.Key().(string), args[6].(string)) - require.Equal(t, level.InfoValue(), args[7].(level.Value)) - require.Equal(t, "msg", args[8].(string)) - require.Equal(t, "hello", args[9].(string)) - require.Equal(t, "k2", args[10].(string)) - require.Equal(t, "v2", args[11].(string)) + rootLogger := New("root") + rootLoggerCtx := rootLogger.FromContext(ctx) + rootLoggerCtx.Debug("hello root") + childLogger := rootLogger.New("childKey", "childValue") + childLoggerCtx := childLogger.FromContext(ctx) + childLoggerCtx.Error("hello child") + + RegisterContextualLogProvider(func(ctx context.Context) ([]interface{}, bool) { + return []interface{}{"ctxKey", "ctxValue"}, true + }) + + rootLoggerCtx = rootLogger.FromContext(ctx) + rootLoggerCtx.Debug("hello contextual root") + childLoggerCtx = childLogger.FromContext(ctx) + childLoggerCtx.Error("hello contextual child") + + newRootLogger := New("root") + newRootLogger.Debug("hello root") + + require.Len(t, scenario.loggedArgs, 5) + + baseLog := []any{ + "logger", "root", + "t", scenario.mockedTime, + level.Key(), level.DebugValue(), + "msg", "hello root", + } + scenario.ValidateLineEquality(t, 0, baseLog) + + scenario.ValidateLineEquality(t, 1, []any{ + "logger", "root", + "childKey", "childValue", + "t", scenario.mockedTime, + level.Key(), level.ErrorValue(), + "msg", "hello child", + }) + + require.Len(t, scenario.loggedArgs, 5) + scenario.ValidateLineEquality(t, 2, []any{ + "logger", "root", + "ctxKey", "ctxValue", + "t", scenario.mockedTime, + level.Key(), level.DebugValue(), + "msg", "hello contextual root", + }) + + scenario.ValidateLineEquality(t, 3, []any{ + "logger", "root", + "childKey", "childValue", + "ctxKey", "ctxValue", + "t", scenario.mockedTime, + level.Key(), level.ErrorValue(), + "msg", "hello contextual child", + }) + + scenario.ValidateLineEquality(t, 4, baseLog) +} + +func TestWithPrefix_prependsContext(t *testing.T) { + scenario := newLoggerScenario(t) + ls := WithPrefix(New("test"), "k1", "v1") + ls.Info("hello", "k2", "v2") + + require.Len(t, scenario.loggedArgs, 1) + scenario.ValidateLineEquality(t, 0, []any{ + "logger", "test", + "k1", "v1", + "t", scenario.mockedTime, + level.Key(), level.InfoValue(), + "msg", "hello", + "k2", "v2", }) } -func TestWithSuffix(t *testing.T) { - newLoggerScenario(t, "WithSuffix should append context to end of log message", func(t *testing.T, ctx *scenarioContext) { - ls := WithSuffix(New("test"), "k1", "v1") - ls.Info("hello", "k2", "v2") - require.Len(t, ctx.loggedArgs, 1) - require.Len(t, ctx.loggedArgs[0], 12) +func TestWithSuffix_appendsContext(t *testing.T) { + scenario := newLoggerScenario(t) - args := ctx.loggedArgs[0] - require.Equal(t, "logger", args[0].(string)) - require.Equal(t, "test", args[1].(string)) - require.Equal(t, "t", args[2].(string)) - require.Equal(t, ctx.mockedTime.Format(time.RFC3339Nano), args[3].(fmt.Stringer).String()) - require.Equal(t, level.Key().(string), args[4].(string)) - require.Equal(t, level.InfoValue(), args[5].(level.Value)) - require.Equal(t, "msg", args[6].(string)) - require.Equal(t, "hello", args[7].(string)) - require.Equal(t, "k2", args[8].(string)) - require.Equal(t, "v2", args[9].(string)) - require.Equal(t, "k1", args[10].(string)) - require.Equal(t, "v1", args[11].(string)) + ls := WithSuffix(New("test"), "k1", "v1") + ls.Info("hello", "k2", "v2") + + require.Len(t, scenario.loggedArgs, 1) + scenario.ValidateLineEquality(t, 0, []any{ + "logger", "test", + "t", scenario.mockedTime, + level.Key(), level.InfoValue(), + "msg", "hello", + "k2", "v2", + "k1", "v1", }) } @@ -306,30 +272,48 @@ type scenarioContext struct { mockedTime time.Time } -func newLoggerScenario(t *testing.T, desc string, fn func(t *testing.T, ctx *scenarioContext)) { +func (s *scenarioContext) ValidateLineEquality(t testing.TB, n int, expected []any) { t.Helper() - ctx := &scenarioContext{ + actual := s.loggedArgs[n] + require.Len(t, actual, len(expected)) + for i := range expected { + switch ex := expected[i].(type) { + case time.Time: + assert.Equal(t, ex.Format(time.RFC3339Nano), actual[i].(fmt.Stringer).String()) + default: + assert.Equalf(t, ex, actual[i], "line %d argument %d does not match expected value.", n, i) + } + } +} + +func newLoggerScenario(t testing.TB) *scenarioContext { + t.Helper() + + scenario := &scenarioContext{ loggedArgs: [][]interface{}{}, mockedTime: time.Now(), } l := gokitlog.LoggerFunc(func(i ...interface{}) error { - ctx.loggedArgs = append(ctx.loggedArgs, i) + scenario.loggedArgs = append(scenario.loggedArgs, i) return nil }) origNow := now now = func() time.Time { - return ctx.mockedTime + return scenario.mockedTime } t.Cleanup(func() { now = origNow }) - root = newManager(l) - - t.Run(desc, func(t *testing.T) { - fn(t, ctx) + origContextHandlers := ctxLogProviders + ctxLogProviders = []ContextualLogProviderFunc{} + t.Cleanup(func() { + ctxLogProviders = origContextHandlers }) + + root = newManager(l) + return scenario }