From 911975059a50e71632d33567da7000a97aa28f22 Mon Sep 17 00:00:00 2001 From: wxiaoguang Date: Sat, 22 Apr 2023 04:32:25 +0800 Subject: [PATCH] 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 | 5 - modules/log/buffer.go | 71 ------------- modules/log/buffer_test.go | 63 ----------- modules/log/conn.go | 5 - modules/log/console.go | 5 - modules/log/event.go | 10 +- modules/log/file.go | 9 -- modules/log/provider.go | 1 - modules/log/smtp.go | 5 - modules/test/logchecker.go | 116 +++++++++++++++++++++ modules/test/logchecker_test.go | 47 +++++++++ services/migrations/gitea_uploader_test.go | 67 +++++------- tests/testlogger.go | 5 - 13 files changed, 195 insertions(+), 214 deletions(-) delete mode 100644 modules/log/buffer.go delete mode 100644 modules/log/buffer_test.go create mode 100644 modules/test/logchecker.go create mode 100644 modules/test/logchecker_test.go diff --git a/models/migrations/base/testlogger.go b/models/migrations/base/testlogger.go index 7cbf4602b..80e672952 100644 --- a/models/migrations/base/testlogger.go +++ b/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() { } diff --git a/modules/log/buffer.go b/modules/log/buffer.go deleted file mode 100644 index 1eee2465f..000000000 --- a/modules/log/buffer.go +++ /dev/null @@ -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) -} diff --git a/modules/log/buffer_test.go b/modules/log/buffer_test.go deleted file mode 100644 index 1c3900605..000000000 --- a/modules/log/buffer_test.go +++ /dev/null @@ -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) -} diff --git a/modules/log/conn.go b/modules/log/conn.go index 39d523421..b21a74403 100644 --- a/modules/log/conn.go +++ b/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() { } diff --git a/modules/log/console.go b/modules/log/console.go index 8764d984a..ce0415d13 100644 --- a/modules/log/console.go +++ b/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() { } diff --git a/modules/log/event.go b/modules/log/event.go index d23e56807..5729e022b 100644 --- a/modules/log/event.go +++ b/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 +} diff --git a/modules/log/file.go b/modules/log/file.go index 55147ffac..2ec6de450 100644 --- a/modules/log/file.go +++ b/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. diff --git a/modules/log/provider.go b/modules/log/provider.go index 490c3fa71..b5058139d 100644 --- a/modules/log/provider.go +++ b/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 } diff --git a/modules/log/smtp.go b/modules/log/smtp.go index e385020c6..4e896496d 100644 --- a/modules/log/smtp.go +++ b/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() { } diff --git a/modules/test/logchecker.go b/modules/test/logchecker.go new file mode 100644 index 000000000..8f8c753c7 --- /dev/null +++ b/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) + } +} diff --git a/modules/test/logchecker_test.go b/modules/test/logchecker_test.go new file mode 100644 index 000000000..1ed7f427f --- /dev/null +++ b/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) +} diff --git a/services/migrations/gitea_uploader_test.go b/services/migrations/gitea_uploader_test.go index 6a942b9b5..b59ccb7c4 100644 --- a/services/migrations/gitea_uploader_test.go +++ b/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) } }) } diff --git a/tests/testlogger.go b/tests/testlogger.go index a7cc27a92..7cac5bbe3 100644 --- a/tests/testlogger.go +++ b/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() { }