Improve test logger (#24235)

Before, there was a `log/buffer.go`, but that design is not general, and
it introduces a lot of irrelevant `Content() (string, error) ` and
`return "", fmt.Errorf("not supported")` .


And the old `log/buffer.go` is difficult to use, developers have to
write a lot of `Contains` and `Sleep` code.


The new `LogChecker` is designed to be a general approach to help to
assert some messages appearing or not appearing in logs.

models/migrations/base/testlogger.go

@@ -165,11 +165,6 @@ func (log *TestLogger) Init(config string) error {
 	return nil
 }
 
-// Content returns the content accumulated in the content provider
-func (log *TestLogger) Content() (string, error) {
-	return "", fmt.Errorf("not supported")
-}
-
 // Flush when log should be flushed
 func (log *TestLogger) Flush() {
 }

modules/log/buffer.go

@@ -1,71 +0,0 @@
-// Copyright 2022 The Gitea Authors. All rights reserved.
-// SPDX-License-Identifier: MIT
-
-package log
-
-import (
-	"bytes"
-	"sync"
-)
-
-type bufferWriteCloser struct {
-	mu     sync.Mutex
-	buffer bytes.Buffer
-}
-
-func (b *bufferWriteCloser) Write(p []byte) (int, error) {
-	b.mu.Lock()
-	defer b.mu.Unlock()
-	return b.buffer.Write(p)
-}
-
-func (b *bufferWriteCloser) Close() error {
-	return nil
-}
-
-func (b *bufferWriteCloser) String() string {
-	b.mu.Lock()
-	defer b.mu.Unlock()
-	return b.buffer.String()
-}
-
-// BufferLogger implements LoggerProvider and writes messages in a buffer.
-type BufferLogger struct {
-	WriterLogger
-}
-
-// NewBufferLogger create BufferLogger returning as LoggerProvider.
-func NewBufferLogger() LoggerProvider {
-	log := &BufferLogger{}
-	log.NewWriterLogger(&bufferWriteCloser{})
-	return log
-}
-
-// Init inits connection writer
-func (log *BufferLogger) Init(string) error {
-	log.NewWriterLogger(log.out)
-	return nil
-}
-
-// Content returns the content accumulated in the content provider
-func (log *BufferLogger) Content() (string, error) {
-	return log.out.(*bufferWriteCloser).String(), nil
-}
-
-// Flush when log should be flushed
-func (log *BufferLogger) Flush() {
-}
-
-// ReleaseReopen does nothing
-func (log *BufferLogger) ReleaseReopen() error {
-	return nil
-}
-
-// GetName returns the default name for this implementation
-func (log *BufferLogger) GetName() string {
-	return "buffer"
-}
-
-func init() {
-	Register("buffer", NewBufferLogger)
-}

modules/log/buffer_test.go

@@ -1,63 +0,0 @@
-// Copyright 2022 The Gitea Authors. All rights reserved.
-// SPDX-License-Identifier: MIT
-
-package log
-
-import (
-	"fmt"
-	"strings"
-	"testing"
-	"time"
-
-	"github.com/stretchr/testify/assert"
-)
-
-func TestBufferLogger(t *testing.T) {
-	logger := NewBufferLogger()
-	bufferLogger := logger.(*BufferLogger)
-	assert.NotNil(t, bufferLogger)
-
-	err := logger.Init("")
-	assert.NoError(t, err)
-
-	location, _ := time.LoadLocation("EST")
-	date := time.Date(2019, time.January, 13, 22, 3, 30, 15, location)
-
-	msg := "TEST MSG"
-	event := Event{
-		level:    INFO,
-		msg:      msg,
-		caller:   "CALLER",
-		filename: "FULL/FILENAME",
-		line:     1,
-		time:     date,
-	}
-	logger.LogEvent(&event)
-	content, err := bufferLogger.Content()
-	assert.NoError(t, err)
-	assert.Contains(t, content, msg)
-	logger.Close()
-}
-
-func TestBufferLoggerContent(t *testing.T) {
-	level := INFO
-	logger := NewLogger(0, "console", "console", fmt.Sprintf(`{"level":"%s"}`, level.String()))
-
-	logger.SetLogger("buffer", "buffer", "{}")
-	defer logger.DelLogger("buffer")
-
-	msg := "A UNIQUE MESSAGE"
-	Error(msg)
-
-	found := false
-	for i := 0; i < 30000; i++ {
-		content, err := logger.GetLoggerProviderContent("buffer")
-		assert.NoError(t, err)
-		if strings.Contains(content, msg) {
-			found = true
-			break
-		}
-		time.Sleep(1 * time.Millisecond)
-	}
-	assert.True(t, found)
-}

modules/log/conn.go

@@ -118,11 +118,6 @@ func (log *ConnLogger) Init(jsonconfig string) error {
 	return nil
 }
 
-// Content returns the content accumulated in the content provider
-func (log *ConnLogger) Content() (string, error) {
-	return "", fmt.Errorf("not supported")
-}
-
 // Flush does nothing for this implementation
 func (log *ConnLogger) Flush() {
 }

modules/log/console.go

@@ -65,11 +65,6 @@ func (log *ConsoleLogger) Init(config string) error {
 	return nil
 }
 
-// Content returns the content accumulated in the content provider
-func (log *ConsoleLogger) Content() (string, error) {
-	return "", fmt.Errorf("not supported")
-}
-
 // Flush when log should be flushed
 func (log *ConsoleLogger) Flush() {
 }

modules/log/event.go

@@ -247,12 +247,6 @@ func (m *MultiChannelledLog) GetEventLogger(name string) EventLogger {
 	return m.loggers[name]
 }
 
-// GetEventProvider returns a sub logger provider content from this MultiChannelledLog
-func (m *MultiChannelledLog) GetLoggerProviderContent(name string) (string, error) {
-	channelledLogger := m.GetEventLogger(name).(*ChannelledLog)
-	return channelledLogger.loggerProvider.Content()
-}
-
 // GetEventLoggerNames returns a list of names
 func (m *MultiChannelledLog) GetEventLoggerNames() []string {
 	m.rwmutex.RLock()
@@ -460,3 +454,7 @@ func (m *MultiChannelledLog) ResetLevel() Level {
 func (m *MultiChannelledLog) GetName() string {
 	return m.name
 }
+
+func (e *Event) GetMsg() string {
+	return e.msg
+}

modules/log/file.go

@@ -253,15 +253,6 @@ func (log *FileLogger) deleteOldLog() {
 	})
 }
 
-// Content returns the content accumulated in the content provider
-func (log *FileLogger) Content() (string, error) {
-	b, err := os.ReadFile(log.Filename)
-	if err != nil {
-		return "", err
-	}
-	return string(b), nil
-}
-
 // Flush flush file logger.
 // there are no buffering messages in file logger in memory.
 // flush file means sync file from disk.

modules/log/provider.go

@@ -6,7 +6,6 @@ package log
 // LoggerProvider represents behaviors of a logger provider.
 type LoggerProvider interface {
 	Init(config string) error
-	Content() (string, error)
 	EventLogger
 }
 

modules/log/smtp.go

@@ -95,11 +95,6 @@ func (log *SMTPLogger) sendMail(p []byte) (int, error) {
 	)
 }
 
-// Content returns the content accumulated in the content provider
-func (log *SMTPLogger) Content() (string, error) {
-	return "", fmt.Errorf("not supported")
-}
-
 // Flush when log should be flushed
 func (log *SMTPLogger) Flush() {
 }

modules/test/logchecker.go

@@ -0,0 +1,116 @@
+// Copyright 2023 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package test
+
+import (
+	"strconv"
+	"strings"
+	"sync"
+	"sync/atomic"
+	"time"
+
+	"code.gitea.io/gitea/modules/log"
+)
+
+type LogChecker struct {
+	logger          *log.MultiChannelledLogger
+	loggerName      string
+	eventLoggerName string
+
+	filterMessages []string
+	filtered       []bool
+
+	stopMark string
+	stopped  bool
+
+	mu sync.Mutex
+}
+
+func (lc *LogChecker) LogEvent(event *log.Event) error {
+	lc.mu.Lock()
+	defer lc.mu.Unlock()
+	for i, msg := range lc.filterMessages {
+		if strings.Contains(event.GetMsg(), msg) {
+			lc.filtered[i] = true
+		}
+	}
+	if strings.Contains(event.GetMsg(), lc.stopMark) {
+		lc.stopped = true
+	}
+	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 *LogChecker, cancel 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()) }
+}
+
+// Filter will make the `Check` function to check if these logs are outputted.
+func (lc *LogChecker) Filter(msgs ...string) *LogChecker {
+	lc.mu.Lock()
+	defer lc.mu.Unlock()
+	lc.filterMessages = make([]string, len(msgs))
+	copy(lc.filterMessages, msgs)
+	lc.filtered = make([]bool, len(lc.filterMessages))
+	return lc
+}
+
+func (lc *LogChecker) StopMark(msg string) *LogChecker {
+	lc.mu.Lock()
+	defer lc.mu.Unlock()
+	lc.stopMark = msg
+	lc.stopped = false
+	return lc
+}
+
+// Check returns the filtered slice and whether the stop mark is reached.
+func (lc *LogChecker) Check(d time.Duration) (filtered []bool, stopped bool) {
+	stop := time.Now().Add(d)
+
+	for {
+		lc.mu.Lock()
+		stopped = lc.stopped
+		lc.mu.Unlock()
+
+		if time.Now().After(stop) || stopped {
+			lc.mu.Lock()
+			f := make([]bool, len(lc.filtered))
+			copy(f, lc.filtered)
+			lc.mu.Unlock()
+			return f, stopped
+		}
+		time.Sleep(10 * time.Millisecond)
+	}
+}

modules/test/logchecker_test.go

@@ -0,0 +1,47 @@
+// Copyright 2023 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package test
+
+import (
+	"testing"
+	"time"
+
+	"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.Filter("First", "Third").StopMark("End")
+	log.Info("test")
+
+	filtered, stopped := lc.Check(100 * time.Millisecond)
+	assert.EqualValues(t, []bool{false, false}, filtered)
+	assert.EqualValues(t, false, stopped)
+
+	log.Info("First")
+	filtered, stopped = lc.Check(100 * time.Millisecond)
+	assert.EqualValues(t, []bool{true, false}, filtered)
+	assert.EqualValues(t, false, stopped)
+
+	log.Info("Second")
+	filtered, stopped = lc.Check(100 * time.Millisecond)
+	assert.EqualValues(t, []bool{true, false}, filtered)
+	assert.EqualValues(t, false, stopped)
+
+	log.Info("Third")
+	filtered, stopped = lc.Check(100 * time.Millisecond)
+	assert.EqualValues(t, []bool{true, true}, filtered)
+	assert.EqualValues(t, false, stopped)
+
+	log.Info("End")
+	filtered, stopped = lc.Check(100 * time.Millisecond)
+	assert.EqualValues(t, []bool{true, true}, filtered)
+	assert.EqualValues(t, true, stopped)
+}

services/migrations/gitea_uploader_test.go

@@ -10,7 +10,6 @@ import (
 	"os"
 	"path/filepath"
 	"strconv"
-	"strings"
 	"testing"
 	"time"
 
@@ -24,6 +23,7 @@ import (
 	"code.gitea.io/gitea/modules/log"
 	base "code.gitea.io/gitea/modules/migration"
 	"code.gitea.io/gitea/modules/structs"
+	"code.gitea.io/gitea/modules/test"
 	"code.gitea.io/gitea/modules/util"
 
 	"github.com/stretchr/testify/assert"
@@ -312,10 +312,11 @@ func TestGiteaUploadUpdateGitForPullRequest(t *testing.T) {
 	}))
 
 	for _, testCase := range []struct {
-		name          string
-		head          string
-		assertContent func(t *testing.T, content string)
-		pr            base.PullRequest
+		name        string
+		head        string
+		logFilter   []string
+		logFiltered []bool
+		pr          base.PullRequest
 	}{
 		{
 			name: "fork, good Head.SHA",
@@ -362,9 +363,8 @@ func TestGiteaUploadUpdateGitForPullRequest(t *testing.T) {
 					OwnerName: forkRepo.OwnerName,
 				},
 			},
-			assertContent: func(t *testing.T, content string) {
-				assert.Contains(t, content, "Fetch branch from")
-			},
+			logFilter:   []string{"Fetch branch from"},
+			logFiltered: []bool{true},
 		},
 		{
 			name: "invalid fork CloneURL",
@@ -388,9 +388,8 @@ func TestGiteaUploadUpdateGitForPullRequest(t *testing.T) {
 					OwnerName: "WRONG",
 				},
 			},
-			assertContent: func(t *testing.T, content string) {
-				assert.Contains(t, content, "AddRemote")
-			},
+			logFilter:   []string{"AddRemote"},
+			logFiltered: []bool{true},
 		},
 		{
 			name: "no fork, good Head.SHA",
@@ -437,10 +436,8 @@ func TestGiteaUploadUpdateGitForPullRequest(t *testing.T) {
 					OwnerName: fromRepo.OwnerName,
 				},
 			},
-			assertContent: func(t *testing.T, content string) {
-				assert.Contains(t, content, "Empty reference")
-				assert.NotContains(t, content, "Cannot remove local head")
-			},
+			logFilter:   []string{"Empty reference", "Cannot remove local head"},
+			logFiltered: []bool{true, false},
 		},
 		{
 			name: "no fork, invalid Head.SHA",
@@ -464,9 +461,8 @@ func TestGiteaUploadUpdateGitForPullRequest(t *testing.T) {
 					OwnerName: fromRepo.OwnerName,
 				},
 			},
-			assertContent: func(t *testing.T, content string) {
-				assert.Contains(t, content, "Deprecated local head")
-			},
+			logFilter:   []string{"Deprecated local head"},
+			logFiltered: []bool{true},
 		},
 		{
 			name: "no fork, not found Head.SHA",
@@ -490,36 +486,29 @@ func TestGiteaUploadUpdateGitForPullRequest(t *testing.T) {
 					OwnerName: fromRepo.OwnerName,
 				},
 			},
-			assertContent: func(t *testing.T, content string) {
-				assert.Contains(t, content, "Deprecated local head")
-				assert.NotContains(t, content, "Cannot remove local head")
-			},
+			logFilter:   []string{"Deprecated local head", "Cannot remove local head"},
+			logFiltered: []bool{true, false},
 		},
 	} {
 		t.Run(testCase.name, func(t *testing.T) {
-			logger, ok := log.NamedLoggers.Load(log.DEFAULT)
-			assert.True(t, ok)
-			logger.SetLogger("buffer", "buffer", "{}")
-			defer logger.DelLogger("buffer")
+			stopMark := fmt.Sprintf(">>>>>>>>>>>>>STOP: %s<<<<<<<<<<<<<<<", testCase.name)
+
+			logChecker, cleanup := test.NewLogChecker(log.DEFAULT)
+			logChecker.Filter(testCase.logFilter...).StopMark(stopMark)
+			defer cleanup()
 
 			testCase.pr.EnsuredSafe = true
 
 			head, err := uploader.updateGitForPullRequest(&testCase.pr)
 			assert.NoError(t, err)
 			assert.EqualValues(t, testCase.head, head)
-			if testCase.assertContent != nil {
-				fence := fmt.Sprintf(">>>>>>>>>>>>>FENCE %s<<<<<<<<<<<<<<<", testCase.name)
-				log.Error(fence)
-				var content string
-				for i := 0; i < 5000; i++ {
-					content, err = logger.GetLoggerProviderContent("buffer")
-					assert.NoError(t, err)
-					if strings.Contains(content, fence) {
-						break
-					}
-					time.Sleep(1 * time.Millisecond)
-				}
-				testCase.assertContent(t, content)
+
+			log.Info(stopMark)
+
+			logFiltered, logStopped := logChecker.Check(5 * time.Second)
+			assert.True(t, logStopped)
+			if len(testCase.logFilter) > 0 {
+				assert.EqualValues(t, testCase.logFiltered, logFiltered, "for log message filters: %v", testCase.logFilter)
 			}
 		})
 	}

tests/testlogger.go

@@ -180,11 +180,6 @@ func (log *TestLogger) Init(config string) error {
 	return nil
 }
 
-// Content returns the content accumulated in the content provider
-func (log *TestLogger) Content() (string, error) {
-	return "", fmt.Errorf("not supported")
-}
-
 // Flush when log should be flushed
 func (log *TestLogger) Flush() {
 }