diff --git a/.changeset/backup-copy-names-deadline.md b/.changeset/backup-copy-names-deadline.md new file mode 100644 index 000000000..cd70272a5 --- /dev/null +++ b/.changeset/backup-copy-names-deadline.md @@ -0,0 +1,5 @@ +--- +"ftw": patch +--- + +A backup stopped by its time limit or by a cancel while it copies a table now reports the deadline or the cancel. Before, the reason could end in "sql: statement is closed" instead. diff --git a/go/internal/state/backup_failure_test.go b/go/internal/state/backup_failure_test.go index 3dd226367..6ade363ae 100644 --- a/go/internal/state/backup_failure_test.go +++ b/go/internal/state/backup_failure_test.go @@ -3,6 +3,7 @@ package state import ( "bytes" "context" + "database/sql" "errors" "log/slog" "os" @@ -42,6 +43,42 @@ func TestLiveBackupPastItsLimitNamesTheLimitAndTable(t *testing.T) { } } +// A deadline that lands inside a batch rolls back the copy's transaction and +// closes its statement; the next row then fails with "statement is closed". +// The reason must still carry the context's error (CI run 39759536215). +func TestBackupCopyCancelledInsideABatchKeepsTheContextError(t *testing.T) { + dest, err := sql.Open("sqlite", filepath.Join(t.TempDir(), "dest.db")) + if err != nil { + t.Fatal(err) + } + defer dest.Close() + if _, err := dest.Exec(`CREATE TABLE t(a INTEGER)`); err != nil { + t.Fatal(err) + } + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + scan := func(_ context.Context, _ historyQueryer, _ string, visit func([]any) error) (int64, error) { + if err := visit([]any{int64(1)}); err != nil { + return 0, err + } + cancel() + // database/sql rolls the transaction back on its own goroutine and + // then returns the connection. + deadline := time.Now().Add(5 * time.Second) + for dest.Stats().InUse > 0 { + if time.Now().After(deadline) { + return 0, errors.New("the cancelled transaction kept its connection") + } + time.Sleep(time.Millisecond) + } + return 2, visit([]any{int64(2)}) + } + err = copyVerifiedTable(ctx, nil, dest, "t", scan, nil) + if !errors.Is(err, context.Canceled) || !strings.Contains(err.Error(), "copy t") { + t.Fatalf("copy cancelled inside a batch = %v", err) + } +} + func TestCanceledBackupIsNotBlamedOnTheLimit(t *testing.T) { s := freshStore(t) ctx, cancel := context.WithCancel(context.Background()) diff --git a/go/internal/state/history_rollback_test.go b/go/internal/state/history_rollback_test.go index c025f8140..06bfc007c 100644 --- a/go/internal/state/history_rollback_test.go +++ b/go/internal/state/history_rollback_test.go @@ -199,7 +199,7 @@ func TestHistoryMaintenanceWaitsForCancelledRollback(t *testing.T) { if err := s.history.Close(); err != nil { t.Fatal(err) } - d := &slowHistoryRollbackDriver{started: make(chan struct{}), release: make(chan struct{})} + d := &slowHistoryRollbackDriver{blocked: make(chan struct{}), started: make(chan struct{}), release: make(chan struct{})} name := fmt.Sprintf("maintenance-rollback-%s-%d", kind, time.Now().UnixNano()) sql.Register(name, d) var err error @@ -223,11 +223,22 @@ func TestHistoryMaintenanceWaitsForCancelledRollback(t *testing.T) { return s.ensureSeriesHours(ctx) } } - ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond) + ctx, cancel := context.WithCancel(context.Background()) defer cancel() d.armed.Store(true) done := make(chan error, 1) go func() { done <- run(ctx) }() + // Cancel once the maintenance write is under way, so the rollback + // held below is that write's. A deadline could land earlier, in a + // read that holds no writer mutex yet. + select { + case <-d.blocked: + case err := <-done: + t.Fatalf("maintenance ended before its write: %v", err) + case <-time.After(5 * time.Second): + t.Fatal("maintenance did not reach its write") + } + cancel() select { case <-d.started: case err := <-done: @@ -250,7 +261,9 @@ func TestHistoryMaintenanceWaitsForCancelledRollback(t *testing.T) { if lockErr == nil { t.Fatal("maintenance released the writer mutex before SQLite rollback finished") } - if !errors.Is(err, context.DeadlineExceeded) { + // The archive write also has its own 1 s limit, which a stalled + // test goroutine can let expire before it cancels. + if !errors.Is(err, context.Canceled) && !errors.Is(err, context.DeadlineExceeded) { t.Fatalf("cancelled maintenance: %v", err) } if err := run(context.Background()); err != nil { diff --git a/go/internal/state/history_sqlite.go b/go/internal/state/history_sqlite.go index 23375702c..1a798e3f8 100644 --- a/go/internal/state/history_sqlite.go +++ b/go/internal/state/history_sqlite.go @@ -266,13 +266,13 @@ func copyVerifiedTable(ctx context.Context, source historyQueryer, dest *sql.DB, return nil }) if err != nil { - return fmt.Errorf("copy %s: %w", table, err) + return fmt.Errorf("copy %s: %w", table, withContextErr(ctx, err)) } if tx != nil { stmt.Close() stmt = nil if err := tx.Commit(); err != nil { - return err + return fmt.Errorf("copy %s: %w", table, withContextErr(ctx, err)) } tx = nil } @@ -294,6 +294,17 @@ func copyVerifiedTable(ctx context.Context, source historyQueryer, dest *sql.DB, return nil } +// withContextErr puts the context's error in front of err once the context +// has ended. database/sql rolls back a cancelled transaction and closes its +// statements, so the copy can fail with "statement is closed" or "transaction +// has already been committed or rolled back", which hides the deadline. +func withContextErr(ctx context.Context, err error) error { + if ctxErr := ctx.Err(); ctxErr != nil && !errors.Is(err, ctxErr) { + return fmt.Errorf("%w: %w", ctxErr, err) + } + return err +} + func appendHistoryRows(conn *sql.Conn, points []HistoryPoint) error { stmt, err := conn.PrepareContext(context.Background(), `INSERT OR REPLACE INTO history_hot VALUES (?,?,?,?,?,?,?)`) if err != nil {