mirror of
https://github.com/grafana/grafana.git
synced 2025-02-25 18:55:37 -06:00
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.
This commit is contained in:
Emil Tullstedt
GitHub
parent
9b7418ec17
commit
88323a30b7
@ -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
|
||||
}
|
||||
|
||||
Loading…
Reference in New Issue
Block a user