log slow tests (#11487)

* log slow tests

Signed-off-by: Andrew Thornton <art27@cantab.net>

* placate lint

Signed-off-by: Andrew Thornton <art27@cantab.net>

* More lint placation

Co-authored-by: 6543 <6543@obermui.de>

Co-authored-by: 6543 <6543@obermui.de>
Co-authored-by: techknowlogick <techknowlogick@gitea.io>

integrations/README.md

@@ -70,3 +70,25 @@ For other databases(replace MSSQL to MYSQL, MYSQL8, PGSQL):
 ```
 TEST_MSSQL_HOST=localhost:1433 TEST_MSSQL_DBNAME=test TEST_MSSQL_USERNAME=sa TEST_MSSQL_PASSWORD=MwantsaSecurePassword1 make test-mssql#GPG
 ```
+
+## Setting timeouts for declaring long-tests and long-flushes
+
+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:
+
+```bash
+GITEA_SLOW_TEST_TIME="10s" GITEA_SLOW_FLUSH_TIME="5s" make test-sqlite
+```

integrations/integration_test.go

@@ -22,6 +22,7 @@ import (
 	"runtime"
 	"strings"
 	"testing"
+	"time"
 
 	"code.gitea.io/gitea/models"
 	"code.gitea.io/gitea/modules/base"
@@ -66,6 +67,27 @@ func TestMain(m *testing.M) {
 	mac = routes.NewMacaron()
 	routes.RegisterRoutes(mac)
 
+	// integration test settings...
+	if setting.Cfg != nil {
+		testingCfg := setting.Cfg.Section("integration-tests")
+		slowTest = testingCfg.Key("SLOW_TEST").MustDuration(slowTest)
+		slowFlush = testingCfg.Key("SLOW_FLUSH").MustDuration(slowFlush)
+	}
+
+	if os.Getenv("GITEA_SLOW_TEST_TIME") != "" {
+		duration, err := time.ParseDuration(os.Getenv("GITEA_SLOW_TEST_TIME"))
+		if err == nil {
+			slowTest = duration
+		}
+	}
+
+	if os.Getenv("GITEA_SLOW_FLUSH_TIME") != "" {
+		duration, err := time.ParseDuration(os.Getenv("GITEA_SLOW_FLUSH_TIME"))
+		if err == nil {
+			slowFlush = duration
+		}
+	}
+
 	var helper testfixtures.Helper
 	if setting.Database.UseMySQL {
 		helper = &testfixtures.MySQL{}

integrations/testlogger.go

@@ -13,12 +13,17 @@ import (
 	"strings"
 	"sync"
 	"testing"
+	"time"
 
 	"code.gitea.io/gitea/modules/log"
 	"code.gitea.io/gitea/modules/queue"
 )
 
-var prefix string
+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 {
@@ -87,6 +92,7 @@ func (w *testLoggerWriterCloser) Close() error {
 
 // 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]
@@ -100,9 +106,33 @@ func PrintCurrentTest(t testing.TB, skip ...int) func() {
 	}
 	writerCloser.setT(&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 tets (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(), -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.Close()
 	}
 }