diff --git a/.github/workflows/golang-test-linux.yml b/.github/workflows/golang-test-linux.yml index 9e3caa17a..449eb14fa 100644 --- a/.github/workflows/golang-test-linux.yml +++ b/.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' diff --git a/management/server/account_test.go b/management/server/account_test.go index bd7bf2d97..c63782ca8 100644 --- a/management/server/account_test.go +++ b/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 diff --git a/management/server/store/sql_store.go b/management/server/store/sql_store.go index 08ec45395..d2d197a03 100644 --- a/management/server/store/sql_store.go +++ b/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 } diff --git a/management/server/store/store.go b/management/server/store/store.go index 6886536b9..7a92de0a6 100644 --- a/management/server/store/store.go +++ b/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
[:/@])(?P[^/?]+)(?P \?|$)`) return re.ReplaceAllString(dsn, `${pre}`+newDBName+`${post}`) diff --git a/management/server/testutil/store.go b/management/server/testutil/store.go index 07699e2c3..3854c1173 100644 --- a/management/server/testutil/store.go +++ b/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), diff --git a/tools/gotestsummary/main.go b/tools/gotestsummary/main.go new file mode 100644 index 000000000..2a5487fc6 --- /dev/null +++ b/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) +} diff --git a/tools/gotestsummary/main_test.go b/tools/gotestsummary/main_test.go new file mode 100644 index 000000000..d5b51e132 --- /dev/null +++ b/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) + } +}