summaryrefslogtreecommitdiffstats
path: root/modules/testlogger
diff options
context:
space:
mode:
authorwxiaoguang <wxiaoguang@gmail.com>2023-05-08 19:49:59 +0800
committerGitHub <noreply@github.com>2023-05-08 19:49:59 +0800
commit6f9c278559789066aa831c1df25b0d866103d02d (patch)
treee3a1880e0d4cf88916f9d1b65d82fbd4c41ea47f /modules/testlogger
parentcb700aedd1e670fb47b8cf0cd67fb117a1ad88a2 (diff)
downloadgitea-6f9c278559789066aa831c1df25b0d866103d02d.tar.gz
gitea-6f9c278559789066aa831c1df25b0d866103d02d.zip
Rewrite queue (#24505)
# ⚠️ Breaking Many deprecated queue config options are removed (actually, they should have been removed in 1.18/1.19). If you see the fatal message when starting Gitea: "Please update your app.ini to remove deprecated config options", please follow the error messages to remove these options from your app.ini. Example: ``` 2023/05/06 19:39:22 [E] Removed queue option: `[indexer].ISSUE_INDEXER_QUEUE_TYPE`. Use new options in `[queue.issue_indexer]` 2023/05/06 19:39:22 [E] Removed queue option: `[indexer].UPDATE_BUFFER_LEN`. Use new options in `[queue.issue_indexer]` 2023/05/06 19:39:22 [F] Please update your app.ini to remove deprecated config options ``` Many options in `[queue]` are are dropped, including: `WRAP_IF_NECESSARY`, `MAX_ATTEMPTS`, `TIMEOUT`, `WORKERS`, `BLOCK_TIMEOUT`, `BOOST_TIMEOUT`, `BOOST_WORKERS`, they can be removed from app.ini. # The problem The old queue package has some legacy problems: * complexity: I doubt few people could tell how it works. * maintainability: Too many channels and mutex/cond are mixed together, too many different structs/interfaces depends each other. * stability: due to the complexity & maintainability, sometimes there are strange bugs and difficult to debug, and some code doesn't have test (indeed some code is difficult to test because a lot of things are mixed together). * general applicability: although it is called "queue", its behavior is not a well-known queue. * scalability: it doesn't seem easy to make it work with a cluster without breaking its behaviors. It came from some very old code to "avoid breaking", however, its technical debt is too heavy now. It's a good time to introduce a better "queue" package. # The new queue package It keeps using old config and concept as much as possible. * It only contains two major kinds of concepts: * The "base queue": channel, levelqueue, redis * They have the same abstraction, the same interface, and they are tested by the same testing code. * The "WokerPoolQueue", it uses the "base queue" to provide "worker pool" function, calls the "handler" to process the data in the base queue. * The new code doesn't do "PushBack" * Think about a queue with many workers, the "PushBack" can't guarantee the order for re-queued unhandled items, so in new code it just does "normal push" * The new code doesn't do "pause/resume" * The "pause/resume" was designed to handle some handler's failure: eg: document indexer (elasticsearch) is down * If a queue is paused for long time, either the producers blocks or the new items are dropped. * The new code doesn't do such "pause/resume" trick, it's not a common queue's behavior and it doesn't help much. * If there are unhandled items, the "push" function just blocks for a few seconds and then re-queue them and retry. * The new code doesn't do "worker booster" * Gitea's queue's handlers are light functions, the cost is only the go-routine, so it doesn't make sense to "boost" them. * The new code only use "max worker number" to limit the concurrent workers. * The new "Push" never blocks forever * Instead of creating more and more blocking goroutines, return an error is more friendly to the server and to the end user. There are more details in code comments: eg: the "Flush" problem, the strange "code.index" hanging problem, the "immediate" queue problem. Almost ready for review. TODO: * [x] add some necessary comments during review * [x] add some more tests if necessary * [x] update documents and config options * [x] test max worker / active worker * [x] re-run the CI tasks to see whether any test is flaky * [x] improve the `handleOldLengthConfiguration` to provide more friendly messages * [x] fine tune default config values (eg: length?) ## Code coverage: ![image](https://user-images.githubusercontent.com/2114189/236620635-55576955-f95d-4810-b12f-879026a3afdf.png)
Diffstat (limited to 'modules/testlogger')
-rw-r--r--modules/testlogger/testlogger.go212
1 files changed, 212 insertions, 0 deletions
diff --git a/modules/testlogger/testlogger.go b/modules/testlogger/testlogger.go
new file mode 100644
index 0000000000..bf912f41dc
--- /dev/null
+++ b/modules/testlogger/testlogger.go
@@ -0,0 +1,212 @@
+// Copyright 2019 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package testlogger
+
+import (
+ "context"
+ "fmt"
+ "os"
+ "runtime"
+ "strings"
+ "sync"
+ "testing"
+ "time"
+
+ "code.gitea.io/gitea/modules/json"
+ "code.gitea.io/gitea/modules/log"
+ "code.gitea.io/gitea/modules/queue"
+)
+
+var (
+ prefix string
+ SlowTest = 10 * time.Second
+ SlowFlush = 5 * time.Second
+)
+
+// TestLogger is a logger which will write to the testing log
+type TestLogger struct {
+ log.WriterLogger
+}
+
+var WriterCloser = &testLoggerWriterCloser{}
+
+type testLoggerWriterCloser struct {
+ sync.RWMutex
+ t []*testing.TB
+}
+
+func (w *testLoggerWriterCloser) pushT(t *testing.TB) {
+ w.Lock()
+ w.t = append(w.t, t)
+ w.Unlock()
+}
+
+func (w *testLoggerWriterCloser) Write(p []byte) (int, error) {
+ // There was a data race problem: the logger system could still try to output logs after the runner is finished.
+ // So we must ensure that the "t" in stack is still valid.
+ w.RLock()
+ defer w.RUnlock()
+
+ var t *testing.TB
+ if len(w.t) > 0 {
+ t = w.t[len(w.t)-1]
+ }
+
+ if len(p) > 0 && p[len(p)-1] == '\n' {
+ p = p[:len(p)-1]
+ }
+
+ if t == nil || *t == nil {
+ return fmt.Fprintf(os.Stdout, "??? [Unknown Test] %s\n", p)
+ }
+
+ defer func() {
+ err := recover()
+ if err == nil {
+ return
+ }
+ var errString string
+ errErr, ok := err.(error)
+ if ok {
+ errString = errErr.Error()
+ } else {
+ errString, ok = err.(string)
+ }
+ if !ok {
+ panic(err)
+ }
+ if !strings.HasPrefix(errString, "Log in goroutine after ") {
+ panic(err)
+ }
+ }()
+
+ (*t).Log(string(p))
+ return len(p), nil
+}
+
+func (w *testLoggerWriterCloser) popT() {
+ w.Lock()
+ if len(w.t) > 0 {
+ w.t = w.t[:len(w.t)-1]
+ }
+ w.Unlock()
+}
+
+func (w *testLoggerWriterCloser) Close() error {
+ return nil
+}
+
+func (w *testLoggerWriterCloser) Reset() {
+ w.Lock()
+ if len(w.t) > 0 {
+ for _, t := range w.t {
+ if t == nil {
+ continue
+ }
+ fmt.Fprintf(os.Stdout, "Unclosed logger writer in test: %s", (*t).Name())
+ (*t).Errorf("Unclosed logger writer in test: %s", (*t).Name())
+ }
+ w.t = nil
+ }
+ w.Unlock()
+}
+
+// PrintCurrentTest prints the current test to os.Stdout
+func PrintCurrentTest(t testing.TB, skip ...int) func() {
+ start := time.Now()
+ actualSkip := 1
+ if len(skip) > 0 {
+ actualSkip = skip[0]
+ }
+ _, filename, line, _ := runtime.Caller(actualSkip)
+
+ if log.CanColorStdout {
+ fmt.Fprintf(os.Stdout, "=== %s (%s:%d)\n", fmt.Formatter(log.NewColoredValue(t.Name())), strings.TrimPrefix(filename, prefix), line)
+ } else {
+ fmt.Fprintf(os.Stdout, "=== %s (%s:%d)\n", t.Name(), strings.TrimPrefix(filename, prefix), line)
+ }
+ WriterCloser.pushT(&t)
+ return func() {
+ took := time.Since(start)
+ if took > SlowTest {
+ if log.CanColorStdout {
+ fmt.Fprintf(os.Stdout, "+++ %s is a slow test (took %v)\n", fmt.Formatter(log.NewColoredValue(t.Name(), log.Bold, log.FgYellow)), fmt.Formatter(log.NewColoredValue(took, log.Bold, log.FgYellow)))
+ } else {
+ fmt.Fprintf(os.Stdout, "+++ %s is a slow test (took %v)\n", t.Name(), took)
+ }
+ }
+ timer := time.AfterFunc(SlowFlush, func() {
+ if log.CanColorStdout {
+ fmt.Fprintf(os.Stdout, "+++ %s ... still flushing after %v ...\n", fmt.Formatter(log.NewColoredValue(t.Name(), log.Bold, log.FgRed)), SlowFlush)
+ } else {
+ fmt.Fprintf(os.Stdout, "+++ %s ... still flushing after %v ...\n", t.Name(), SlowFlush)
+ }
+ })
+ if err := queue.GetManager().FlushAll(context.Background(), time.Minute); err != nil {
+ t.Errorf("Flushing queues failed with error %v", err)
+ }
+ timer.Stop()
+ flushTook := time.Since(start) - took
+ if flushTook > SlowFlush {
+ if log.CanColorStdout {
+ fmt.Fprintf(os.Stdout, "+++ %s had a slow clean-up flush (took %v)\n", fmt.Formatter(log.NewColoredValue(t.Name(), log.Bold, log.FgRed)), fmt.Formatter(log.NewColoredValue(flushTook, log.Bold, log.FgRed)))
+ } else {
+ fmt.Fprintf(os.Stdout, "+++ %s had a slow clean-up flush (took %v)\n", t.Name(), flushTook)
+ }
+ }
+ WriterCloser.popT()
+ }
+}
+
+// Printf takes a format and args and prints the string to os.Stdout
+func Printf(format string, args ...interface{}) {
+ if log.CanColorStdout {
+ for i := 0; i < len(args); i++ {
+ args[i] = log.NewColoredValue(args[i])
+ }
+ }
+ fmt.Fprintf(os.Stdout, "\t"+format, args...)
+}
+
+// NewTestLogger creates a TestLogger as a log.LoggerProvider
+func NewTestLogger() log.LoggerProvider {
+ logger := &TestLogger{}
+ logger.Colorize = log.CanColorStdout
+ logger.Level = log.TRACE
+ return logger
+}
+
+// Init inits connection writer with json config.
+// json config only need key "level".
+func (log *TestLogger) Init(config string) error {
+ err := json.Unmarshal([]byte(config), log)
+ if err != nil {
+ return err
+ }
+ log.NewWriterLogger(WriterCloser)
+ return nil
+}
+
+// Flush when log should be flushed
+func (log *TestLogger) Flush() {
+}
+
+// ReleaseReopen does nothing
+func (log *TestLogger) ReleaseReopen() error {
+ return nil
+}
+
+// GetName returns the default name for this implementation
+func (log *TestLogger) GetName() string {
+ return "test"
+}
+
+func init() {
+ const relFilePath = "modules/testlogger/testlogger.go"
+ _, filename, _, _ := runtime.Caller(0)
+ if !strings.HasSuffix(filename, relFilePath) {
+ panic("source code file path doesn't match expected: " + relFilePath)
+ }
+ prefix = strings.TrimSuffix(filename, relFilePath)
+}