[management] Speed up test store setup and summarize the unit test run (#7518)

Management / Unit (amd64, mysql) hit the 20 minute go test budget on #7516. The package was not hung: each of the 133 test store creations in management/server paid about 1.6s on MySQL for CREATE DATABASE, the pre-migrations, a 40-table AutoMigrate and the post-migrations, which puts the package at 10 minutes on a healthy runner and over the budget on a slow one.

The migration now runs once per test binary into a template database and each test database is cloned from it, with CREATE DATABASE ... TEMPLATE on Postgres and a replay of SHOW CREATE TABLE on MySQL. The MySQL test container also drops the binary log, doublewrite buffer and per-commit redo fsync. Two goroutine leaks in the test helpers are fixed.

tools/gotestsummary turns the go test -json stream into a readable log, and the Management unit and integration jobs now pipe through it, so a timeout names the tests still running. On MySQL, management/server went from 10m16s to 6m36s.

.github/workflows/golang-test-linux.yml

@@ -514,14 +514,32 @@ jobs:
         if: matrix.store == 'mysql'
         run: docker pull mlsmaycon/warmed-mysql:8
 
+      # The -json stream goes through tools/gotestsummary so the log shows one
+      # line per test, the output of failed tests, the head of a timeout panic
+      # with the still-running tests, and the slowest tests per package.
       - name: Test
+        shell: bash
         run: |
+          set -o pipefail
           CGO_ENABLED=1 GOARCH=${{ matrix.arch }} \
           NETBIRD_STORE_ENGINE=${{ matrix.store }} \
             CI=true \
-          go test -tags=devcert -coverprofile=coverage.txt \
+          go test -json -tags=devcert -coverprofile=coverage.txt \
             -exec "sudo --preserve-env=CI,NETBIRD_STORE_ENGINE" \
-            -timeout 20m ./management/... ./shared/management/...
+            -timeout 20m ./management/... ./shared/management/... \
+            | tee management-test-events.jsonl \
+            | go run ./tools/gotestsummary
+
+      # The summary trims long outputs; the raw stream keeps every line for
+      # the failures that need it. A green run has no use for it.
+      - name: Upload raw test events
+        if: failure()
+        uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a #v7.0.1
+        with:
+          name: management-unit-test-events-${{ matrix.store }}
+          path: management-test-events.jsonl
+          if-no-files-found: ignore
+          retention-days: 14
 
       - name: Upload coverage reports to Codecov
         if: matrix.arch == 'amd64'
@@ -771,12 +789,27 @@ jobs:
       - name: check git status
         run: git --no-pager diff --exit-code
 
+      # Same summary as the unit job: a timeout here names the tests still
+      # running instead of ending in a goroutine dump.
       - name: Test
+        shell: bash
         run: |
+          set -o pipefail
           CGO_ENABLED=1 GOARCH=${{ matrix.arch }} \
           NETBIRD_STORE_ENGINE=${{ matrix.store }} \
           CI=true \
-          mage integrationtest:all -gotestflags="-coverprofile=coverage.txt"
+          mage integrationtest:all -gotestflags="-json -coverprofile=coverage.txt" \
+            | tee management-integration-test-events.jsonl \
+            | go run ./tools/gotestsummary
+
+      - name: Upload raw test events
+        if: failure()
+        uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a #v7.0.1
+        with:
+          name: management-integration-test-events-${{ matrix.store }}
+          path: management-integration-test-events.jsonl
+          if-no-files-found: ignore
+          retention-days: 14
 
       - name: Upload coverage reports to Codecov
         if: matrix.arch == 'amd64'

management/server/account_test.go

@@ -3516,7 +3516,13 @@ func buildTestManager(t testing.TB, store store.Store, nmdataStore *networkmapdb
 
 	eventStore := &activity.InMemoryEventStore{}
 
-	metrics, err := telemetry.NewDefaultAppMetrics(context.Background())
+	// Everything built here watches this context; cancelling it on cleanup stops
+	// the metrics flushers, caches and controllers instead of leaking them for
+	// the rest of the package run.
+	ctx, cancel := context.WithCancel(context.Background())
+	t.Cleanup(cancel)
+
+	metrics, err := telemetry.NewDefaultAppMetrics(ctx)
 	if err != nil {
 		return nil, nil, err
 	}
@@ -3535,8 +3541,6 @@ func buildTestManager(t testing.TB, store store.Store, nmdataStore *networkmapdb
 		Return(nil).
 		AnyTimes()
 
-	ctx := context.Background()
-
 	cacheStore, err := cache.NewStore(ctx, 100*time.Millisecond, 300*time.Millisecond, 100)
 	if err != nil {
 		return nil, nil, err

management/server/store/sql_store.go

@@ -3154,7 +3154,12 @@ func NewMysqlStore(ctx context.Context, dsn string, metrics telemetry.AppMetrics
 		return nil, err
 	}
 
-	return NewSqlStore(ctx, db, types.MysqlStoreEngine, metrics, skipMigration)
+	store, err := NewSqlStore(ctx, db, types.MysqlStoreEngine, metrics, skipMigration)
+	if err != nil {
+		closeGormDB(db)
+		return nil, err
+	}
+	return store, nil
 }
 
 func getGormConfig() *gorm.Config {
@@ -3213,23 +3218,20 @@ func NewSqliteStoreFromFileStore(ctx context.Context, fileStore *FileStore, data
 
 // NewPostgresqlStoreFromSqlStore restores a store from SqlStore and stores Postgres DB.
 func NewPostgresqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn string, metrics telemetry.AppMetrics) (*SqlStore, error) {
-	store, err := NewPostgresqlStoreForTests(ctx, dsn, metrics, false)
+	return newPostgresqlStoreFromSqlStore(ctx, sqliteStore, dsn, metrics, false)
+}
+
+func newPostgresqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn string, metrics telemetry.AppMetrics, skipMigration bool) (*SqlStore, error) {
+	store, err := NewPostgresqlStoreForTests(ctx, dsn, metrics, skipMigration)
 	if err != nil {
 		return nil, err
 	}
 
-	err = store.SaveInstallationID(ctx, sqliteStore.GetInstallationID())
-	if err != nil {
+	if err := seedFromSqliteStore(ctx, store, sqliteStore); err != nil {
+		closeStore(ctx, store)
 		return nil, err
 	}
 
-	for _, account := range sqliteStore.GetAllAccounts(ctx) {
-		err := store.SaveAccount(ctx, account)
-		if err != nil {
-			return nil, err
-		}
-	}
-
 	return store, nil
 }
 
@@ -3241,11 +3243,14 @@ func NewPostgresqlStoreForTests(ctx context.Context, dsn string, metrics telemet
 	}
 	pool, err := connectToPgDbForTests(context.Background(), dsn)
 	if err != nil {
+		closeGormDB(db)
 		return nil, err
 	}
 	store, err := NewSqlStore(ctx, db, types.PostgresStoreEngine, metrics, skipMigration)
 	if err != nil {
+		// Release the sessions, or the caller cannot drop the database.
 		pool.Close()
+		closeGormDB(db)
 		return nil, err
 	}
 	store.pool = pool
@@ -3279,22 +3284,42 @@ func connectToPgDbForTests(ctx context.Context, dsn string) (*pgxpool.Pool, erro
 
 // NewMysqlStoreFromSqlStore restores a store from SqlStore and stores MySQL DB.
 func NewMysqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn string, metrics telemetry.AppMetrics) (*SqlStore, error) {
-	store, err := NewMysqlStore(ctx, dsn, metrics, false)
-	if err != nil {
-		return nil, err
-	}
+	return newMysqlStoreFromSqlStore(ctx, sqliteStore, dsn, metrics, false)
+}
 
-	err = store.SaveInstallationID(ctx, sqliteStore.GetInstallationID())
-	if err != nil {
-		return nil, err
+// seedFromSqliteStore copies the installation ID and the accounts of the
+// sqlite seed store into a freshly created engine store.
+func seedFromSqliteStore(ctx context.Context, store, sqliteStore *SqlStore) error {
+	if err := store.SaveInstallationID(ctx, sqliteStore.GetInstallationID()); err != nil {
+		return err
 	}
-
 	for _, account := range sqliteStore.GetAllAccounts(ctx) {
-		err := store.SaveAccount(ctx, account)
-		if err != nil {
-			return nil, err
+		if err := store.SaveAccount(ctx, account); err != nil {
+			return err
 		}
 	}
+	return nil
+}
+
+// closeStore releases a store that is not handed to the caller, so a failed
+// seed does not leak its connection and pool.
+func closeStore(ctx context.Context, store *SqlStore) {
+	store.Close(ctx)
+	if store.pool != nil {
+		store.pool.Close()
+	}
+}
+
+func newMysqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn string, metrics telemetry.AppMetrics, skipMigration bool) (*SqlStore, error) {
+	store, err := NewMysqlStore(ctx, dsn, metrics, skipMigration)
+	if err != nil {
+		return nil, err
+	}
+
+	if err := seedFromSqliteStore(ctx, store, sqliteStore); err != nil {
+		closeStore(ctx, store)
+		return nil, err
+	}
 
 	return store, nil
 }

management/server/store/store.go

@@ -4,6 +4,7 @@ package store
 
 import (
 	"context"
+	"database/sql"
 	"errors"
 	"fmt"
 	"net"
@@ -15,6 +16,7 @@ import (
 	"runtime"
 	"slices"
 	"strings"
+	"sync"
 	"time"
 
 	"github.com/google/uuid"
@@ -732,6 +734,7 @@ func NewTestStoreFromSQL(ctx context.Context, filename string, dataDir string) (
 			time.Sleep(100 * time.Millisecond)
 		}
 	}
+	store.Close(ctx)
 	return nil, nil, fmt.Errorf("failed to create test store after %d attempts: %v", maxRetries, err)
 }
 
@@ -758,14 +761,15 @@ func addAllGroupToAccount(ctx context.Context, store Store) error {
 	return nil
 }
 
-func getSqlStoreEngine(ctx context.Context, store *SqlStore, kind types.Engine) (Store, func(), error) {
+func getSqlStoreEngine(ctx context.Context, sqliteStore *SqlStore, kind types.Engine) (Store, func(), error) {
+	store := sqliteStore
 	var cleanup func()
 	var err error
 	switch kind {
 	case types.PostgresStoreEngine:
-		store, cleanup, err = newReusedPostgresStore(ctx, store, kind)
+		store, cleanup, err = newReusedPostgresStore(ctx, sqliteStore, kind)
 	case types.MysqlStoreEngine:
-		store, cleanup, err = newReusedMysqlStore(ctx, store, kind)
+		store, cleanup, err = newReusedMysqlStore(ctx, sqliteStore, kind)
 	default:
 		cleanup = func() {
 			// sqlite doesn't need to be cleaned up
@@ -781,6 +785,11 @@ func getSqlStoreEngine(ctx context.Context, store *SqlStore, kind types.Engine)
 		if store.pool != nil {
 			store.pool.Close()
 		}
+		if store != sqliteStore {
+			// The sqlite store only seeded the engine under test; without this
+			// every test leaks its connection and the opener goroutines.
+			sqliteStore.Close(ctx)
+		}
 	}
 
 	return store, closeConnection, nil
@@ -805,19 +814,23 @@ func newReusedPostgresStore(ctx context.Context, store *SqlStore, kind types.Eng
 		return nil, nil, fmt.Errorf("failed to open postgres connection: %v", err)
 	}
 
-	dsn, cleanup, err := createRandomDB(dsn, db, kind)
-
-	sqlDB, _ := db.DB()
-	if sqlDB != nil {
-		sqlDB.Close()
+	template, err := postgresSchemaTemplate(ctx, dsn, db)
+	if err != nil {
+		closeGormDB(db)
+		return nil, nil, err
 	}
 
+	dsn, cleanup, err := createRandomDB(dsn, db, kind, template)
+
+	closeGormDB(db)
+
 	if err != nil {
 		return nil, nil, err
 	}
 
-	store, err = NewPostgresqlStoreFromSqlStore(ctx, store, dsn, nil)
+	store, err = newPostgresqlStoreFromSqlStore(ctx, store, dsn, nil, true)
 	if err != nil {
+		cleanup()
 		return nil, nil, err
 	}
 
@@ -850,7 +863,13 @@ func newReusedMysqlStore(ctx context.Context, store *SqlStore, kind types.Engine
 	sqlDB.SetMaxOpenConns(1)
 	sqlDB.SetMaxIdleConns(1)
 
-	dsn, cleanup, err := createRandomDB(dsn, db, kind)
+	tableDDL, err := mysqlSchemaTemplate(ctx, dsn, db)
+	if err != nil {
+		sqlDB.Close()
+		return nil, nil, err
+	}
+
+	dsn, cleanup, err := createRandomDB(dsn, db, kind, "")
 
 	sqlDB.Close()
 
@@ -858,14 +877,200 @@ func newReusedMysqlStore(ctx context.Context, store *SqlStore, kind types.Engine
 		return nil, nil, err
 	}
 
-	store, err = NewMysqlStoreFromSqlStore(ctx, store, dsn, nil)
+	if err := cloneMysqlSchema(ctx, dsn, tableDDL); err != nil {
+		cleanup()
+		return nil, nil, err
+	}
+
+	store, err = newMysqlStoreFromSqlStore(ctx, store, dsn, nil, true)
 	if err != nil {
+		cleanup()
 		return nil, nil, err
 	}
 
 	return store, cleanup, nil
 }
 
+// schemaTemplates remembers, per engine and server, a database that went
+// through the full migration once in this process. Every later test database
+// is cloned from it, so a test pays for CREATE DATABASE and a schema copy
+// instead of the 40-table AutoMigrate plus every pre and post migration, which
+// is what made each MySQL test store cost well over a second in CI.
+var (
+	schemaTemplatesMu sync.Mutex
+	schemaTemplates   = map[string]*schemaTemplate{}
+)
+
+type schemaTemplate struct {
+	dbName string
+	// tableDDL holds the CREATE TABLE statements of the template. MySQL has no
+	// server-side database template, so the schema is replayed statement by
+	// statement into each test database.
+	tableDDL []string
+}
+
+func schemaTemplateKey(engine types.Engine, dsn string) string {
+	return string(engine) + "|" + dsn
+}
+
+func newTestDBName(prefix string) string {
+	return fmt.Sprintf("%s_%s", prefix, strings.ReplaceAll(uuid.New().String(), "-", "_"))
+}
+
+// postgresSchemaTemplate returns the name of a fully migrated database that
+// CREATE DATABASE ... TEMPLATE can copy, creating it on first use.
+func postgresSchemaTemplate(ctx context.Context, baseDSN string, admin *gorm.DB) (string, error) {
+	schemaTemplatesMu.Lock()
+	defer schemaTemplatesMu.Unlock()
+
+	key := schemaTemplateKey(types.PostgresStoreEngine, baseDSN)
+	if tpl, ok := schemaTemplates[key]; ok {
+		return tpl.dbName, nil
+	}
+
+	name := newTestDBName("test_template")
+	if err := admin.Exec(fmt.Sprintf("CREATE DATABASE %s", name)).Error; err != nil {
+		return "", fmt.Errorf("create postgres template database: %w", err)
+	}
+
+	tplStore, err := NewPostgresqlStoreForTests(ctx, replaceDBName(baseDSN, name), nil, false)
+	if err != nil {
+		dropDatabase(admin, name)
+		return "", fmt.Errorf("migrate postgres template database: %w", err)
+	}
+	// TEMPLATE refuses a source that still has sessions, so release both handles
+	// before the first clone.
+	tplStore.Close(ctx)
+	if tplStore.pool != nil {
+		tplStore.pool.Close()
+	}
+
+	schemaTemplates[key] = &schemaTemplate{dbName: name}
+	return name, nil
+}
+
+// mysqlSchemaTemplate returns the CREATE TABLE statements of a fully migrated
+// database, migrating one on first use.
+func mysqlSchemaTemplate(ctx context.Context, baseDSN string, admin *gorm.DB) ([]string, error) {
+	schemaTemplatesMu.Lock()
+	defer schemaTemplatesMu.Unlock()
+
+	key := schemaTemplateKey(types.MysqlStoreEngine, baseDSN)
+	if tpl, ok := schemaTemplates[key]; ok {
+		return tpl.tableDDL, nil
+	}
+
+	name := newTestDBName("test_template")
+	if err := admin.Exec(fmt.Sprintf("CREATE DATABASE %s", name)).Error; err != nil {
+		return nil, fmt.Errorf("create mysql template database: %w", err)
+	}
+
+	tplStore, err := NewMysqlStore(ctx, replaceDBName(baseDSN, name), nil, false)
+	if err != nil {
+		dropDatabase(admin, name)
+		return nil, fmt.Errorf("migrate mysql template database: %w", err)
+	}
+	tableDDL, err := mysqlTableDDL(ctx, tplStore.db, name)
+	tplStore.Close(ctx)
+	if err != nil {
+		dropDatabase(admin, name)
+		return nil, err
+	}
+
+	schemaTemplates[key] = &schemaTemplate{dbName: name, tableDDL: tableDDL}
+	return tableDDL, nil
+}
+
+func mysqlTableDDL(ctx context.Context, db *gorm.DB, dbName string) ([]string, error) {
+	sqlDB, err := db.DB()
+	if err != nil {
+		return nil, err
+	}
+
+	tables, err := mysqlTableNames(ctx, sqlDB, dbName)
+	if err != nil {
+		return nil, err
+	}
+
+	tableDDL := make([]string, 0, len(tables))
+	for _, table := range tables {
+		var name, createStmt string
+		row := sqlDB.QueryRowContext(ctx, fmt.Sprintf("SHOW CREATE TABLE %s.%s", dbName, table))
+		if err := row.Scan(&name, &createStmt); err != nil {
+			return nil, fmt.Errorf("read create statement of %s: %w", table, err)
+		}
+		tableDDL = append(tableDDL, createStmt)
+	}
+	return tableDDL, nil
+}
+
+func mysqlTableNames(ctx context.Context, sqlDB *sql.DB, dbName string) ([]string, error) {
+	rows, err := sqlDB.QueryContext(ctx, fmt.Sprintf("SHOW TABLES FROM %s", dbName))
+	if err != nil {
+		return nil, fmt.Errorf("list template tables: %w", err)
+	}
+	defer rows.Close()
+
+	var tables []string
+	for rows.Next() {
+		var table string
+		if err := rows.Scan(&table); err != nil {
+			return nil, fmt.Errorf("scan template table name: %w", err)
+		}
+		tables = append(tables, table)
+	}
+	if err := rows.Err(); err != nil {
+		return nil, fmt.Errorf("list template tables: %w", err)
+	}
+	return tables, nil
+}
+
+// cloneMysqlSchema replays the template's CREATE TABLE statements into the
+// database the DSN points at.
+func cloneMysqlSchema(ctx context.Context, dsn string, tableDDL []string) error {
+	db, err := gorm.Open(mysql.Open(dsn+"?charset=utf8&parseTime=True&loc=Local"), getGormConfig())
+	if err != nil {
+		return fmt.Errorf("connect to test database: %w", err)
+	}
+	sqlDB, err := db.DB()
+	if err != nil {
+		return err
+	}
+	defer sqlDB.Close()
+
+	// The statements come out of SHOW TABLES in name order, not dependency
+	// order, and their foreign keys reference tables of the session's default
+	// database. Pin a single connection so the session setting below covers
+	// every statement, and connect straight to the new database so unqualified
+	// references land there.
+	sqlDB.SetMaxOpenConns(1)
+	if _, err := sqlDB.ExecContext(ctx, "SET FOREIGN_KEY_CHECKS = 0"); err != nil {
+		return fmt.Errorf("disable foreign key checks: %w", err)
+	}
+	for _, stmt := range tableDDL {
+		if _, err := sqlDB.ExecContext(ctx, stmt); err != nil {
+			return fmt.Errorf("replay table definition: %w", err)
+		}
+	}
+	return nil
+}
+
+// dropDatabase removes a template that never became usable, so a failed setup
+// does not leave it behind on a shared server. The server may still be tearing
+// down the sessions the failed migration held, so the drop retries while
+// Postgres reports the database as in use.
+func dropDatabase(admin *gorm.DB, name string) {
+	if err := execWithTemplateRetry(admin, fmt.Sprintf("DROP DATABASE IF EXISTS %s", name)); err != nil {
+		log.Warnf("failed to drop template database %s: %v", name, err)
+	}
+}
+
+func closeGormDB(db *gorm.DB) {
+	if sqlDB, _ := db.DB(); sqlDB != nil {
+		sqlDB.Close()
+	}
+}
+
 func openDBWithRetry(dsn string, engine types.Engine, maxRetries int) (*gorm.DB, error) {
 	var db *gorm.DB
 	var err error
@@ -891,10 +1096,16 @@ func openDBWithRetry(dsn string, engine types.Engine, maxRetries int) (*gorm.DB,
 	return nil, err
 }
 
-func createRandomDB(dsn string, db *gorm.DB, engine types.Engine) (string, func(), error) {
-	dbName := fmt.Sprintf("test_db_%s", strings.ReplaceAll(uuid.New().String(), "-", "_"))
+// createRandomDB creates a uniquely named database for one test. On postgres a
+// non-empty template is copied server-side with CREATE DATABASE ... TEMPLATE.
+func createRandomDB(dsn string, db *gorm.DB, engine types.Engine, template string) (string, func(), error) {
+	dbName := newTestDBName("test_db")
 
-	if err := db.Exec(fmt.Sprintf("CREATE DATABASE %s", dbName)).Error; err != nil {
+	createStmt := fmt.Sprintf("CREATE DATABASE %s", dbName)
+	if template != "" && engine == types.PostgresStoreEngine {
+		createStmt = fmt.Sprintf("CREATE DATABASE %s TEMPLATE %s", dbName, template)
+	}
+	if err := execWithTemplateRetry(db, createStmt); err != nil {
 		return "", nil, fmt.Errorf("failed to create database: %v", err)
 	}
 
@@ -960,6 +1171,20 @@ func createRandomDB(dsn string, db *gorm.DB, engine types.Engine) (string, func(
 	return replaceDBName(dsn, dbName), cleanup, nil
 }
 
+// execWithTemplateRetry runs a statement, retrying briefly when postgres still
+// sees the template's just-closed sessions and refuses to copy it.
+func execWithTemplateRetry(db *gorm.DB, stmt string) error {
+	var err error
+	for attempt := 0; attempt < 20; attempt++ {
+		err = db.Exec(stmt).Error
+		if err == nil || !strings.Contains(err.Error(), "is being accessed by other users") {
+			return err
+		}
+		time.Sleep(100 * time.Millisecond)
+	}
+	return err
+}
+
 func replaceDBName(dsn, newDBName string) string {
 	re := regexp.MustCompile(`(?P<pre>[:/@])(?P<dbname>[^/?]+)(?P<post>\?|$)`)
 	return re.ReplaceAllString(dsn, `${pre}`+newDBName+`${post}`)

management/server/testutil/store.go

@@ -37,6 +37,18 @@ func CreateMysqlTestContainer() (func(), string, error) {
 		mysql.WithDatabase("testing"),
 		mysql.WithUsername("root"),
 		mysql.WithPassword("testing"),
+		// Every test creates and drops a database with about 40 tables, so with
+		// the server defaults the run is dominated by durability work: each
+		// CREATE TABLE fsyncs the redo log, the binary log and the doublewrite
+		// buffer. None of it protects anything in a container that is discarded
+		// after the run. Tables stay in per-table files on purpose: in the shared
+		// system tablespace the cost of every CREATE and DROP grew with the number
+		// of databases the run had already created.
+		testcontainers.WithCmd("mysqld",
+			"--innodb-flush-log-at-trx-commit=0",
+			"--innodb-doublewrite=OFF",
+			"--skip-log-bin",
+		),
 		testcontainers.WithWaitStrategy(
 			wait.ForLog("/usr/sbin/mysqld: ready for connections").
 				WithOccurrence(1).WithStartupTimeout(15*time.Second).WithPollInterval(100*time.Millisecond),

tools/gotestsummary/main.go

@@ -0,0 +1,402 @@
+// Package main turns a `go test -json` stream into a readable CI log.
+//
+// It prints one line per top-level test as it finishes, the captured output of
+// every failed test, the head of a package-level panic (which is where Go
+// reports "test timed out" and the list of still-running tests), and ends with
+// the per-package durations and the slowest tests. The exit code is always zero
+// unless the input cannot be read; the `go test` exit code is what CI should act
+// on, so run the two with `set -o pipefail`.
+//
+// Usage:
+//
+//	go test -json ./... | go run ./tools/gotestsummary
+//	go run ./tools/gotestsummary -slowest 60 test-output.jsonl
+package main
+
+import (
+	"bufio"
+	"encoding/json"
+	"flag"
+	"fmt"
+	"io"
+	"os"
+	"sort"
+	"strings"
+	"time"
+)
+
+const (
+	modulePrefix = "github.com/netbirdio/netbird/"
+
+	// failedTestOutputLines bounds how much captured output a single failed
+	// test may print, so one noisy failure cannot flood the job log.
+	failedTestOutputLines = 200
+	// panicHeadLines is enough for the "panic: test timed out" header, the
+	// "running tests:" list, and the first few goroutines of the dump.
+	panicHeadLines = 150
+	// bufferedOutputLines bounds the per-test output kept in memory while the
+	// test runs; only the tail is kept once the cap is reached.
+	bufferedOutputLines = 400
+)
+
+type event struct {
+	Action  string  `json:"Action"`
+	Package string  `json:"Package"`
+	Test    string  `json:"Test"`
+	Output  string  `json:"Output"`
+	Elapsed float64 `json:"Elapsed"`
+	// ImportPath is set instead of Package on build events. It carries a
+	// " [pkg.test]" suffix naming the test binary the package was compiled
+	// for, and the same package can be built for several binaries at once.
+	ImportPath string `json:"ImportPath"`
+	// FailedBuild names the ImportPath whose build failure made the package
+	// fail; go test reports the package fail event after the build-fail one.
+	FailedBuild string `json:"FailedBuild"`
+}
+
+type testKey struct {
+	pkg, name string
+}
+
+type testResult struct {
+	pkg, name string
+	action    string
+	elapsed   time.Duration
+}
+
+type packageResult struct {
+	pkg     string
+	action  string
+	elapsed time.Duration
+}
+
+type summarizer struct {
+	out io.Writer
+
+	output  map[testKey][]string
+	dropped map[testKey]int
+	// pkgOutput keeps what a package printed outside any test, which is where
+	// compiler diagnostics of a failed build end up.
+	pkgOutput map[string][]string
+	// failedBuilds holds the ImportPaths whose build failed and has not been
+	// reported through a package fail event yet.
+	failedBuilds map[string]bool
+	tests        []testResult
+	packages     []packageResult
+	// panics holds the head of a panic per package. Package streams interleave
+	// in a go test -json run, so one package's dump must not swallow another's
+	// output.
+	panics map[string][]string
+}
+
+func newSummarizer(out io.Writer) *summarizer {
+	return &summarizer{
+		out:          out,
+		output:       make(map[testKey][]string),
+		dropped:      make(map[testKey]int),
+		pkgOutput:    make(map[string][]string),
+		failedBuilds: make(map[string]bool),
+		panics:       make(map[string][]string),
+	}
+}
+
+func main() {
+	slowest := flag.Int("slowest", 40, "number of slowest top-level tests to list")
+	flag.Parse()
+
+	if err := run(flag.Arg(0), *slowest); err != nil {
+		fmt.Fprintln(os.Stderr, err)
+		os.Exit(1)
+	}
+}
+
+func run(path string, slowest int) error {
+	in := os.Stdin
+	if path != "" {
+		f, err := os.Open(path)
+		if err != nil {
+			return fmt.Errorf("open %s: %w", path, err)
+		}
+		defer f.Close()
+		in = f
+	}
+
+	s := newSummarizer(os.Stdout)
+	if err := s.consume(in); err != nil {
+		return fmt.Errorf("read input: %w", err)
+	}
+	s.printSummary(slowest)
+	return nil
+}
+
+func (s *summarizer) consume(r io.Reader) error {
+	scanner := bufio.NewScanner(r)
+	scanner.Buffer(make([]byte, 0, 1024*1024), 16*1024*1024)
+	for scanner.Scan() {
+		line := scanner.Bytes()
+		var ev event
+		if err := json.Unmarshal(line, &ev); err != nil {
+			// Build errors and other non-JSON lines are passed through untouched.
+			fmt.Fprintln(s.out, string(line))
+			continue
+		}
+		s.handle(ev)
+	}
+	return scanner.Err()
+}
+
+func (s *summarizer) handle(ev event) {
+	if ev.Package == "" {
+		// Keep the full path as the key so concurrent builds of one package for
+		// different test binaries do not share, and delete, each other's state.
+		ev.Package = ev.ImportPath
+	}
+	key := testKey{pkg: ev.Package, name: ev.Test}
+	switch ev.Action {
+	case "run":
+		// Register the test even before it prints anything, so a test that
+		// hangs silently still shows up as unfinished.
+		if ev.Test != "" {
+			if _, ok := s.output[key]; !ok {
+				s.output[key] = []string{}
+			}
+		}
+	case "output":
+		s.handleOutput(key, strings.TrimRight(ev.Output, "\n"))
+	case "build-output":
+		// Compiler output may carry several lines per event and is never test
+		// output, so it skips the panic detection.
+		for _, line := range strings.Split(strings.TrimRight(ev.Output, "\n"), "\n") {
+			s.pkgOutput[key.pkg] = appendBounded(s.pkgOutput[key.pkg], line)
+		}
+	case "build-fail":
+		// The package fail event that follows carries FailedBuild and reports
+		// the compiler output; this only remembers the build in case it never
+		// comes.
+		s.failedBuilds[key.pkg] = true
+	case "pass", "fail", "skip":
+		if ev.Test == "" {
+			s.handlePackageResult(ev)
+			return
+		}
+		s.handleTestResult(key, ev)
+	}
+}
+
+func (s *summarizer) handleOutput(key testKey, line string) {
+	if strings.HasPrefix(line, "panic: ") || strings.HasPrefix(line, "fatal error: ") {
+		if _, ok := s.panics[key.pkg]; !ok {
+			s.panics[key.pkg] = []string{}
+		}
+	}
+	if head, ok := s.panics[key.pkg]; ok {
+		// The goroutine dump that follows a panic is kept in the panic head only;
+		// letting it flood the per-test buffers would hide the test's own output.
+		if len(head) < panicHeadLines {
+			s.panics[key.pkg] = append(head, line)
+		}
+		return
+	}
+
+	if key.name == "" {
+		s.pkgOutput[key.pkg] = appendBounded(s.pkgOutput[key.pkg], line)
+		return
+	}
+	if len(s.output[key]) >= bufferedOutputLines {
+		s.dropped[key]++
+	}
+	s.output[key] = appendBounded(s.output[key], line)
+}
+
+// appendBounded keeps the most recent bufferedOutputLines lines.
+func appendBounded(buf []string, line string) []string {
+	if len(buf) >= bufferedOutputLines {
+		buf = buf[1:]
+	}
+	return append(buf, line)
+}
+
+func (s *summarizer) handleTestResult(key testKey, ev event) {
+	elapsed := time.Duration(ev.Elapsed * float64(time.Second))
+	s.tests = append(s.tests, testResult{
+		pkg:     ev.Package,
+		name:    ev.Test,
+		action:  ev.Action,
+		elapsed: elapsed,
+	})
+
+	if !strings.Contains(ev.Test, "/") || ev.Action == "fail" {
+		fmt.Fprintf(s.out, "--- %s: %s.%s (%s)\n", strings.ToUpper(ev.Action), shortPkg(ev.Package), ev.Test, elapsed.Round(time.Millisecond))
+	}
+	if ev.Action == "fail" {
+		s.printTestOutput(key)
+	}
+	delete(s.output, key)
+	delete(s.dropped, key)
+}
+
+func (s *summarizer) printTestOutput(key testKey) {
+	lines := s.output[key]
+	if len(lines) == 0 {
+		return
+	}
+	skipped := s.dropped[key]
+	if len(lines) > failedTestOutputLines {
+		skipped += len(lines) - failedTestOutputLines
+		lines = lines[len(lines)-failedTestOutputLines:]
+	}
+	if skipped > 0 {
+		fmt.Fprintf(s.out, "    ... %d earlier output lines omitted ...\n", skipped)
+	}
+	for _, l := range lines {
+		fmt.Fprintf(s.out, "    %s\n", l)
+	}
+}
+
+func (s *summarizer) handlePackageResult(ev event) {
+	elapsed := time.Duration(ev.Elapsed * float64(time.Second))
+	s.packages = append(s.packages, packageResult{pkg: ev.Package, action: ev.Action, elapsed: elapsed})
+
+	label := "ok  "
+	switch ev.Action {
+	case "fail", "build-fail":
+		label = "FAIL"
+	case "skip":
+		label = "skip"
+	}
+	fmt.Fprintf(s.out, "%s %s %s\n", label, shortPkg(ev.Package), elapsed.Round(time.Millisecond))
+
+	if label == "FAIL" {
+		if ev.FailedBuild != "" {
+			// Several test binaries can share one failed dependency, so its
+			// output stays available for the next package that names it.
+			s.printPackageOutput(ev.FailedBuild, "build output of %s")
+			delete(s.failedBuilds, ev.FailedBuild)
+		}
+		s.printPackageOutput(ev.Package, "output of %s outside tests")
+		s.printUnfinished(ev.Package)
+		s.printPanicHead(ev.Package)
+	}
+	delete(s.pkgOutput, ev.Package)
+	delete(s.panics, ev.Package)
+}
+
+// printUnclaimedBuildFailures reports the failed builds no package fail event
+// accounted for, so a compiler error never disappears from the log.
+func (s *summarizer) printUnclaimedBuildFailures() {
+	var builds []string
+	for b := range s.failedBuilds {
+		builds = append(builds, b)
+	}
+	sort.Strings(builds)
+	for _, b := range builds {
+		fmt.Fprintf(s.out, "FAIL %s [build failed]\n", shortPkg(b))
+		s.printPackageOutput(b, "build output of %s")
+	}
+}
+
+// printPackageOutput shows what a failed package printed outside its tests,
+// or the compiler errors of a failed build, under the given header.
+func (s *summarizer) printPackageOutput(pkg, header string) {
+	lines := s.pkgOutput[pkg]
+	if len(lines) == 0 {
+		return
+	}
+	if len(lines) > failedTestOutputLines {
+		lines = lines[len(lines)-failedTestOutputLines:]
+	}
+	fmt.Fprintf(s.out, "\n==== "+header+" ====\n", shortPkg(pkg))
+	for _, l := range lines {
+		fmt.Fprintf(s.out, "    %s\n", l)
+	}
+}
+
+func (s *summarizer) printPanicHead(pkg string) {
+	head := s.panics[pkg]
+	if len(head) == 0 {
+		return
+	}
+	fmt.Fprintf(s.out, "\n==== panic in %s (first %d lines) ====\n", shortPkg(pkg), len(head))
+	for _, l := range head {
+		fmt.Fprintln(s.out, l)
+	}
+	fmt.Fprintln(s.out, "==== end of panic head ====")
+	fmt.Fprintln(s.out)
+}
+
+// printUnfinished names the tests of a failed package that never reported a
+// result, which is what a timeout leaves behind, and shows their last output.
+func (s *summarizer) printUnfinished(pkg string) {
+	var keys []testKey
+	for key := range s.output {
+		if key.pkg == pkg && key.name != "" {
+			keys = append(keys, key)
+		}
+	}
+	if len(keys) == 0 {
+		return
+	}
+	sort.Slice(keys, func(i, j int) bool { return keys[i].name < keys[j].name })
+	fmt.Fprintf(s.out, "\n==== tests in %s that did not finish (%d) ====\n", shortPkg(pkg), len(keys))
+	for _, key := range keys {
+		fmt.Fprintf(s.out, "--- UNFINISHED: %s.%s\n", shortPkg(key.pkg), key.name)
+		s.printTestOutput(key)
+		delete(s.output, key)
+		delete(s.dropped, key)
+	}
+}
+
+func (s *summarizer) printSummary(slowest int) {
+	s.printUnclaimedBuildFailures()
+
+	fmt.Fprintln(s.out)
+	fmt.Fprintln(s.out, "==== package durations ====")
+	sort.Slice(s.packages, func(i, j int) bool { return s.packages[i].elapsed > s.packages[j].elapsed })
+	for _, p := range s.packages {
+		fmt.Fprintf(s.out, "%9s  %-4s  %s\n", p.elapsed.Round(time.Millisecond), p.action, shortPkg(p.pkg))
+	}
+
+	var failed []testResult
+	for _, t := range s.tests {
+		if t.action == "fail" {
+			failed = append(failed, t)
+		}
+	}
+	if len(failed) > 0 {
+		fmt.Fprintln(s.out)
+		fmt.Fprintf(s.out, "==== failed tests (%d) ====\n", len(failed))
+		for _, t := range failed {
+			fmt.Fprintf(s.out, "%9s  %s.%s\n", t.elapsed.Round(time.Millisecond), shortPkg(t.pkg), t.name)
+		}
+	}
+
+	s.printSlowest("slowest top-level tests", slowest, func(t testResult) bool { return !strings.Contains(t.name, "/") })
+	s.printSlowest("slowest subtests", slowest/2, func(t testResult) bool { return strings.Contains(t.name, "/") })
+}
+
+func (s *summarizer) printSlowest(title string, limit int, keep func(testResult) bool) {
+	var tests []testResult
+	for _, t := range s.tests {
+		if keep(t) {
+			tests = append(tests, t)
+		}
+	}
+	if len(tests) == 0 || limit <= 0 {
+		return
+	}
+	sort.Slice(tests, func(i, j int) bool { return tests[i].elapsed > tests[j].elapsed })
+	if len(tests) > limit {
+		tests = tests[:limit]
+	}
+
+	fmt.Fprintln(s.out)
+	fmt.Fprintf(s.out, "==== %s (%d) ====\n", title, len(tests))
+	for _, t := range tests {
+		fmt.Fprintf(s.out, "%9s  %-4s  %s.%s\n", t.elapsed.Round(time.Millisecond), t.action, shortPkg(t.pkg), t.name)
+	}
+}
+
+func shortPkg(pkg string) string {
+	pkg, _, _ = strings.Cut(pkg, " [")
+	return strings.TrimPrefix(pkg, modulePrefix)
+}

tools/gotestsummary/main_test.go

@@ -0,0 +1,180 @@
+package main
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+)
+
+func feed(t *testing.T, events string) string {
+	t.Helper()
+	var out bytes.Buffer
+	s := newSummarizer(&out)
+	if err := s.consume(strings.NewReader(events)); err != nil {
+		t.Fatalf("consume: %v", err)
+	}
+	s.printSummary(10)
+	return out.String()
+}
+
+func TestTimeoutReportsUnfinishedTestsAndPanicHead(t *testing.T) {
+	events := `
+{"Action":"run","Package":"a","Test":"TestHang"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"=== RUN   TestHang\n"}
+{"Action":"run","Package":"a","Test":"TestSilent"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"panic: test timed out after 1s\n"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"\trunning tests:\n"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"\t\tTestHang (1s)\n"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"goroutine 7 [running]:\n"}
+{"Action":"fail","Package":"a","Elapsed":1.0}
+`
+	got := feed(t, events)
+	for _, want := range []string{
+		"--- UNFINISHED: a.TestHang",
+		"--- UNFINISHED: a.TestSilent",
+		"==== panic in a (first 4 lines) ====",
+		"\t\tTestHang (1s)",
+		"    === RUN   TestHang",
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("output lacks %q:\n%s", want, got)
+		}
+	}
+	if strings.Contains(got, "    goroutine 7 [running]:") {
+		t.Errorf("goroutine dump leaked into the test's own output:\n%s", got)
+	}
+}
+
+func TestPanicInOnePackageKeepsOtherPackageOutput(t *testing.T) {
+	events := `
+{"Action":"run","Package":"a","Test":"TestHang"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"panic: test timed out after 1s\n"}
+{"Action":"run","Package":"b","Test":"TestOther"}
+{"Action":"output","Package":"b","Test":"TestOther","Output":"    other_test.go:9: expected 1, got 2\n"}
+{"Action":"output","Package":"a","Test":"TestHang","Output":"goroutine 7 [running]:\n"}
+{"Action":"fail","Package":"b","Test":"TestOther","Elapsed":0.01}
+{"Action":"fail","Package":"b","Elapsed":0.02}
+{"Action":"fail","Package":"a","Elapsed":1.0}
+`
+	got := feed(t, events)
+	if !strings.Contains(got, "    other_test.go:9: expected 1, got 2") {
+		t.Errorf("other package's output was swallowed by the panic head:\n%s", got)
+	}
+	if strings.Contains(got, "panic in b") {
+		t.Errorf("panic head attributed to the wrong package:\n%s", got)
+	}
+	if !strings.Contains(got, "==== panic in a (first 2 lines) ====") {
+		t.Errorf("panic head missing for package a:\n%s", got)
+	}
+}
+
+func TestBuildFailureShowsCompilerOutput(t *testing.T) {
+	// The event sequence go test emits for a build failure: the build events
+	// name the test binary, then the package itself fails with FailedBuild.
+	events := `
+{"Action":"build-output","ImportPath":"a [a.test]","Output":"# a [a.test]\na_test.go:7:2: undefined: nope\na_test.go:9:2: undefined: nope2\n"}
+{"Action":"build-fail","ImportPath":"a [a.test]"}
+{"Action":"start","Package":"a"}
+{"Action":"output","Package":"a","Output":"FAIL\ta [build failed]\n"}
+{"Action":"fail","Package":"a","Elapsed":0,"FailedBuild":"a [a.test]"}
+`
+	got := feed(t, events)
+	for _, want := range []string{
+		"==== build output of a ====",
+		"    a_test.go:7:2: undefined: nope\n    a_test.go:9:2: undefined: nope2",
+		"FAIL\ta [build failed]",
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("output lacks %q:\n%s", want, got)
+		}
+	}
+	if n := strings.Count(got, "FAIL a 0s"); n != 1 {
+		t.Errorf("expected one FAIL line for the package, got %d:\n%s", n, got)
+	}
+	if n := strings.Count(got, "undefined: nope2"); n != 1 {
+		t.Errorf("expected the compiler output once, got %d:\n%s", n, got)
+	}
+}
+
+func TestFailedDependencyOutputIsShownForEveryImporter(t *testing.T) {
+	events := `
+{"Action":"build-output","ImportPath":"m/x","Output":"# m/x\nx.go:3:11: undefined: y\n"}
+{"Action":"build-fail","ImportPath":"m/x"}
+{"Action":"start","Package":"m/a"}
+{"Action":"output","Package":"m/a","Output":"FAIL\tm/a [build failed]\n"}
+{"Action":"fail","Package":"m/a","Elapsed":0,"FailedBuild":"m/x"}
+{"Action":"start","Package":"m/b"}
+{"Action":"output","Package":"m/b","Output":"FAIL\tm/b [build failed]\n"}
+{"Action":"fail","Package":"m/b","Elapsed":0,"FailedBuild":"m/x"}
+`
+	got := feed(t, events)
+	if n := strings.Count(got, "x.go:3:11: undefined: y"); n != 2 {
+		t.Errorf("expected the dependency's compiler output under both packages, got %d:\n%s", n, got)
+	}
+	if strings.Contains(got, "FAIL m/x") {
+		t.Errorf("the dependency must not be reported as a package of its own:\n%s", got)
+	}
+}
+
+func TestBuildFailureWithoutPackageEventIsStillReported(t *testing.T) {
+	events := `
+{"Action":"build-output","ImportPath":"a [a.test]","Output":"a_test.go:7:2: undefined: nope\n"}
+{"Action":"build-fail","ImportPath":"a [a.test]"}
+`
+	got := feed(t, events)
+	for _, want := range []string{"FAIL a [build failed]", "==== build output of a ====", "undefined: nope"} {
+		if !strings.Contains(got, want) {
+			t.Errorf("output lacks %q:\n%s", want, got)
+		}
+	}
+}
+
+func TestCompilerPanicIsBuildOutputNotTestPanic(t *testing.T) {
+	events := `
+{"Action":"build-output","ImportPath":"a [a.test]","Output":"# a [a.test]\npanic: internal compiler error\n\ngoroutine 1 [running]:\n"}
+{"Action":"build-fail","ImportPath":"a [a.test]"}
+{"Action":"start","Package":"a"}
+{"Action":"output","Package":"a","Output":"FAIL\ta [build failed]\n"}
+{"Action":"fail","Package":"a","Elapsed":0,"FailedBuild":"a [a.test]"}
+`
+	got := feed(t, events)
+	if !strings.Contains(got, "==== build output of a ====\n    # a [a.test]\n    panic: internal compiler error") {
+		t.Errorf("compiler diagnostic missing from the build output block:\n%s", got)
+	}
+	if strings.Contains(got, "==== panic in") {
+		t.Errorf("compiler output must not be reported as a test panic:\n%s", got)
+	}
+}
+
+func TestBuildVariantsOfOnePackageKeepSeparateOutput(t *testing.T) {
+	events := `
+{"Action":"build-output","ImportPath":"a [a.test]","Output":"a.go:1:1: broken for a.test\n"}
+{"Action":"build-output","ImportPath":"a [b.test]","Output":"a.go:1:1: broken for b.test\n"}
+{"Action":"build-fail","ImportPath":"a [a.test]"}
+{"Action":"build-fail","ImportPath":"a [b.test]"}
+{"Action":"start","Package":"a"}
+{"Action":"fail","Package":"a","Elapsed":0,"FailedBuild":"a [a.test]"}
+{"Action":"start","Package":"b"}
+{"Action":"fail","Package":"b","Elapsed":0,"FailedBuild":"a [b.test]"}
+`
+	got := feed(t, events)
+	if strings.Count(got, "==== build output of a ====") != 2 {
+		t.Errorf("expected one output block per build variant:\n%s", got)
+	}
+	for _, want := range []string{"broken for a.test", "broken for b.test"} {
+		if strings.Count(got, want) != 1 {
+			t.Errorf("expected %q exactly once:\n%s", want, got)
+		}
+	}
+}
+
+func TestPassingPackageOutputIsNotPrinted(t *testing.T) {
+	events := `
+{"Action":"output","Package":"a","Output":"level=info msg=\"noise between tests\"\n"}
+{"Action":"pass","Package":"a","Elapsed":0.5}
+`
+	got := feed(t, events)
+	if strings.Contains(got, "noise between tests") {
+		t.Errorf("package output of a passing package should stay quiet:\n%s", got)
+	}
+}