Add test log checker

Author: wxiaoguang

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

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])
+}

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())
+}