From b1717d1c629c9852c3c005e2ac4948771551e687 Mon Sep 17 00:00:00 2001 From: sneak Date: Wed, 7 Oct 2026 13:57:55 +0000 Subject: [PATCH] Speed up the vaultik and database package tests (closes #235) In the Dockerfile test phase, internal/vaultik spent 23.6s of 31.9s in 36 tests run one at a time. 24 of them were serial only because they call log.Initialize; they now call it before t.Parallel(), so the logger is replaced before any parallel test runs. The 12 still serial change the umask, TMPDIR, os.Stderr or time.Local. TestLargeDatasets took 8.4s of the 9.8s internal/database run by committing each of its 1,500 inserts on its own; it now makes them in one transaction. TestDedupOnlySnapshotRestores gives its second backup its own snapshot name instead of sleeping 1.1s for a new snapshot ID. Model: opus-5-5 --- TODO.md | 10 ++++ .../database/repository_edge_cases_test.go | 50 +++++++++++-------- internal/vaultik/changed_file_restore_test.go | 6 +-- internal/vaultik/fault_injection_test.go | 37 ++++++-------- internal/vaultik/integration_test.go | 21 ++++---- internal/vaultik/missing_destination_test.go | 15 ++---- internal/vaultik/prune_count_test.go | 3 +- internal/vaultik/restore_interrupt_test.go | 3 +- internal/vaultik/restore_skip_errors_test.go | 11 ++-- internal/vaultik/same_second_rewrite_test.go | 3 +- internal/vaultik/snapshot_summary_test.go | 17 ++++--- internal/vaultik/two_path_snapshot_test.go | 3 +- 12 files changed, 90 insertions(+), 89 deletions(-) diff --git a/TODO.md b/TODO.md index 2f33a00..c6b96b1 100644 --- a/TODO.md +++ b/TODO.md @@ -22,6 +22,16 @@ the tag exists and is exercised; what is left is merging `next` to # Completed Steps +- 2026-10-07: Cut the time the `internal/vaultik` and `internal/database` + tests take ([issue #235](https://git.eeqj.de/sneak/vaultik/issues/235)). + Most of the `internal/vaultik` time went to 24 tests that ran one at a + time only because they call `log.Initialize`; they now call it before + `t.Parallel()`, as the package's other tests do. `TestLargeDatasets` + committed each of its 1,500 inserts on its own and now makes them in + one transaction. `TestDedupOnlySnapshotRestores` gives its second + backup its own snapshot name instead of sleeping past the one-second + timestamp in the snapshot ID. + - 2026-10-07: Made two messages say only what is true ([issue #240](https://git.eeqj.de/sneak/vaultik/issues/240)). A config file that others can read was warned about as containing S3 diff --git a/internal/database/repository_edge_cases_test.go b/internal/database/repository_edge_cases_test.go index 59f85ca..59b54ac 100644 --- a/internal/database/repository_edge_cases_test.go +++ b/internal/database/repository_edge_cases_test.go @@ -3,6 +3,7 @@ package database import ( "context" + "database/sql" "fmt" "strings" "testing" @@ -367,7 +368,7 @@ func verifyBlobNullUploadTS( } // createLargeDatasetFiles creates fileCount files and adds every other -// one to the snapshot. +// one to the snapshot, in one transaction as a backup writes them. func createLargeDatasetFiles( t *testing.T, repos *Repositories, @@ -376,31 +377,38 @@ func createLargeDatasetFiles( ) { t.Helper() - ctx := context.Background() start := time.Now() - for i := range fileCount { - file := &File{ - Path: types.FilePath(fmt.Sprintf("/large/file%05d.txt", i)), - MTime: time.Now(), - Size: int64(i * 1024), - Mode: 0644, - UID: uint32(1000 + (i % 10)), - GID: uint32(1000 + (i % 10)), - } + err := repos.WithTx(context.Background(), + func(ctx context.Context, tx *sql.Tx) error { + for i := range fileCount { + file := &File{ + Path: types.FilePath(fmt.Sprintf("/large/file%05d.txt", i)), + MTime: time.Now(), + Size: int64(i * 1024), + Mode: 0644, + UID: uint32(1000 + (i % 10)), + GID: uint32(1000 + (i % 10)), + } - err := repos.Files.Create(ctx, nil, file) - if err != nil { - t.Fatalf("failed to create file %d: %v", i, err) - } + err := repos.Files.Create(ctx, tx, file) + if err != nil { + return fmt.Errorf("creating file %d: %w", i, err) + } - // Add half to snapshot - if i%2 == 0 { - err = repos.Snapshots.AddFileByID(ctx, nil, snapshotID, file.ID) - if err != nil { - t.Fatal(err) + // Add half to snapshot + if i%2 == 0 { + err = repos.Snapshots.AddFileByID(ctx, tx, snapshotID, file.ID) + if err != nil { + return err + } + } } - } + + return nil + }) + if err != nil { + t.Fatal(err) } t.Logf("Created %d files in %v", fileCount, time.Since(start)) diff --git a/internal/vaultik/changed_file_restore_test.go b/internal/vaultik/changed_file_restore_test.go index de61170..01ed0ec 100644 --- a/internal/vaultik/changed_file_restore_test.go +++ b/internal/vaultik/changed_file_restore_test.go @@ -130,10 +130,9 @@ func assertThirdSnapshotRestores( // up, and that snapshot is removed. The first snapshot keeps the file row, // which now lists the appended content's chunks, while removal drops the // blob that held them. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestBackupAfterRemovingNewestSnapshotRestoresChangedFile(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() @@ -178,10 +177,9 @@ func TestBackupAfterRemovingNewestSnapshotRestoresChangedFile(t *testing.T) { // The next run's prune drops that incomplete snapshot and its blob, while // the first snapshot keeps the file row, which now lists the appended // content's chunks. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestBackupAfterInterruptedRunRestoresChangedFile(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() diff --git a/internal/vaultik/fault_injection_test.go b/internal/vaultik/fault_injection_test.go index 594c284..1595151 100644 --- a/internal/vaultik/fault_injection_test.go +++ b/internal/vaultik/fault_injection_test.go @@ -38,11 +38,9 @@ import ( // (https://git.eeqj.de/sneak/vaultik/issues/130) and is not re-tested // here; these tests target the layers above the backend. // -// The tests run serially, not with t.Parallel: each calls -// log.Initialize, which replaces the package-global logger, and a -// backup or restore running concurrently reads that same logger. Under -// -race the two collide. Running one at a time is the same choice -// prune_count_test.go already makes for the same reason. +// log.Initialize replaces the package-global logger that a running +// backup or restore reads, so each test calls it before t.Parallel, +// while no parallel test is running yet. const ( faultChunkSize = int64(64 * 1024) @@ -165,17 +163,19 @@ func newReaderVaultik( // Scenario 3: a stored blob's bytes are flipped before restore reads // them. Restore must fail loudly, and no file must be left on the // restore target holding corrupt content. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestRestoreRejectsCorruptBlob(t *testing.T) { + log.Initialize(log.Config{}) + t.Parallel() + assertRestoreRejectsDamagedBlob(t, faultstore.GetCorrupt, "corrupt") } // Scenario 4: a stored blob is truncated before restore reads it. Same // contract as the corrupt case. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestRestoreRejectsTruncatedBlob(t *testing.T) { + log.Initialize(log.Config{}) + t.Parallel() + assertRestoreRejectsDamagedBlob(t, faultstore.GetTruncate, "truncated") } @@ -188,7 +188,6 @@ func assertRestoreRejectsDamagedBlob( t *testing.T, fault faultstore.GetFault, name string, ) { t.Helper() - log.Initialize(log.Config{}) fs := afero.NewOsFs() tempDir := t.TempDir() @@ -232,10 +231,9 @@ func assertRestoreRejectsDamagedBlob( // Scenario 6: the backend accepts blob uploads and reports success but // stores nothing. verify --deep must catch it. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestDeepVerifyCatchesLyingBackend(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() @@ -285,10 +283,9 @@ func TestDeepVerifyCatchesLyingBackend(t *testing.T) { // Scenario 1a: a blob upload fails partway through. The interrupted run // must not record the blob as uploaded, must not reference it from the // snapshot, and must leave no blob object at the destination. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestInterruptedBlobUploadRecordsNoUploadedBlob(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() @@ -361,10 +358,9 @@ func TestInterruptedBlobUploadRecordsNoUploadedBlob(t *testing.T) { // chunks in a blob that was actually uploaded, so the retry re-chunks and // re-uploads the affected data instead of silently referencing data that // never reached storage. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestBackupRetryAfterInterruptedUploadIsRestorable(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() @@ -426,10 +422,9 @@ func TestBackupRetryAfterInterruptedUploadIsRestorable(t *testing.T) { // covered by TestBackupCompletesOnlyAfterMetadataExport // (https://git.eeqj.de/sneak/vaultik/issues/177); this test exercises the // lower-level export path in isolation. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestBackupSurvivesMetadataExportInterruption(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() @@ -509,10 +504,9 @@ func TestBackupSurvivesMetadataExportInterruption(t *testing.T) { // destination. Rerunning the backup must then prune the incomplete // snapshot, produce a snapshot whose destination metadata and local index // agree, and restore. See https://git.eeqj.de/sneak/vaultik/issues/177. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestBackupCompletesOnlyAfterMetadataExport(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() @@ -685,10 +679,9 @@ func faultScannerFactory( // Scenario 5: the restore target runs out of space mid-file. Restore // must fail with an out-of-space error, and must not leave a truncated // file at the target path presenting as a complete restore. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestRestoreReportsDiskFull(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() osFS := afero.NewOsFs() tempDir := t.TempDir() diff --git a/internal/vaultik/integration_test.go b/internal/vaultik/integration_test.go index 5bb5483..ded2e7e 100644 --- a/internal/vaultik/integration_test.go +++ b/internal/vaultik/integration_test.go @@ -928,17 +928,17 @@ func setupDedupBackupEnv( } } -// runDedupSnapshot creates a "dedup" snapshot, scans dataDir into it, -// completes it, and exports its metadata, returning the snapshot ID and -// scan result. +// runDedupSnapshot creates a snapshot with the given name, scans dataDir +// into it, completes it, and exports its metadata, returning the snapshot +// ID and scan result. func runDedupSnapshot( ctx context.Context, t *testing.T, sm *snapshot.SnapshotManager, scanner *snapshot.Scanner, - hostname, dataDir, dbPath string, + hostname, name, dataDir, dbPath string, ) (string, *snapshot.ScanResult) { t.Helper() - id, err := sm.CreateSnapshotWithName(ctx, hostname, "dedup", "v", "g") + id, err := sm.CreateSnapshotWithName(ctx, hostname, name, "v", "g") require.NoError(t, err) result, err := scanner.Scan(ctx, dataDir, id) @@ -980,16 +980,15 @@ func TestDedupOnlySnapshotRestores(t *testing.T) { // First snapshot — uploads all blobs. _, r1 := runDedupSnapshot(ctx, t, sm, makeScanner(), - cfg.Hostname, dataDir, dbPath) + cfg.Hostname, "first", dataDir, dbPath) require.Positive(t, r1.BlobsCreated, "first snapshot should upload at least one blob") - // Second snapshot — same data, every chunk dedups. Sleep past the - // second-precision timestamp so the snapshot IDs differ. - time.Sleep(1100 * time.Millisecond) - + // Second snapshot — same data, every chunk dedups. Its own name gives + // it a different snapshot ID without waiting for the one-second + // timestamp in the ID to tick over. id2, r2 := runDedupSnapshot(ctx, t, sm, makeScanner(), - cfg.Hostname, dataDir, dbPath) + cfg.Hostname, "second", dataDir, dbPath) require.Equal(t, 0, r2.BlobsCreated, "second snapshot should upload zero new blobs (fully dedup'd)") diff --git a/internal/vaultik/missing_destination_test.go b/internal/vaultik/missing_destination_test.go index cc3affa..e3d3561 100644 --- a/internal/vaultik/missing_destination_test.go +++ b/internal/vaultik/missing_destination_test.go @@ -78,10 +78,9 @@ func backUpThenUnplug( // TestFirstBackupCreatesDestinationDirectory checks that a first backup // to a destination directory that does not exist yet creates it, and // that the destination can be listed afterwards. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestFirstBackupCreatesDestinationDirectory(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() ctx := context.Background() storeDir := filepath.Join(t.TempDir(), "volume", "backup") @@ -96,10 +95,9 @@ func TestFirstBackupCreatesDestinationDirectory(t *testing.T) { // TestListSnapshotsWarnsWhenDestinationMissing checks that snapshot list // warns and shows the local index alone, without reporting the local // snapshot as missing from the destination. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestListSnapshotsWarnsWhenDestinationMissing(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() ctx := context.Background() v, repos, out := backUpThenUnplug(ctx, t) @@ -116,10 +114,9 @@ func TestListSnapshotsWarnsWhenDestinationMissing(t *testing.T) { // TestRemoveSnapshotWarnsWhenDestinationMissing checks that snapshot // remove warns that the metadata could not be removed from the // destination, instead of reporting that it was. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestRemoveSnapshotWarnsWhenDestinationMissing(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() ctx := context.Background() v, repos, out := backUpThenUnplug(ctx, t) @@ -138,10 +135,9 @@ func TestRemoveSnapshotWarnsWhenDestinationMissing(t *testing.T) { // TestPruneKeepsLocalRecordsWhenDestinationMissing checks that prune // fails on a destination it cannot list and deletes no local snapshot // record. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestPruneKeepsLocalRecordsWhenDestinationMissing(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() ctx := context.Background() v, repos, _ := backUpThenUnplug(ctx, t) @@ -158,10 +154,9 @@ func TestPruneKeepsLocalRecordsWhenDestinationMissing(t *testing.T) { // TestPurgeSaysListingFailedOnceWhenDestinationMissing checks that // snapshot purge fails on a destination it cannot list, with an error // that says "listing remote snapshots" once. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestPurgeSaysListingFailedOnceWhenDestinationMissing(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() ctx := context.Background() v, _, _ := backUpThenUnplug(ctx, t) diff --git a/internal/vaultik/prune_count_test.go b/internal/vaultik/prune_count_test.go index fbc3e5d..ab9268f 100644 --- a/internal/vaultik/prune_count_test.go +++ b/internal/vaultik/prune_count_test.go @@ -14,10 +14,9 @@ import ( // the discarded-error bug: getTableCount for a table its query cannot // resolve must not silently become 0. A count that could not be read is // reported as unknown, which a reader can tell apart from an empty table. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestTableCountForReportSurfacesReadFailure(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() ctx := context.Background() diff --git a/internal/vaultik/restore_interrupt_test.go b/internal/vaultik/restore_interrupt_test.go index e8816c5..0625ccb 100644 --- a/internal/vaultik/restore_interrupt_test.go +++ b/internal/vaultik/restore_interrupt_test.go @@ -164,10 +164,9 @@ func scratchEntries(t *testing.T, dir string) []string { // restore while a blob download is in progress. The download fails only // because of the cancel, so Restore must return context.Canceled without // reporting the file that needs the blob as failed. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestRestoreSkipErrorsCancelDuringBlobDownload(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() diff --git a/internal/vaultik/restore_skip_errors_test.go b/internal/vaultik/restore_skip_errors_test.go index bb19ff4..7cbfeff 100644 --- a/internal/vaultik/restore_skip_errors_test.go +++ b/internal/vaultik/restore_skip_errors_test.go @@ -45,9 +45,10 @@ type missingBlobBackup struct { // after one blob of a two-blob snapshot was deleted. Every file stored in // that blob must be reported as failed and left absent, every other file // must be restored intact, and Restore must still return an error. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestRestoreSkipErrorsSkipsFilesOfMissingBlob(t *testing.T) { + log.Initialize(log.Config{}) + t.Parallel() + ctx := context.Background() backup := backupThenDeleteOneBlob(ctx, t) @@ -85,9 +86,10 @@ func TestRestoreSkipErrorsSkipsFilesOfMissingBlob(t *testing.T) { // TestRestoreMissingBlobAbortsWithoutSkipErrors checks that a deleted blob // still ends the restore with an error when SkipErrors is not set. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestRestoreMissingBlobAbortsWithoutSkipErrors(t *testing.T) { + log.Initialize(log.Config{}) + t.Parallel() + ctx := context.Background() backup := backupThenDeleteOneBlob(ctx, t) @@ -107,7 +109,6 @@ func backupThenDeleteOneBlob( ctx context.Context, t *testing.T, ) *missingBlobBackup { t.Helper() - log.Initialize(log.Config{}) fs := afero.NewOsFs() tempDir := t.TempDir() diff --git a/internal/vaultik/same_second_rewrite_test.go b/internal/vaultik/same_second_rewrite_test.go index 71ca958..998330b 100644 --- a/internal/vaultik/same_second_rewrite_test.go +++ b/internal/vaultik/same_second_rewrite_test.go @@ -18,10 +18,9 @@ import ( // A file rewritten with its size unchanged and a new mtime in the same // second as the mtime the index holds must still be backed up. See // https://git.eeqj.de/sneak/vaultik/issues/226. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestBackupOfSameSecondRewriteRestoresNewContent(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() fs := afero.NewOsFs() tempDir := t.TempDir() diff --git a/internal/vaultik/snapshot_summary_test.go b/internal/vaultik/snapshot_summary_test.go index a3562f3..3e180b6 100644 --- a/internal/vaultik/snapshot_summary_test.go +++ b/internal/vaultik/snapshot_summary_test.go @@ -54,8 +54,6 @@ type summaryEnv struct { func newSummaryEnv(t *testing.T) *summaryEnv { t.Helper() - log.Initialize(log.Config{}) - fs := afero.NewOsFs() tempDir := t.TempDir() srcDir := filepath.Join(tempDir, "src") @@ -193,9 +191,10 @@ func (e *summaryEnv) dataLine(total, backedUp int64) string { // A first backup stores copy.bin's chunks while backing up a.bin, so // copy.bin's chunks are deduplicated within the run. Each file and byte // is still counted once. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestSnapshotSummaryFirstRun(t *testing.T) { + log.Initialize(log.Config{}) + t.Parallel() + env := newSummaryEnv(t) summary := env.backUp(t, "first", false) @@ -219,9 +218,10 @@ func TestSnapshotSummaryFirstRun(t *testing.T) { // An incremental backup where a.bin's mtime changed but its content did // not: a.bin is backed up again and every one of its chunks is already // stored. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestSnapshotSummaryIncrementalRunWithDeduplicatedChunks(t *testing.T) { + log.Initialize(log.Config{}) + t.Parallel() + env := newSummaryEnv(t) env.backUp(t, "first", false) @@ -251,9 +251,10 @@ func TestSnapshotSummaryIncrementalRunWithDeduplicatedChunks(t *testing.T) { // Under --cron the progress reporter is off; the upload figures must // still reach the summary and the snapshots row. The snapshot has two // paths, each backed up by its own scan. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestSnapshotSummaryCronRunRecordsUploads(t *testing.T) { + log.Initialize(log.Config{}) + t.Parallel() + env := newSummaryEnv(t) summary := env.backUp(t, "split", true) diff --git a/internal/vaultik/two_path_snapshot_test.go b/internal/vaultik/two_path_snapshot_test.go index f20ae4b..06c2fed 100644 --- a/internal/vaultik/two_path_snapshot_test.go +++ b/internal/vaultik/two_path_snapshot_test.go @@ -18,10 +18,9 @@ import ( // A backup without --cron runs the progress reporter while one scanner // scans each path of the snapshot in turn. See // https://git.eeqj.de/sneak/vaultik/issues/253. -// -//nolint:paralleltest // installs the global logger via log.Initialize func TestBackupWithoutCronOfTwoPathSnapshotRestoresBothPaths(t *testing.T) { log.Initialize(log.Config{}) + t.Parallel() const snapshotName = "data" -- 2.54.0