fix

Author: wxiaoguang

.github/workflows/pull-db-tests.yml

@@ -158,6 +158,10 @@ jobs:
         env:
           MYSQL_ALLOW_EMPTY_PASSWORD: true
           MYSQL_DATABASE: testgitea
+          MYSQL_EXTRA_FLAGS: >
+            --innodb-doublewrite=off
+            --innodb-flush-log-at-trx-commit=0
+            --disable-log-bin
         ports:
           - "3306:3306"
       elasticsearch:

models/migrations/base/tests.go

@@ -15,7 +15,6 @@ import (
 	"code.gitea.io/gitea/models/unittest"
 	"code.gitea.io/gitea/modules/base"
 	"code.gitea.io/gitea/modules/git"
-	"code.gitea.io/gitea/modules/log"
 	"code.gitea.io/gitea/modules/setting"
 	"code.gitea.io/gitea/modules/testlogger"
 
@@ -91,7 +90,7 @@ func PrepareTestEnv(t *testing.T, skip int, syncModels ...any) (*xorm.Engine, fu
 }
 
 func MainTest(m *testing.M) {
-	log.RegisterEventWriter("test", testlogger.NewTestLoggerWriter)
+	testlogger.Init()
 
 	giteaRoot := base.SetupGiteaRoot()
 	if giteaRoot == "" {

modules/log/color.go

@@ -86,13 +86,19 @@ type ColoredValue struct {
 	colors []ColorAttribute
 }
 
+var _ fmt.Formatter = (*ColoredValue)(nil)
+
 func (c *ColoredValue) Format(f fmt.State, verb rune) {
 	_, _ = f.Write(ColorBytes(c.colors...))
 	s := fmt.Sprintf(fmt.FormatString(f, verb), c.v)
 	_, _ = f.Write([]byte(s))
 	_, _ = f.Write(resetBytes)
 }
 
+func (c *ColoredValue) Value() any {
+	return c.v
+}
+
 func NewColoredValue(v any, color ...ColorAttribute) *ColoredValue {
 	return &ColoredValue{v: v, colors: color}
 }

modules/testlogger/testlogger.go

@@ -19,9 +19,10 @@ import (
 )
 
 var (
-	prefix    string
-	SlowTest  = 10 * time.Second
-	SlowFlush = 5 * time.Second
+	prefix        string
+	TestTimeout   = 10 * time.Minute
+	TestSlowRun   = 10 * time.Second
+	TestSlowFlush = 5 * time.Second
 )
 
 var WriterCloser = &testLoggerWriterCloser{}
@@ -89,79 +90,92 @@ func (w *testLoggerWriterCloser) Reset() {
 	w.Unlock()
 }
 
+// Printf takes a format and args and prints the string to os.Stdout
+func Printf(format string, args ...any) {
+	if !log.CanColorStdout {
+		for i := 0; i < len(args); i++ {
+			if c, ok := args[i].(*log.ColoredValue); ok {
+				args[i] = c.Value()
+			}
+		}
+	}
+	_, _ = fmt.Fprintf(os.Stdout, "\t"+format, args...)
+}
+
 // PrintCurrentTest prints the current test to os.Stdout
 func PrintCurrentTest(t testing.TB, skip ...int) func() {
 	t.Helper()
-	start := time.Now()
+	runStart := time.Now()
 	actualSkip := util.OptionalArg(skip) + 1
 	_, 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)
-	}
+	Printf("=== %s (%s:%d)\n", log.NewColoredValue(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)
+	timeoutChecker := time.AfterFunc(TestTimeout, func() {
+		l := 128 * 1024
+		var stack []byte
+		for {
+			stack = make([]byte, l)
+			n := runtime.Stack(stack, true)
+			if n <= l {
+				stack = stack[:n]
+				break
 			}
+			l = n
 		}
-		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)
-			}
+		Printf("!!! %s ... timeout: %v ... stacktrace:\n%s\n\n", log.NewColoredValue(t.Name(), log.Bold, log.FgRed), TestTimeout, string(stack))
+	})
+	return func() {
+		flushStart := time.Now()
+		slowFlushChecker := time.AfterFunc(TestSlowFlush, func() {
+			Printf("+++ %s ... still flushing after %v ...\n", log.NewColoredValue(t.Name(), log.Bold, log.FgRed), TestSlowFlush)
 		})
 		if err := queue.GetManager().FlushAll(context.Background(), -1); 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()
-	}
-}
+		slowFlushChecker.Stop()
+		timeoutChecker.Stop()
 
-// Printf takes a format and args and prints the string to os.Stdout
-func Printf(format string, args ...any) {
-	if log.CanColorStdout {
-		for i := 0; i < len(args); i++ {
-			args[i] = log.NewColoredValue(args[i])
+		runDuration := time.Since(runStart)
+		flushDuration := time.Since(flushStart)
+		if runDuration > TestSlowRun {
+			Printf("+++ %s is a slow test (run: %v, flush: %v)\n", log.NewColoredValue(t.Name(), log.Bold, log.FgYellow), runDuration, flushDuration)
 		}
+		WriterCloser.popT()
 	}
-	_, _ = 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 {
+// 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
 	return w
 }
 
-func init() {
+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)
+
+	log.RegisterEventWriter("test", newTestLoggerWriter)
+
+	duration, err := time.ParseDuration(os.Getenv("GITEA_TEST_SLOW_RUN"))
+	if err == nil && duration > 0 {
+		TestSlowRun = duration
+	}
+
+	duration, err = time.ParseDuration(os.Getenv("GITEA_TEST_SLOW_FLUSH"))
+	if err == nil && duration > 0 {
+		TestSlowFlush = duration
+	}
 }

tests/integration/README.md

@@ -99,18 +99,8 @@ We appreciate that some testing machines may not be very powerful and
 the default timeouts for declaring a slow test or a slow clean-up flush
 may not be appropriate.
 
-You can either:
-
-* Within the test ini file set the following section:
-
-```ini
-[integration-tests]
-SLOW_TEST = 10s ; 10s is the default value
-SLOW_FLUSH = 5S ; 5s is the default value
-```
-
-* Set the following environment variables:
+You can set the following environment variables:
 
 ```bash
-GITEA_SLOW_TEST_TIME="10s" GITEA_SLOW_FLUSH_TIME="5s" make test-sqlite
+GITEA_TEST_SLOW_RUN="10s" GITEA_TEST_SLOW_FLUSH="5s" make test-sqlite
 ```

tests/integration/integration_test.go

@@ -20,15 +20,13 @@ import (
 	"strings"
 	"sync/atomic"
 	"testing"
-	"time"
 
 	"code.gitea.io/gitea/models/auth"
 	"code.gitea.io/gitea/models/unittest"
 	"code.gitea.io/gitea/modules/graceful"
 	"code.gitea.io/gitea/modules/json"
 	"code.gitea.io/gitea/modules/log"
 	"code.gitea.io/gitea/modules/setting"
-	"code.gitea.io/gitea/modules/testlogger"
 	"code.gitea.io/gitea/modules/util"
 	"code.gitea.io/gitea/modules/web"
 	"code.gitea.io/gitea/routers"
@@ -90,27 +88,6 @@ func TestMain(m *testing.M) {
 	tests.InitTest(true)
 	testWebRoutes = routers.NormalRoutes()
 
-	// integration test settings...
-	if setting.CfgProvider != nil {
-		testingCfg := setting.CfgProvider.Section("integration-tests")
-		testlogger.SlowTest = testingCfg.Key("SLOW_TEST").MustDuration(testlogger.SlowTest)
-		testlogger.SlowFlush = testingCfg.Key("SLOW_FLUSH").MustDuration(testlogger.SlowFlush)
-	}
-
-	if os.Getenv("GITEA_SLOW_TEST_TIME") != "" {
-		duration, err := time.ParseDuration(os.Getenv("GITEA_SLOW_TEST_TIME"))
-		if err == nil {
-			testlogger.SlowTest = duration
-		}
-	}
-
-	if os.Getenv("GITEA_SLOW_FLUSH_TIME") != "" {
-		duration, err := time.ParseDuration(os.Getenv("GITEA_SLOW_FLUSH_TIME"))
-		if err == nil {
-			testlogger.SlowFlush = duration
-		}
-	}
-
 	os.Unsetenv("GIT_AUTHOR_NAME")
 	os.Unsetenv("GIT_AUTHOR_EMAIL")
 	os.Unsetenv("GIT_AUTHOR_DATE")
@@ -132,8 +109,6 @@ 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 = util.RemoveAll(setting.Indexer.IssuePath); err != nil {
 		fmt.Printf("util.RemoveAll: %v\n", err)
 		os.Exit(1)

tests/integration/linguist_test.go

@@ -6,6 +6,7 @@ package integration
 import (
 	"context"
 	"net/url"
+	"strconv"
 	"strings"
 	"testing"
 	"time"
@@ -19,6 +20,7 @@ import (
 	"code.gitea.io/gitea/modules/queue"
 	repo_service "code.gitea.io/gitea/services/repository"
 	files_service "code.gitea.io/gitea/services/repository/files"
+	"code.gitea.io/gitea/tests"
 
 	"github.com/stretchr/testify/assert"
 )
@@ -218,42 +220,43 @@ func TestLinguist(t *testing.T) {
 		}
 
 		for i, c := range cases {
-			repo, err := repo_service.CreateRepository(db.DefaultContext, user, user, repo_service.CreateRepoOptions{
-				Name: "linguist-test",
-			})
-			assert.NoError(t, err)
-
-			files := []*files_service.ChangeRepoFile{
-				{
-					TreePath:      ".gitattributes",
-					ContentReader: strings.NewReader(c.GitAttributesContent),
-				},
-			}
-			files = append(files, c.FilesToAdd...)
-			for _, f := range files {
-				f.Operation = "create"
-			}
+			t.Run("Case-"+strconv.Itoa(i), func(t *testing.T) {
+				defer tests.PrintCurrentTest(t)()
+				repo, err := repo_service.CreateRepository(db.DefaultContext, user, user, repo_service.CreateRepoOptions{
+					Name: "linguist-test-" + strconv.Itoa(i),
+				})
+				assert.NoError(t, err)
 
-			_, err = files_service.ChangeRepoFiles(git.DefaultContext, repo, user, &files_service.ChangeRepoFilesOptions{
-				Files:     files,
-				OldBranch: repo.DefaultBranch,
-				NewBranch: repo.DefaultBranch,
-			})
-			assert.NoError(t, err)
+				files := []*files_service.ChangeRepoFile{
+					{
+						TreePath:      ".gitattributes",
+						ContentReader: strings.NewReader(c.GitAttributesContent),
+					},
+				}
+				files = append(files, c.FilesToAdd...)
+				for _, f := range files {
+					f.Operation = "create"
+				}
 
-			assert.NoError(t, stats.UpdateRepoIndexer(repo))
-			assert.NoError(t, queue.GetManager().FlushAll(context.Background(), 10*time.Second))
+				_, err = files_service.ChangeRepoFiles(git.DefaultContext, repo, user, &files_service.ChangeRepoFilesOptions{
+					Files:     files,
+					OldBranch: repo.DefaultBranch,
+					NewBranch: repo.DefaultBranch,
+				})
+				assert.NoError(t, err)
 
-			stats, err := repo_model.GetTopLanguageStats(db.DefaultContext, repo, len(c.FilesToAdd))
-			assert.NoError(t, err)
+				assert.NoError(t, stats.UpdateRepoIndexer(repo))
+				assert.NoError(t, queue.GetManager().FlushAll(context.Background(), 10*time.Second))
 
-			languages := make([]string, 0, len(stats))
-			for _, s := range stats {
-				languages = append(languages, s.Language)
-			}
-			assert.Equal(t, c.ExpectedLanguageOrder, languages, "case %d: unexpected language stats", i)
+				stats, err := repo_model.GetTopLanguageStats(db.DefaultContext, repo, len(c.FilesToAdd))
+				assert.NoError(t, err)
 
-			assert.NoError(t, repo_service.DeleteRepository(db.DefaultContext, user, repo, false))
+				languages := make([]string, 0, len(stats))
+				for _, s := range stats {
+					languages = append(languages, s.Language)
+				}
+				assert.Equal(t, c.ExpectedLanguageOrder, languages, "case %d: unexpected language stats", i)
+			})
 		}
 	})
 }

tests/integration/migration-test/migration_test.go

@@ -37,7 +37,7 @@ import (
 var currentEngine *xorm.Engine
 
 func initMigrationTest(t *testing.T) func() {
-	log.RegisterEventWriter("test", testlogger.NewTestLoggerWriter)
+	testlogger.Init()
 
 	deferFn := tests.PrintCurrentTest(t, 2)
 	giteaRoot := base.SetupGiteaRoot()

tests/test_utils.go

@@ -35,7 +35,7 @@ func exitf(format string, args ...any) {
 }
 
 func InitTest(requireGitea bool) {
-	log.RegisterEventWriter("test", testlogger.NewTestLoggerWriter)
+	testlogger.Init()
 
 	giteaRoot := base.SetupGiteaRoot()
 	if giteaRoot == "" {