From e43c6cd9dfe621798516bd6df4c4d4d01903a52e Mon Sep 17 00:00:00 2001 From: oliverpool Date: Thu, 14 Mar 2024 14:45:41 +0100 Subject: [PATCH] fail test when log.Error is called except for some specific messages (to make the test pass for now) --- .deadcode-out | 10 +- models/migrations/base/tests.go | 4 + modules/testlogger/testlogger.go | 216 ++++++++++++++++++++++---- tests/e2e/e2e_test.go | 6 +- tests/integration/integration_test.go | 5 +- 5 files changed, 206 insertions(+), 35 deletions(-) diff --git a/.deadcode-out b/.deadcode-out index dc4aa0e49..c728ea81a 100644 --- a/.deadcode-out +++ b/.deadcode-out @@ -271,13 +271,19 @@ package "code.gitea.io/gitea/modules/sync" package "code.gitea.io/gitea/modules/testlogger" func (*testLoggerWriterCloser).pushT - func (*testLoggerWriterCloser).Write + func (*testLoggerWriterCloser).Log + func (*testLoggerWriterCloser).recordError + func (*testLoggerWriterCloser).printMsg func (*testLoggerWriterCloser).popT - func (*testLoggerWriterCloser).Close func (*testLoggerWriterCloser).Reset func PrintCurrentTest func Printf func NewTestLoggerWriter + func (*TestLogEventWriter).Base + func (*TestLogEventWriter).GetLevel + func (*TestLogEventWriter).GetWriterName + func (*TestLogEventWriter).GetWriterType + func (*TestLogEventWriter).Run package "code.gitea.io/gitea/modules/timeutil" func GetExecutableModTime diff --git a/models/migrations/base/tests.go b/models/migrations/base/tests.go index 85cafc1ab..0726211ea 100644 --- a/models/migrations/base/tests.go +++ b/models/migrations/base/tests.go @@ -160,6 +160,10 @@ func MainTest(m *testing.M) { exitStatus := m.Run() + if err := testlogger.WriterCloser.Reset(); err != nil && exitStatus == 0 { + fmt.Printf("testlogger.WriterCloser.Reset: %v\n", err) + os.Exit(1) + } if err := removeAllWithRetry(setting.RepoRootPath); err != nil { fmt.Fprintf(os.Stderr, "os.RemoveAll: %v\n", err) } diff --git a/modules/testlogger/testlogger.go b/modules/testlogger/testlogger.go index 4215567c0..908885554 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() + return w.err } -func (w *testLoggerWriterCloser) Close() error { - return nil -} - -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/tests/e2e/e2e_test.go b/tests/e2e/e2e_test.go index df4fe95fd..12681ab0f 100644 --- a/tests/e2e/e2e_test.go +++ b/tests/e2e/e2e_test.go @@ -59,8 +59,10 @@ func TestMain(m *testing.M) { exitVal := m.Run() - testlogger.WriterCloser.Reset() - + if err := testlogger.WriterCloser.Reset(); err != nil { + fmt.Printf("testlogger.WriterCloser.Reset: %v\n", err) + os.Exit(1) + } if err = util.RemoveAll(setting.Indexer.IssuePath); err != nil { fmt.Printf("util.RemoveAll: %v\n", err) os.Exit(1) diff --git a/tests/integration/integration_test.go b/tests/integration/integration_test.go index 0a2003447..76b36a734 100644 --- a/tests/integration/integration_test.go +++ b/tests/integration/integration_test.go @@ -145,7 +145,10 @@ func TestMain(m *testing.M) { // Instead, "No tests were found", last nonsense log is "According to the configuration, subsequent logs will not be printed to the console" exitCode := m.Run() - testlogger.WriterCloser.Reset() + if err := testlogger.WriterCloser.Reset(); err != nil { + fmt.Printf("testlogger.WriterCloser.Reset: %v\n", err) + os.Exit(1) + } if err = util.RemoveAll(setting.Indexer.IssuePath); err != nil { fmt.Printf("util.RemoveAll: %v\n", err)