Commit cf378095 authored by refcell's avatar refcell Committed by GitHub

feat(op-service): Introduce variadic log filters (#9469)

parent e1132e13
...@@ -21,12 +21,16 @@ func TestProgressGame_LogErrorFromAct(t *testing.T) { ...@@ -21,12 +21,16 @@ func TestProgressGame_LogErrorFromAct(t *testing.T) {
status := game.ProgressGame(context.Background()) status := game.ProgressGame(context.Background())
require.Equal(t, types.GameStatusInProgress, status) require.Equal(t, types.GameStatusInProgress, status)
require.Equal(t, 1, actor.callCount, "should perform next actions") require.Equal(t, 1, actor.callCount, "should perform next actions")
errLog := handler.FindLog(log.LevelError, "Error when acting on game") levelFilter := testlog.NewLevelFilter(log.LevelError)
msgFilter := testlog.NewMessageFilter("Error when acting on game")
errLog := handler.FindLog(levelFilter, msgFilter)
require.NotNil(t, errLog, "should log error") require.NotNil(t, errLog, "should log error")
require.Equal(t, actor.actErr, errLog.AttrValue("err")) require.Equal(t, actor.actErr, errLog.AttrValue("err"))
// Should still log game status // Should still log game status
msg := handler.FindLog(log.LevelInfo, "Game info") levelFilter = testlog.NewLevelFilter(log.LevelInfo)
msgFilter = testlog.NewMessageFilter("Game info")
msg := handler.FindLog(levelFilter, msgFilter)
require.NotNil(t, msg) require.NotNil(t, msg)
require.Equal(t, uint64(1), msg.AttrValue("claims")) require.Equal(t, uint64(1), msg.AttrValue("claims"))
} }
...@@ -62,7 +66,9 @@ func TestProgressGame_LogGameStatus(t *testing.T) { ...@@ -62,7 +66,9 @@ func TestProgressGame_LogGameStatus(t *testing.T) {
status := game.ProgressGame(context.Background()) status := game.ProgressGame(context.Background())
require.Equal(t, 1, gameState.callCount, "should perform next actions") require.Equal(t, 1, gameState.callCount, "should perform next actions")
require.Equal(t, test.status, status) require.Equal(t, test.status, status)
errLog := handler.FindLog(log.LevelInfo, test.logMsg) levelFilter := testlog.NewLevelFilter(log.LevelInfo)
msgFilter := testlog.NewMessageFilter(test.logMsg)
errLog := handler.FindLog(levelFilter, msgFilter)
require.NotNil(t, errLog, "should log game result") require.NotNil(t, errLog, "should log game result")
require.Equal(t, test.status, errLog.AttrValue("status")) require.Equal(t, test.status, errLog.AttrValue("status"))
}) })
......
...@@ -139,7 +139,9 @@ func TestRunCmdLogsOutput(t *testing.T) { ...@@ -139,7 +139,9 @@ func TestRunCmdLogsOutput(t *testing.T) {
logger, logs := testlog.CaptureLogger(t, log.LevelInfo) logger, logs := testlog.CaptureLogger(t, log.LevelInfo)
err := runCmd(ctx, logger, bin, "Hello World") err := runCmd(ctx, logger, bin, "Hello World")
require.NoError(t, err) require.NoError(t, err)
require.NotNil(t, logs.FindLog(log.LevelInfo, "Hello World")) levelFilter := testlog.NewLevelFilter(log.LevelInfo)
msgFilter := testlog.NewMessageFilter("Hello World")
require.NotNil(t, logs.FindLog(levelFilter, msgFilter))
} }
func TestFindStartingSnapshot(t *testing.T) { func TestFindStartingSnapshot(t *testing.T) {
......
...@@ -73,7 +73,9 @@ func TestChallenge(t *testing.T) { ...@@ -73,7 +73,9 @@ func TestChallenge(t *testing.T) {
err := challenger.Challenge(context.Background(), common.Hash{0xaa}, oracle, preimages) err := challenger.Challenge(context.Background(), common.Hash{0xaa}, oracle, preimages)
require.NoError(t, err) require.NoError(t, err)
errLog := logs.FindLog(log.LevelError, "Failed to create challenge transaction") levelFilter := testlog.NewLevelFilter(log.LevelError)
msgFilter := testlog.NewMessageFilter("Failed to create challenge transaction")
errLog := logs.FindLog(levelFilter, msgFilter)
require.ErrorIs(t, errLog.AttrValue("err").(error), oracle.err) require.ErrorIs(t, errLog.AttrValue("err").(error), oracle.err)
}) })
...@@ -86,7 +88,9 @@ func TestChallenge(t *testing.T) { ...@@ -86,7 +88,9 @@ func TestChallenge(t *testing.T) {
err := challenger.Challenge(context.Background(), common.Hash{0xaa}, oracle, preimages) err := challenger.Challenge(context.Background(), common.Hash{0xaa}, oracle, preimages)
require.NoError(t, err) require.NoError(t, err)
errLog := logs.FindLog(log.LevelError, "Failed to verify large preimage") levelFilter := testlog.NewLevelFilter(log.LevelError)
msgFilter := testlog.NewMessageFilter("Failed to verify large preimage")
errLog := logs.FindLog(levelFilter, msgFilter)
require.ErrorIs(t, errLog.AttrValue("err").(error), verifier.err) require.ErrorIs(t, errLog.AttrValue("err").(error), verifier.err)
}) })
...@@ -98,10 +102,14 @@ func TestChallenge(t *testing.T) { ...@@ -98,10 +102,14 @@ func TestChallenge(t *testing.T) {
err := challenger.Challenge(context.Background(), common.Hash{0xaa}, oracle, preimages) err := challenger.Challenge(context.Background(), common.Hash{0xaa}, oracle, preimages)
require.NoError(t, err) require.NoError(t, err)
errLog := logs.FindLog(log.LevelError, "Failed to verify large preimage") levelFilter := testlog.NewLevelFilter(log.LevelError)
msgFilter := testlog.NewMessageFilter("Failed to verify large preimage")
errLog := logs.FindLog(levelFilter, msgFilter)
require.Nil(t, errLog) require.Nil(t, errLog)
dbgLog := logs.FindLog(log.LevelDebug, "Preimage is valid") levelFilter = testlog.NewLevelFilter(log.LevelDebug)
msgFilter = testlog.NewMessageFilter("Preimage is valid")
dbgLog := logs.FindLog(levelFilter, msgFilter)
require.NotNil(t, dbgLog) require.NotNil(t, dbgLog)
}) })
} }
......
...@@ -213,10 +213,12 @@ func TestDetector_CheckAgreement_Succeeds(t *testing.T) { ...@@ -213,10 +213,12 @@ func TestDetector_CheckAgreement_Succeeds(t *testing.T) {
require.NoError(t, err) require.NoError(t, err)
test.expectBatch(&batch) test.expectBatch(&batch)
levelFilter := testlog.NewLevelFilter(log.LevelError)
if !test.expectErrorLog { if !test.expectErrorLog {
require.Empty(t, logs.FindLogsWithLevel(log.LevelError), "Should not log an error`") require.Empty(t, logs.FindLogs(levelFilter), "Should not log an error")
} else { } else {
l := logs.FindLog(log.LevelError, "Unexpected game result") msgFilter := testlog.NewMessageFilter("Unexpected game result")
l := logs.FindLog(levelFilter, msgFilter)
require.NotNil(t, l, "Should have logged an error") require.NotNil(t, l, "Should have logged an error")
expectedResult := l.AttrValue("expectedResult") expectedResult := l.AttrValue("expectedResult")
require.Equal(t, test.expectStatus, expectedResult) require.Equal(t, test.expectStatus, expectedResult)
......
...@@ -1523,14 +1523,16 @@ func TestValidBatch(t *testing.T) { ...@@ -1523,14 +1523,16 @@ func TestValidBatch(t *testing.T) {
require.Equal(t, testCase.Expected, validity, "batch check must return expected validity level") require.Equal(t, testCase.Expected, validity, "batch check must return expected validity level")
if expLog := testCase.ExpectedLog; expLog != "" { if expLog := testCase.ExpectedLog; expLog != "" {
// Check if ExpectedLog is contained in the log buffer // Check if ExpectedLog is contained in the log buffer
if _, ok := logs.FindLogContaining(expLog); !ok { containsFilter := testlog.NewMessageContainsFilter(expLog)
if l := logs.FindLog(containsFilter); l == nil {
t.Errorf("Expected log message was not logged: %q", expLog) t.Errorf("Expected log message was not logged: %q", expLog)
} }
} }
if notExpLog := testCase.NotExpectedLog; notExpLog != "" { if notExpLog := testCase.NotExpectedLog; notExpLog != "" {
// Check if NotExpectedLog is contained in the log buffer // Check if NotExpectedLog is contained in the log buffer
if rec, ok := logs.FindLogContaining(notExpLog); ok { containsFilter := testlog.NewMessageContainsFilter(notExpLog)
t.Errorf("Unexpected log message containing %q was logged: %q", notExpLog, rec.Message) if l := logs.FindLog(containsFilter); l != nil {
t.Errorf("Unexpected log message containing %q was logged: %q", notExpLog, l.Message)
} }
} }
logs.Clear() logs.Clear()
......
...@@ -28,7 +28,9 @@ func TestLogWriter(t *testing.T) { ...@@ -28,7 +28,9 @@ func TestLogWriter(t *testing.T) {
count, err := writer.Write(line) count, err := writer.Write(line)
require.NoError(t, err) require.NoError(t, err)
require.Equal(t, len(line), count) require.Equal(t, len(line), count)
require.NotNil(t, logs.FindLog(log.LevelInfo, "Test line")) levelFilter := testlog.NewLevelFilter(log.LevelInfo)
msgFilter := testlog.NewMessageFilter("Test line")
require.NotNil(t, logs.FindLog(levelFilter, msgFilter))
}) })
t.Run("LogMultipleLines", func(t *testing.T) { t.Run("LogMultipleLines", func(t *testing.T) {
...@@ -37,8 +39,11 @@ func TestLogWriter(t *testing.T) { ...@@ -37,8 +39,11 @@ func TestLogWriter(t *testing.T) {
count, err := writer.Write(line) count, err := writer.Write(line)
require.NoError(t, err) require.NoError(t, err)
require.Equal(t, len(line), count) require.Equal(t, len(line), count)
require.NotNil(t, logs.FindLog(log.LevelInfo, "Line 1")) levelFilter := testlog.NewLevelFilter(log.LevelInfo)
require.NotNil(t, logs.FindLog(log.LevelInfo, "Line 2")) lineOneFilter := testlog.NewMessageFilter("Line 1")
lineTwoFilter := testlog.NewMessageFilter("Line 2")
require.NotNil(t, logs.FindLog(levelFilter, lineOneFilter))
require.NotNil(t, logs.FindLog(levelFilter, lineTwoFilter))
}) })
t.Run("LogLineAcrossMultipleCalls", func(t *testing.T) { t.Run("LogLineAcrossMultipleCalls", func(t *testing.T) {
...@@ -47,14 +52,19 @@ func TestLogWriter(t *testing.T) { ...@@ -47,14 +52,19 @@ func TestLogWriter(t *testing.T) {
count, err := writer.Write(line) count, err := writer.Write(line)
require.NoError(t, err) require.NoError(t, err)
require.Equal(t, len(line), count) require.Equal(t, len(line), count)
require.NotNil(t, logs.FindLog(log.LevelInfo, "First line")) levelFilter := testlog.NewLevelFilter(log.LevelInfo)
msgFilter := testlog.NewMessageFilter("First line")
require.NotNil(t, logs.FindLog(levelFilter, msgFilter))
line = []byte("Line\nLast Line\n") line = []byte("Line\nLast Line\n")
count, err = writer.Write(line) count, err = writer.Write(line)
require.NoError(t, err) require.NoError(t, err)
require.Equal(t, len(line), count) require.Equal(t, len(line), count)
require.NotNil(t, logs.FindLog(log.LevelInfo, "Split Line")) levelFilter = testlog.NewLevelFilter(log.LevelInfo)
require.NotNil(t, logs.FindLog(log.LevelInfo, "Last Line")) splitLineFilter := testlog.NewMessageFilter("Split Line")
lastLineFilter := testlog.NewMessageFilter("Last Line")
require.NotNil(t, logs.FindLog(levelFilter, splitLineFilter))
require.NotNil(t, logs.FindLog(levelFilter, lastLineFilter))
}) })
// Can't test LevelCrit or it will call os.Exit // Can't test LevelCrit or it will call os.Exit
...@@ -66,7 +76,9 @@ func TestLogWriter(t *testing.T) { ...@@ -66,7 +76,9 @@ func TestLogWriter(t *testing.T) {
count, err := writer.Write(line) count, err := writer.Write(line)
require.NoError(t, err) require.NoError(t, err)
require.Equal(t, len(line), count) require.Equal(t, len(line), count)
require.NotNil(t, logs.FindLog(lvl, "Log line")) levelFilter := testlog.NewLevelFilter(lvl)
msgFilter := testlog.NewMessageFilter("Log line")
require.NotNil(t, logs.FindLog(levelFilter, msgFilter))
}) })
} }
...@@ -77,7 +89,10 @@ func TestLogWriter(t *testing.T) { ...@@ -77,7 +89,10 @@ func TestLogWriter(t *testing.T) {
count, err := writer.Write(line) count, err := writer.Write(line)
require.NoError(t, err) require.NoError(t, err)
require.Equal(t, len(line), count) require.Equal(t, len(line), count)
require.NotNil(t, logs.FindLog(log.LevelError, "Unknown log level. Using Error")) levelFilter := testlog.NewLevelFilter(log.LevelError)
require.NotNil(t, logs.FindLog(log.LevelError, "Log line")) unknownFilter := testlog.NewMessageFilter("Unknown log level. Using Error")
logLineFilter := testlog.NewMessageFilter("Log line")
require.NotNil(t, logs.FindLog(levelFilter, unknownFilter))
require.NotNil(t, logs.FindLog(levelFilter, logLineFilter))
}) })
} }
...@@ -56,34 +56,59 @@ func (c *CapturingHandler) Clear() { ...@@ -56,34 +56,59 @@ func (c *CapturingHandler) Clear() {
*c.Logs = (*c.Logs)[:0] // reuse slice *c.Logs = (*c.Logs)[:0] // reuse slice
} }
func (c *CapturingHandler) FindLog(lvl slog.Level, msg string) *HelperRecord { func NewLevelFilter(level slog.Level) LogFilter {
return func(r *slog.Record) bool {
return r.Level == level
}
}
func NewMessageFilter(message string) LogFilter {
return func(r *slog.Record) bool {
return r.Message == message
}
}
func NewMessageContainsFilter(message string) LogFilter {
return func(r *slog.Record) bool {
return strings.Contains(r.Message, message)
}
}
type LogFilter func(*slog.Record) bool
func (c *CapturingHandler) FindLog(filters ...LogFilter) *HelperRecord {
for _, record := range *c.Logs { for _, record := range *c.Logs {
if record.Level == lvl && record.Message == msg { match := true
for _, filter := range filters {
if !filter(record) {
match = false
break
}
}
if match {
return &HelperRecord{record} return &HelperRecord{record}
} }
} }
return nil return nil
} }
func (c *CapturingHandler) FindLogsWithLevel(lvl slog.Level) []*HelperRecord { func (c *CapturingHandler) FindLogs(filters ...LogFilter) []*HelperRecord {
var logs []*HelperRecord var logs []*HelperRecord
for _, record := range *c.Logs { for _, record := range *c.Logs {
if record.Level == lvl { match := true
for _, filter := range filters {
if !filter(record) {
match = false
break
}
}
if match {
logs = append(logs, &HelperRecord{record}) logs = append(logs, &HelperRecord{record})
} }
} }
return logs return logs
} }
func (c *CapturingHandler) FindLogContaining(msg string) (*HelperRecord, bool) {
for _, record := range *c.Logs {
if strings.Contains(record.Message, msg) {
return &HelperRecord{record}, true
}
}
return nil, false
}
type HelperRecord struct { type HelperRecord struct {
*slog.Record *slog.Record
} }
......
...@@ -12,27 +12,32 @@ func TestCaptureLogger(t *testing.T) { ...@@ -12,27 +12,32 @@ func TestCaptureLogger(t *testing.T) {
lgr, logs := testlog.CaptureLogger(t, log.LevelInfo) lgr, logs := testlog.CaptureLogger(t, log.LevelInfo)
msg := "foo bar" msg := "foo bar"
lgr.Info(msg, "a", 1) lgr.Info(msg, "a", 1)
rec, ok := logs.FindLogContaining("foo") msgFilter := testlog.NewMessageFilter(msg)
require.True(t, ok) rec := logs.FindLog(msgFilter)
require.Equal(t, msg, rec.Message) require.Equal(t, msg, rec.Message)
require.EqualValues(t, 1, rec.AttrValue("a")) require.EqualValues(t, 1, rec.AttrValue("a"))
lgr.Debug("bug") lgr.Debug("bug")
_, ok = logs.FindLogContaining("bug") containsFilter := testlog.NewMessageContainsFilter("bug")
require.True(t, ok, "should capture all logs, not only above level") l := logs.FindLog(containsFilter)
require.NotNil(t, l, "should capture all logs, not only above level")
msgClear := "clear" msgClear := "clear"
lgr.Error(msgClear) lgr.Error(msgClear)
require.NotNil(t, logs.FindLog(log.LevelError, msgClear)) levelFilter := testlog.NewLevelFilter(log.LevelError)
msgFilter = testlog.NewMessageFilter(msgClear)
require.NotNil(t, logs.FindLog(levelFilter, msgFilter))
logs.Clear() logs.Clear()
_, ok = logs.FindLogContaining(msgClear) containsFilter = testlog.NewMessageContainsFilter(msgClear)
require.False(t, ok) l = logs.FindLog(containsFilter)
require.Nil(t, l)
lgrb := lgr.New("b", 2) lgrb := lgr.New("b", 2)
msgOp := "optimistic" msgOp := "optimistic"
lgrb.Info(msgOp, "c", 3) lgrb.Info(msgOp, "c", 3)
recOp, ok := logs.FindLogContaining(msgOp) containsFilter = testlog.NewMessageContainsFilter(msgOp)
require.True(t, ok, "should still capture logs from derived logger") recOp := logs.FindLog(containsFilter)
require.NotNil(t, recOp, "should still capture logs from derived logger")
require.EqualValues(t, 3, recOp.AttrValue("c")) require.EqualValues(t, 3, recOp.AttrValue("c"))
// Note: "b" attributes won't be visible on captured record // Note: "b" attributes won't be visible on captured record
} }
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment