From a3ffae3ecc28c7d01af370b140dd38bc8c717774 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sun, 13 Feb 2022 01:11:35 +0800 Subject: [PATCH] Add test log checker --- modules/log/event.go | 11 +++ modules/testlog/testlog.go | 114 ++++++++++++++++++++++++++++++++ modules/testlog/testlog_test.go | 34 ++++++++++ 3 files changed, 159 insertions(+) create mode 100644 modules/testlog/testlog.go create mode 100644 modules/testlog/testlog_test.go diff --git a/modules/log/event.go b/modules/log/event.go index 00a66c306abef..2cad29ed9b0c1 100644 --- a/modules/log/event.go +++ b/modules/log/event.go @@ -7,6 +7,7 @@ package log import ( "fmt" "sync" + "sync/atomic" "time" ) @@ -152,6 +153,7 @@ type MultiChannelledLog struct { stacktraceLevel Level closed chan bool paused chan bool + processedCount int64 } // NewMultiChannelledLog a new logger instance with given logger provider and config. @@ -307,6 +309,7 @@ func (m *MultiChannelledLog) Start() { m.closeLoggers() return } + atomic.AddInt64(&m.processedCount, 1) m.rwmutex.RLock() for _, logger := range m.loggers { err := logger.LogEvent(event) @@ -346,6 +349,10 @@ func (m *MultiChannelledLog) LogEvent(event *Event) error { } } +func (m *MultiChannelledLog) GetProcessedCount() int64 { + return atomic.LoadInt64(&m.processedCount) +} + // Close this MultiChannelledLog func (m *MultiChannelledLog) Close() { m.close <- true @@ -397,3 +404,7 @@ func (m *MultiChannelledLog) ResetLevel() Level { func (m *MultiChannelledLog) GetName() string { return m.name } + +func (e *Event) GetMsg() string { + return e.msg +} diff --git a/modules/testlog/testlog.go b/modules/testlog/testlog.go new file mode 100644 index 0000000000000..d4741fa1b2e70 --- /dev/null +++ b/modules/testlog/testlog.go @@ -0,0 +1,114 @@ +// Copyright 2022 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package testlog + +import ( + "fmt" + "strconv" + "strings" + "sync" + "sync/atomic" + "time" + + "code.gitea.io/gitea/modules/log" +) + +type LogChecker struct { + logger *log.MultiChannelledLogger + loggerName string + eventLoggerName string + expectedMessages []string + expectedMessageIdx int + mu sync.Mutex +} + +func (lc *LogChecker) LogEvent(event *log.Event) error { + lc.mu.Lock() + defer lc.mu.Unlock() + + if lc.expectedMessageIdx < len(lc.expectedMessages) { + if strings.Contains(event.GetMsg(), lc.expectedMessages[lc.expectedMessageIdx]) { + lc.expectedMessageIdx++ + } + } + return nil +} + +func (lc *LogChecker) Close() { +} + +func (lc *LogChecker) Flush() { +} + +func (lc *LogChecker) GetLevel() log.Level { + return log.TRACE +} + +func (lc *LogChecker) GetStacktraceLevel() log.Level { + return log.NONE +} + +func (lc *LogChecker) GetName() string { + return lc.eventLoggerName +} + +func (lc *LogChecker) ReleaseReopen() error { + return nil +} + +var checkerIndex int64 + +func NewLogChecker(loggerName string) (*LogChecker, func()) { + logger := log.GetLogger(loggerName) + newCheckerIndex := atomic.AddInt64(&checkerIndex, 1) + lc := &LogChecker{ + logger: logger, + loggerName: loggerName, + eventLoggerName: "TestLogChecker-" + strconv.FormatInt(newCheckerIndex, 10), + } + + if err := logger.AddLogger(lc); err != nil { + panic(err) // it's impossible + } + + return lc, func() { + _, _ = logger.DelLogger(lc.GetName()) + } +} + +// ExpectContains will make the `Check` function to check if these logs are outputted. +// we could refactor this function to accept user-defined functions to do more filter work, ex: Except(Contains("..."), NotContains("..."), ...) +func (lc *LogChecker) ExpectContains(msg string, msgs ...string) { + lc.expectedMessages = make([]string, 0, len(msg)+1) + lc.expectedMessages = append(lc.expectedMessages, msg) + lc.expectedMessages = append(lc.expectedMessages, msgs...) +} + +// Check returns nil if the logs are expected. Otherwise it returns the error with reason. +func (lc *LogChecker) Check() error { + lastProcessedCount := lc.logger.GetProcessedCount() + + // in case the LogEvent is still being processed, we should wait for a while to make sure our EventLogger could receive all events. + for i := 0; i < 100; i++ { + lc.mu.Lock() + if lc.expectedMessageIdx == len(lc.expectedMessages) { + return nil + } + lc.mu.Unlock() + + // we assume that the MultiChannelledLog can process one log event in 10ms. + // if there is a long time that no more log is processed, then we are sure that there is really no more logs. + time.Sleep(10 * time.Millisecond) + currProcessedCount := lc.logger.GetProcessedCount() + if currProcessedCount == lastProcessedCount { + break + } + lastProcessedCount = currProcessedCount + } + + lc.mu.Lock() + defer lc.mu.Unlock() + return fmt.Errorf("expect to see message: %q, but failed", lc.expectedMessages[lc.expectedMessageIdx]) +} diff --git a/modules/testlog/testlog_test.go b/modules/testlog/testlog_test.go new file mode 100644 index 0000000000000..37d52c85f42ff --- /dev/null +++ b/modules/testlog/testlog_test.go @@ -0,0 +1,34 @@ +// Copyright 2022 The Gitea Authors. All rights reserved. +// Use of this source code is governed by a MIT-style +// license that can be found in the LICENSE file. + +package testlog + +import ( + "testing" + + "code.gitea.io/gitea/modules/log" + + "github.com/stretchr/testify/assert" +) + +func TestLogChecker(t *testing.T) { + _ = log.NewLogger(1000, "console", "console", `{"level":"info","stacktracelevel":"NONE","stderr":true}`) + + lc, cleanup := NewLogChecker(log.DEFAULT) + defer cleanup() + + lc.ExpectContains("First", "Third") + + log.Info("test") + assert.Error(t, lc.Check()) + + log.Info("First") + assert.Error(t, lc.Check()) + + log.Info("Second") + assert.Error(t, lc.Check()) + + log.Info("Third") + assert.NoError(t, lc.Check()) +}