apitech
/
grafana
mirror of https://github.com/grafana/grafana
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

Logging: Fix server hangs when using log.WithSuffix (#45213)

Browse Source 
Fixes a problem where server hangs if setting 
GF_DATABASE_LOG_QUERIES=true.

Ref #44925
pull/45228/head
Marcus Efraimsson 4 years ago committed by GitHub
parent e48baefd32
commit ca311bf94f
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 112 additions and 49 deletions
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Show Stats Download Patch File Download Diff File
  1. 2
      pkg/infra/log/log.go
  2. 159
      pkg/infra/log/log_test.go

2
pkg/infra/log/log.go
Unescape View File

@ -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
}

159
pkg/infra/log/log_test.go
Unescape View File

@ -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)
})
}

Write Preview
Loading…
Cancel
Save