From ca311bf94f5bf7443e37cdb3a557277a2a4e7aa8 Mon Sep 17 00:00:00 2001 From: Marcus Efraimsson Date: Thu, 10 Feb 2022 12:51:51 +0100 Subject: [PATCH] Logging: Fix server hangs when using log.WithSuffix (#45213) Fixes a problem where server hangs if setting GF_DATABASE_LOG_QUERIES=true. Ref #44925 --- pkg/infra/log/log.go | 2 +- pkg/infra/log/log_test.go | 159 ++++++++++++++++++++++++++------------ 2 files changed, 112 insertions(+), 49 deletions(-) diff --git a/pkg/infra/log/log.go b/pkg/infra/log/log.go index 14eac121bd7..683336045d1 100644 --- a/pkg/infra/log/log.go +++ b/pkg/infra/log/log.go @@ -206,7 +206,7 @@ func with(ctxLogger *ConcreteLogger, withFunc func(gokitlog.Logger, ...interface return ctxLogger } - ctxLogger.Swap(withFunc(&ctxLogger.SwapLogger, ctx...)) + ctxLogger.Swap(withFunc(ctxLogger.GetLogger(), ctx...)) return ctxLogger } diff --git a/pkg/infra/log/log_test.go b/pkg/infra/log/log_test.go index c914d6fd93b..a3c7fef24fd 100644 --- a/pkg/infra/log/log_test.go +++ b/pkg/infra/log/log_test.go @@ -18,23 +18,7 @@ func TestLogger(t *testing.T) { 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) + 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) @@ -47,36 +31,36 @@ func TestLogger(t *testing.T) { 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)) + require.Len(t, ctx.loggedArgs, 4) + require.Len(t, ctx.loggedArgs[0], 4) + require.Equal(t, "logger", ctx.loggedArgs[0][0].(string)) + require.Equal(t, "one", ctx.loggedArgs[0][1].(string)) + require.Equal(t, "msg", ctx.loggedArgs[0][2].(string)) + require.Equal(t, "hello 1", ctx.loggedArgs[0][3].(string)) + + require.Len(t, ctx.loggedArgs[1], 4) + require.Equal(t, "logger", ctx.loggedArgs[1][0].(string)) + require.Equal(t, "two", ctx.loggedArgs[1][1].(string)) + require.Equal(t, "msg", ctx.loggedArgs[1][2].(string)) + require.Equal(t, "hello 2", ctx.loggedArgs[1][3].(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("2006-01-02T15:04:05.99-0700"), ctx.loggedArgs[2][3].(fmt.Stringer).String()) + require.Equal(t, "lvl", 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], 6) + 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, "msg", ctx.loggedArgs[3][4].(string)) + require.Equal(t, "hello 4", ctx.loggedArgs[3][5].(string)) t.Run("When initializing root logger should swap loggers as expected", func(t *testing.T) { swappedLoggedArgs := [][]interface{}{} @@ -103,12 +87,58 @@ func TestLogger(t *testing.T) { log3.Error("hello 3") log3.Debug("debug") - require.Len(t, loggedArgs, 4) + require.Len(t, ctx.loggedArgs, 4) 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) + + 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("2006-01-02T15:04:05.99-0700"), args[5].(fmt.Stringer).String()) + require.Equal(t, "lvl", 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)) + }) +} + +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) + + 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("2006-01-02T15:04:05.99-0700"), args[3].(fmt.Stringer).String()) + require.Equal(t, "lvl", 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)) + }) +} + func TestGetFilters(t *testing.T) { t.Run("Parsing filters on single line with only space should return expected result", func(t *testing.T) { filter := ` ` @@ -178,3 +208,36 @@ func TestGetFilters(t *testing.T) { }, keys) }) } + +type scenarioContext struct { + loggedArgs [][]interface{} + mockedTime time.Time +} + +func newLoggerScenario(t *testing.T, desc string, fn func(t *testing.T, ctx *scenarioContext)) { + t.Helper() + + ctx := &scenarioContext{ + loggedArgs: [][]interface{}{}, + mockedTime: time.Now(), + } + + l := gokitlog.LoggerFunc(func(i ...interface{}) error { + ctx.loggedArgs = append(ctx.loggedArgs, i) + return nil + }) + + origNow := now + now = func() time.Time { + return ctx.mockedTime + } + t.Cleanup(func() { + now = origNow + }) + + root = newManager(l) + + t.Run(desc, func(t *testing.T) { + fn(t, ctx) + }) +}