Merge pull request '[TESTS] fail when log.Error is called' (#2657) from oliverpool/forgejo:fail_test_on_log_error into forgejo

Reviewed-on: https://codeberg.org/forgejo/forgejo/pulls/2657

3 files changed, 196 insertions, 31 deletions

diff --git a/modules/queue/workergroup.go b/modules/queue/workergroup.go
index 8c9dd274f0..ea4c0020c5 100644
--- a/modules/queue/workergroup.go
+++ b/modules/queue/workergroup.go
@@ -334,7 +334,10 @@ func (q *WorkerPoolQueue[T]) doRun() {
 			// since we are already in a "flush" operation, so the dispatching function shouldn't read the flush chan.
 			q.doDispatchBatchToWorker(wg, skipFlushChan)
 			q.doFlush(wg, flush)
-		case err := <-wg.popItemErr:
+		case err, errOk := <-wg.popItemErr:
+			if !errOk {
+				return
+			}
 			if !q.isCtxRunCanceled() {
 				log.Error("Failed to pop item from queue %q (doRun): %v", q.GetName(), err)
 			}
diff --git a/modules/testlogger/testlogger.go b/modules/testlogger/testlogger.go
index 4215567c00..908885554d 100644
--- a/modules/testlogger/testlogger.go
+++ b/modules/testlogger/testlogger.go
@@ -4,8 +4,11 @@
 package testlogger
 
 import (
+	"bytes"
 	"context"
+	"errors"
 	"fmt"
+	"io"
 	"os"
 	"runtime"
 	"strings"
@@ -27,53 +30,146 @@ var WriterCloser = &testLoggerWriterCloser{}
 
 type testLoggerWriterCloser struct {
 	sync.RWMutex
-	t []testing.TB
+	t    []testing.TB
+	errs []error // stack of error, parallel to the stack of testing.TB
+	err  error   // fallback if the stack is empty
 }
 
 func (w *testLoggerWriterCloser) pushT(t testing.TB) {
 	w.Lock()
 	w.t = append(w.t, t)
+	w.errs = append(w.errs, nil)
 	w.Unlock()
 }
 
-func (w *testLoggerWriterCloser) Write(p []byte) (int, error) {
+func (w *testLoggerWriterCloser) Log(level log.Level, msg string) {
+	if len(msg) > 0 && msg[len(msg)-1] == '\n' {
+		msg = msg[:len(msg)-1]
+	}
+
+	w.printMsg(msg)
+	if level >= log.ERROR {
+		w.recordError(msg)
+	}
+}
+
+// list of error message which will not fail the test
+// ideally this list should be empty, however ensuring that it does not grow
+// is already a good first step.
+var ignoredErrorMessageSuffixes = []string{
+	// only seen on mysql tests https://codeberg.org/forgejo/forgejo/pulls/2657#issuecomment-1693055
+	`table columns using inconsistent collation, they should use "utf8mb4_0900_ai_ci". Please go to admin panel Self Check page`,
+
+	// TestAPIDeleteReleaseByTagName
+	// action notification were a commit cannot be computed (because the commit got deleted)
+	`Notify() [E] an error occurred while executing the DeleteRelease actions method: gitRepo.GetCommit: object does not exist [id: refs/tags/release-tag, rel_path: ]`,
+	`Notify() [E] an error occurred while executing the PushCommits actions method: gitRepo.GetCommit: object does not exist [id: refs/tags/release-tag, rel_path: ]`,
+
+	// TestAPIRepoTags
+	`Notify() [E] an error occurred while executing the DeleteRelease actions method: gitRepo.GetCommit: object does not exist [id: refs/tags/gitea/22, rel_path: ]`,
+	`Notify() [E] an error occurred while executing the PushCommits actions method: gitRepo.GetCommit: object does not exist [id: refs/tags/gitea/22, rel_path: ]`,
+
+	// TestAPIDeleteTagByName
+	`Notify() [E] an error occurred while executing the DeleteRelease actions method: gitRepo.GetCommit: object does not exist [id: refs/tags/delete-tag, rel_path: ]`,
+	`Notify() [E] an error occurred while executing the PushCommits actions method: gitRepo.GetCommit: object does not exist [id: refs/tags/delete-tag, rel_path: ]`,
+
+	// TestAPIGenerateRepo
+	`Notify() [E] an error occurred while executing the CreateRepository actions method: gitRepo.GetCommit: object does not exist [id: , rel_path: ]`,
+
+	// TestAPIPullReview
+	`PullRequestReview() [E] Unsupported review webhook type`,
+
+	// TestAPIPullReviewRequest
+	`ToAPIPullRequest() [E] unable to resolve PR head ref`,
+
+	// TestAPILFSUpload
+	`Put() [E] Whilst putting LFS OID[ca978112ca1bbdcafac231b39a23dc4da786eff8147c4e72b9807785afee48bb]: Failed to copy to tmpPath: ca/97/8112ca1bbdcafac231b39a23dc4da786eff8147c4e72b9807785afee48bb Error: content size does not match`,
+	`[E] Error putting LFS MetaObject [ca978112ca1bbdcafac231b39a23dc4da786eff8147c4e72b9807785afee48bb] into content store. Error: content size does not match`,
+	`UploadHandler() [E] Upload does not match LFS MetaObject [ca978112ca1bbdcafac231b39a23dc4da786eff8147c4e72b9807785afee48bb]. Error: content size does not match`,
+	`Put() [E] Whilst putting LFS OID[2581dd7bbc1fe44726de4b7dd806a087a978b9c5aec0a60481259e34be09b06a]: Failed to copy to tmpPath: 25/81/dd7bbc1fe44726de4b7dd806a087a978b9c5aec0a60481259e34be09b06a Error: content hash does not match OID`,
+	`[E] Error putting LFS MetaObject [2581dd7bbc1fe44726de4b7dd806a087a978b9c5aec0a60481259e34be09b06a] into content store. Error: content hash does not match OID`,
+	`UploadHandler() [E] Upload does not match LFS MetaObject [2581dd7bbc1fe44726de4b7dd806a087a978b9c5aec0a60481259e34be09b06a]. Error: content hash does not match OID`,
+	`UploadHandler() [E] Upload does not match LFS MetaObject [83de2e488b89a0aa1c97496b888120a28b0c1e15463a4adb8405578c540f36d4]. Error: content size does not match`,
+
+	// TestAPILFSVerify
+	`getAuthenticatedMeta() [E] Unable to get LFS OID[fb8f7d8435968c4f82a726a92395be4d16f2f63116caf36c8ad35c60831ab042] Error: LFS Meta object does not exist`,
+
+	// TestAPIUpdateOrgAvatar
+	`UpdateAvatar() [E] UploadAvatar: image.DecodeConfig: image: unknown format`,
+
+	// TestGetAttachment
+	`/data/attachments/a/0/a0eebc99-9c0b-4ef8-bb6d-6bb9bd380a18: no such file or directory`,
+
+	// TestBlockUser
+	`BlockedUsersUnblock() [E] IsOrganization: org3 is an organization not a user`,
+	`BlockedUsersBlock() [E] IsOrganization: org3 is an organization not a user`,
+	`Action() [E] Cannot perform this action on an organization "unblock"`,
+	`Action() [E] Cannot perform this action on an organization "block"`,
+
+	// TestBlockActions
+	`/gitea-repositories/user10/repo7.git Error: no such file or directory`,
+
+	// TestE2e/explore.test.e2e
+	`TrString() [E] Missing translation "more_items"`,
+
+	// TestRebuildCargo
+	`RebuildCargoIndex() [E] RebuildIndex failed: GetRepositoryByOwnerAndName: repository does not exist [id: 0, uid: 0, owner_name: user2, name: _cargo-index]`,
+}
+
+func (w *testLoggerWriterCloser) recordError(msg string) {
+	for _, s := range ignoredErrorMessageSuffixes {
+		if strings.HasSuffix(msg, s) {
+			return
+		}
+	}
+
+	w.Lock()
+	defer w.Unlock()
+
+	err := w.err
+	if len(w.errs) > 0 {
+		err = w.errs[len(w.errs)-1]
+	}
+
+	err = errors.Join(err, errors.New(msg))
+
+	if len(w.errs) > 0 {
+		w.errs[len(w.errs)-1] = err
+	} else {
+		w.err = err
+	}
+}
+
+func (w *testLoggerWriterCloser) printMsg(msg string) {
 	// 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 := w.t[len(w.t)-1]
+		t.Log(msg)
+	} else {
 		// if there is no running test, the log message should be outputted to console, to avoid losing important information.
 		// the "???" prefix is used to match the "===" and "+++" in PrintCurrentTest
-		return fmt.Fprintf(os.Stdout, "??? [TestLogger] %s\n", p)
+		fmt.Fprintln(os.Stdout, "??? [TestLogger]", msg)
 	}
-
-	t.Log(string(p))
-	return len(p), nil
 }
 
-func (w *testLoggerWriterCloser) popT() {
+func (w *testLoggerWriterCloser) popT() error {
 	w.Lock()
+	defer w.Unlock()
+
 	if len(w.t) > 0 {
 		w.t = w.t[:len(w.t)-1]
+		err := w.errs[len(w.errs)-1]
+		w.errs = w.errs[:len(w.errs)-1]
+		return err
 	}
-	w.Unlock()
-}
-
-func (w *testLoggerWriterCloser) Close() error {
-	return nil
+	return w.err
 }
 
-func (w *testLoggerWriterCloser) Reset() {
+func (w *testLoggerWriterCloser) Reset() error {
 	w.Lock()
 	if len(w.t) > 0 {
 		for _, t := range w.t {
@@ -84,8 +180,12 @@ func (w *testLoggerWriterCloser) Reset() {
 			t.Errorf("Unclosed logger writer in test: %s", t.Name())
 		}
 		w.t = nil
+		w.errs = nil
 	}
+	err := w.err
+	w.err = nil
 	w.Unlock()
+	return err
 }
 
 // PrintCurrentTest prints the current test to os.Stdout
@@ -132,7 +232,10 @@ func PrintCurrentTest(t testing.TB, skip ...int) func() {
 				_, _ = fmt.Fprintf(os.Stdout, "+++ %s had a slow clean-up flush (took %v)\n", t.Name(), flushTook)
 			}
 		}
-		WriterCloser.popT()
+
+		if err := WriterCloser.popT(); err != nil {
+			t.Errorf("testlogger.go:recordError() FATAL ERROR: log.Error has been called: %v", err)
+		}
 	}
 }
 
@@ -146,19 +249,72 @@ func Printf(format string, args ...any) {
 	_, _ = fmt.Fprintf(os.Stdout, "\t"+format, args...)
 }
 
-// TestLogEventWriter is a logger which will write to the testing log
-type TestLogEventWriter struct {
-	*log.EventWriterBaseImpl
-}
-
 // NewTestLoggerWriter creates a TestLogEventWriter as a log.LoggerProvider
 func NewTestLoggerWriter(name string, mode log.WriterMode) log.EventWriter {
 	w := &TestLogEventWriter{}
-	w.EventWriterBaseImpl = log.NewEventWriterBase(name, "test-log-writer", mode)
-	w.OutputWriteCloser = WriterCloser
+	w.base = log.NewEventWriterBase(name, "test-log-writer", mode)
+	w.writer = WriterCloser
 	return w
 }
 
+// TestLogEventWriter is a logger which will write to the testing log
+type TestLogEventWriter struct {
+	base   *log.EventWriterBaseImpl
+	writer *testLoggerWriterCloser
+}
+
+// Base implements log.EventWriter.
+func (t *TestLogEventWriter) Base() *log.EventWriterBaseImpl {
+	return t.base
+}
+
+// GetLevel implements log.EventWriter.
+func (t *TestLogEventWriter) GetLevel() log.Level {
+	return t.base.GetLevel()
+}
+
+// GetWriterName implements log.EventWriter.
+func (t *TestLogEventWriter) GetWriterName() string {
+	return t.base.GetWriterName()
+}
+
+// GetWriterType implements log.EventWriter.
+func (t *TestLogEventWriter) GetWriterType() string {
+	return t.base.GetWriterType()
+}
+
+// Run implements log.EventWriter.
+func (t *TestLogEventWriter) Run(ctx context.Context) {
+	for {
+		select {
+		case <-ctx.Done():
+			return
+		case event, ok := <-t.base.Queue:
+			if !ok {
+				return
+			}
+
+			var errorMsg string
+
+			switch msg := event.Msg.(type) {
+			case string:
+				errorMsg = msg
+			case []byte:
+				errorMsg = string(msg)
+			case io.WriterTo:
+				var buf bytes.Buffer
+				if _, err := msg.WriteTo(&buf); err != nil {
+					panic(err)
+				}
+				errorMsg = buf.String()
+			default:
+				errorMsg = fmt.Sprint(msg)
+			}
+			t.writer.Log(event.Origin.Level, errorMsg)
+		}
+	}
+}
+
 func init() {
 	const relFilePath = "modules/testlogger/testlogger.go"
 	_, filename, _, _ := runtime.Caller(0)
diff --git a/modules/translation/i18n/localestore.go b/modules/translation/i18n/localestore.go
index 44c3fb0c88..0e6ddab401 100644
--- a/modules/translation/i18n/localestore.go
+++ b/modules/translation/i18n/localestore.go
@@ -114,16 +114,22 @@ func (l *locale) TrString(trKey string, trArgs ...any) string {
 	format := trKey
 
 	idx, ok := l.store.trKeyToIdxMap[trKey]
+	found := false
 	if ok {
 		if msg, ok := l.idxToMsgMap[idx]; ok {
 			format = msg // use the found translation
+			found = true
 		} else if def, ok := l.store.localeMap[l.store.defaultLang]; ok {
 			// try to use default locale's translation
 			if msg, ok := def.idxToMsgMap[idx]; ok {
 				format = msg
+				found = true
 			}
 		}
 	}
+	if !found {
+		log.Error("Missing translation %q", trKey)
+	}
 
 	msg, err := Format(format, trArgs...)
 	if err != nil {