Repository navigation
fix(backup): a failed full backup says why - #1670
Conversation
The home box's backup on 16 October 2026 stopped at the two-hour limit for a live copy and logged nothing. Its raw copy had fallen back to the SD card because a backup cut short on 13 October left 1.37 GB in /dev/shm. Core now logs when a backup starts, ends and fails, with the phase, table and rows it reached. A backup stopped by the limit names it. GET /api/backups keeps the failed run's table and rows, and a new run clears the old record. ftw backup prints the last failure before it starts. A raw copy that does not fit in /dev/shm logs a warning with the space earlier backups' scratch files still take there. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Codex Review SummaryThis comment shows the latest Codex review activity on this pull request.
ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings. |
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 6e2546bccd
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| s.deps.State.ReportBackupProgress(state.BackupProgress{Phase: "failed", Error: err.Error()}) | ||
| last := s.deps.State.BackupProgress() | ||
| slog.Error("full backup failed", "err", err, "phase", last.Phase, "table", last.Table, "rows_done", last.RowsDone, "elapsed", elapsed) | ||
| s.deps.State.ReportBackupProgress(state.BackupProgress{Phase: "failed", Table: last.Table, RowsDone: last.RowsDone, Error: err.Error()}) |
There was a problem hiding this comment.
When Core restarts or updates after a backup failure but before the next backup begins, this call stores the failure only in Store.backupStatus, an in-memory field that is empty in the new process. Consequently, GET /api/backups loses the reason, table, and row count, and the new ftw backup message cannot show the last failure—the exact update-after-failure scenario this change is intended to diagnose. Persist and reload the last outcome, clearing it when the next backup starts.
AGENTS.md reference: AGENTS.md:L22-L25
Useful? React with 👍 / 👎.
|
The outstanding restart finding still applies to current head Keep this PR open until the last failure is persisted and reloaded. Add a close/reopen regression that checks the error/table/row count in the API and CLI before another backup starts, then verifies that beginning a new attempt clears the old failure. The existing same-process tests do not establish restart persistence. |
1 participant
Problem
On 16 October 2026 a full backup on the home box (homelab-rpi, Raspberry Pi 4, Core v0.144.1-beta.1) ran from 12:05 until about 14:05 and then failed. The journal has no line about it, and the CLI had already been stopped. Core kept the reason only in memory, and the update to v0.145.0-beta.1 at 15:37 wiped it.
What happened
Read-only evidence from the box (journal, file times,
df):/dev/shm.systemctlstopped Core at 10:30:29 while a backup was copying. The process exited at 10:30:34, so the deferred cleanup never ran./dev/shm/ftw-backup-4218622654.raw(1,372,872,704 bytes) and its-journalstill have that mtime. Nothing removes them before a reboot.backupScratchFileneeds the source size plus 64 MiB in/dev/shm. With today's files (state.db 283 MB, history.db 1.30 GB, WAL) that is about 1.67 GB./dev/shmholds 1.99 GB, but with the leftover file only 616 MB is free, so the raw copy fell back to<backups>/.ftw-backup-stage-*/database.gz.raw.tmpand logged nothing. On the SD card, every 256 KiB commit fsyncs the same card that holdshistory.db. That explains the 1,600–2,400 rows/s. It also explains why the history writer (write_bucket6.8–11.7 s,read_bucket5–6 s) and forecast calibration (3 s budget) lost their deadlines from 12:07 on. The comment abovebackupScratchFilealready describes this effect on the same box.liveBackupTimeoutis 2 h for the state, history and gzip steps. The backup directory's mtime is 14:05:44.205, whenCreateremoved its stage directory, two hours after the 12:05 start. The writer-lock timeout at 14:05:49 most likely comes from history maintenance resuming and the stage file being removed from the card. The error wasbackup history: copy ts_buckets: context deadline exceeded. The handler put it inprogress.errorand logged nothing.The 10 October backups (2 h 40 min in all) predate the leftover file, so their raw copy most likely fit in
/dev/shm.TestLiveBackupPastItsLimitNamesTheLimitAndTablereproduces step 3 with a one-second limit and slow batches. Without this change its reason readsbackup history: copy history_hot: context deadline exceeded, the same bare form as on the box.Change
full backup started,full backup created(id, size, elapsed) andfull backup failed(err, phase, table, rows_done, elapsed).live backup reached its time limit of 2h0m0s: …. A caller that leaves still gets plaincontext canceled.ftw backupprintsLast try: failed: <reason>before it starts when Core still holds a failure./dev/shm, Core warns that it is copying on the data disk, withneed_bytes,free_bytesandbackup_scratch_in_shm_bytes. On 16 October that line would have pointed straight at the leftover file.Why the speed stays as it is
The hours on 16 October came from the SD-card fallback, and the leftover file caused that. Removing the file and preventing new ones restores the path that worked on 10 October. That cleanup is its own change.
I found no speed-up I could show to be safe. Larger batches make each SD-card fsync bigger, and the comment above
backupScratchFilerecords a goal save over 2 s even at 16 KiB batches. A page copy (SQLite's online backup API) changes how much IO hits the card per second. Whether history writes and forecast reads keep their deadlines meanwhile only shows on a Pi with an SD card, and the home box is read-only for this work. A laptop SSD number would not answer that question.One risk remains: the
/dev/shmpath needs about 1.67 GB today and has 1.99 GB, andhistory.dbgrows. Once it no longer fits, every live backup on this box takes the SD-card path and will likely hit the limit again.Overlap
#1615 also edits
api_backups.go. The hunks differ, but both add an import after"fmt", so whichever lands second needs a one-line merge.Tests
go test ./internal/state/ -run 'TestLiveBackupPastItsLimit|TestCanceledBackupIsNotBlamed|TestBackupScratchOnDisk'go test ./internal/api/ -run TestFailedBackupLogsAndReportsItsReason. Without the reset, its early-failure check fails withTable:ts_buckets RowsDone:4700000.go test ./internal/ftwcli/ -run TestBackupNamesTheLastFailureAndItsOwnmake verify: vet, test and build clean on macOS arm64. The/dev/shmwarning test pointsbackupShmDirat a temporary directory, so it runs without a tmpfs.No backup, update or write ran on the home box.
🤖 Generated with Claude Code