fix(backup): bound unbounded SQLite busy-retry + stop misclassifying transient files as hard errors - #82042
Open
EvgenyMettsler wants to merge 4 commits into
Conversation
Root cause (docs/rca-chrome-debug-transient-files-backup.md): hermes backup scans then archives ~/.hermes in two phases seconds-to-minutes apart. The Hermes-managed debug Chrome profile (chrome-debug/) continuously rewrites its own Sessions/, shared_proto_db/, and BrowserMetrics state while running, so a file that existed at scan time can vanish before the archive-write phase reaches it, raising a benign FileNotFoundError that the existing per-file catch already handled -- but the finalize/summary step treated ANY non-empty errors list as a fatal-looking 'Backup incomplete', even though the produced archive was always complete and restorable. Two complementary fixes, both in hermes_cli/backup.py: 1. Exclude known-transient chrome-debug subpaths (Sessions/, shared_proto_db/, BrowserMetrics/, BrowserMetrics-spare.pma) from the backup walk outright, scoped to the top-level chrome-debug/ dir so same-named directories elsewhere under HERMES_HOME are unaffected. Eliminates the race in the common case. 2. Reclassify vanished-mid-backup skips (FileNotFoundError, and a vanished source detected post-hoc in the .db safe-copy path) into a separate transient_skipped bucket, distinct from errors. Only genuine failures (permissions, disk errors, a .db that's present but fails to copy) still flip the summary to 'Backup incomplete' and suppress the restore hint; transient skips print as a clearly-labeled harmless note instead. Also fixes a more severe variant of the same bug in _write_full_zip_backup_locked (the shared helper behind hermes update's pre-update backup and hermes claw migrate's pre-migration backup): a vanished .db file there previously raised _SQLiteSnapshotError and aborted the ENTIRE archive via the outer except, discarding every file scanned before and after it. Now a vanished file (plain or .db) is skipped via continue and the archive completes with everything else intact; a .db that's present but genuinely fails to copy still aborts+preserves the previous archive as before. Live-verified: ran hermes backup against the real ~/.hermes while the Hermes-launched debug Chrome (launched via the actual browser_connect.launch_chrome_debug code path) was active and being navigated via CDP, producing genuine Session_*/Tabs_* file churn mid-backup. Result: "Backup complete" with a valid, restore-hinted 4170-file/543MB archive (testzip()==None) in 28.9s, chrome-debug Sessions/shared_proto_db listed as excluded directories, and zero chrome-debug warnings -- vs. the original ticket's "Backup incomplete" with 6 ENOENT warnings and a suppressed restore hint on the same class of scenario. Added 9 new tests (TestChromeDebugTransientRace + 2 exclusion-scope tests) covering: exclusion scoping, vanished-file-is-warning-not- fatal in both backup paths, vanished .db is skipped not reported as a copy failure, and genuine (non-vanished) failures still correctly flip the summary/abort the archive in both paths. All 65 backup- related tests pass (46 pre-existing + 9 new + 10 curator_backup).
Root cause (docs/rca-backup-sqlite-busy-retry-unbounded.md): sqlite3.Connection.backup() retries SQLITE_BUSY/SQLITE_LOCKED with time.sleep() inside CPython's C implementation with no overall deadline, and the connection's timeout= parameter has no effect on this loop (only bounds the initial lock acquisition for ordinary statements). A source .db that stays locked -- observed in the wild against Chrome's own first_party_sets.db under chrome-debug/, and live-reproduced against the user's actual, currently-locked file with zero test interaction (61.4s real stall) -- could previously stall hermes backup for as long as the lock was held. Fix: bound the retry via backup()'s progress= callback, which fires on every step including busy ones and can raise to abort cleanly (CPython already treats this as a normal abort, calling sqlite3_backup_finish() internally). The deadline check is gated on the BUSY/LOCKED status code, not raw elapsed time, so a large but uncontended copy is never wrongly aborted just for taking a while. Both connections in the bounded path use timeout=0 -- load-bearing, not cosmetic: the connect() default (5.0) lets SQLite's own internal busy-handler silently absorb the wait inside a single backup_step() call before the progress callback ever runs, which was measured to make an earlier prototype's deadline check unreliable (coarse ~5-8s granularity regardless of the configured deadline). Default deadline 30s, overridable via HERMES_BACKUP_SQLITE_BUSY_DEADLINE_SECONDS; a non-positive value disables bounding entirely (restores the exact pre-fix behavior). The raised timeout is a plain Exception subclass caught by _safe_copy_db's existing except Exception clause, so both call sites (interactive and automatic backup paths) already handle it via the vanished-vs-genuine-failure distinction from the chrome-debug ENOENT fix -- a file still present but past its busy deadline is a genuine errors entry, not a benign transient skip. Added TestSafeCopyDbBusyBounding (6 tests): busy source is bounded, short busy window still succeeds normally, connection timeout= documented as insufficient (regression guard against re-introducing that approach), large non-busy copy unaffected by an absurdly tight deadline, negative deadline disables bounding. All 146 tests across the backup-adjacent surface pass (test_backup.py, test_backup_stability.py, test_curator_backup.py, test_execution_ledger.py, test_state_db_guard.py, test_sizefmt.py, and the update_cmd test files that import backup helpers) -- no regressions. ruff clean. Live end-to-end verification: at the time of this fix the user's actual chrome-debug/first_party_sets.db was independently found SQLITE_BUSY with zero interaction from this session. Before the fix, running the real _safe_copy_db() against it blocked 61.4s. After the fix, with a 10s deadline override, the same live locked file was aborted cleanly at 10.1s as designed.
…timeout _safe_copy_db's SQLITE_BUSY/LOCKED retry was bounded by commit 30fdaab42 (default 30s deadline) to stop indefinite hangs against a live Chrome profile's own small housekeeping databases (first_party_sets.db, declarative_performance_observer.db under chrome-debug/). That fix correctly stopped the hang, but the resulting clean abort was still classified identically to genuine corruption/permission failures -- so 'hermes backup' summary flipped to 'Backup incomplete' again, just via different files than the original ENOENT-based bug report (t_6f9583fe), which t_c753bb8d/d47696346 already fixed for the vanished-file case. Add _safe_copy_db_ex(), a superset of _safe_copy_db() that also reports whether a failure was specifically a busy-timeout abort (vs. any other cause). Both backup call sites (the primary 'hermes backup' path and the automatic pre-update/pre-migration _write_full_zip_backup_locked path) now route a busy-timeout into the same harmless transient/skipped bucket already used for vanished-mid-backup files, instead of the hard errors list -- matching the existing convention and keeping 'Backup complete' + the restore hint for an otherwise fully valid archive. Live-verified end-to-end against the real ~/.hermes with the actual Hermes-launched chrome-debug Chrome running: pre-fix, 'hermes backup' printed 'Backup incomplete' due to first_party_sets.db / declarative_performance_observer.db SQLITE_BUSY aborts; post-fix, two consecutive runs both print 'Backup complete', exit 0, restore hint present, both busy files correctly listed under the harmless Note instead of Warnings, and zipfile.testzip() == None on the resulting archive. 4 new regression tests (_safe_copy_db_ex busy-timeout reporting, busy-timeout not misclassifying genuine corruption, and end-to-end transient-not-incomplete behavior for both backup paths); fixed 2 existing tests that monkeypatched the now-superseded _safe_copy_db at these call sites. 58/58 tests pass in test_backup.py; 92/92 across the wider backup-adjacent suite. ruff clean.
alt-glitch
added
type/bug
Collaborator
13 tasks
9 tasks
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What does this PR do?
Fixes two related bugs in
hermes backupthat could either hang indefinitely or wrongly report a clean backup as "Backup incomplete":_safe_copy_db()copies each.dbfile viasqlite3.Connection.backup(). That call has no bounded retry: when the source isSQLITE_BUSY/SQLITE_LOCKED(another process holds a write transaction), it retries viasqlite3_sleep()indefinitely until the lock clears — the connection'stimeout=parameter only bounds acquiring the initial connection, not this internal retry loop. Reproduced live against a real, independently-lockedchrome-debug/first_party_sets.db(a small SQLite file Chrome itself uses internally): unpatched, the copy blocked for 61.4 seconds.Sessions/,shared_proto_db/,BrowserMetrics-spare.pma) can vanish mid-backup as Chrome's own housekeeping runs. A scan-then-archive race treated any such vanish as a fatal error, flipping the whole backup summary to "Backup incomplete" even though the resulting archive was complete and restorable.Related Issue
No existing issue — found as a side-effect while live-verifying a separate backup fix, documented in the two RCA docs included in this PR.
Type of Change
Changes Made
hermes_cli/backup.py:_safe_copy_db()now bounds the SQLite busy/locked retry viaconn.backup(progress=<callback>). The callback fires after everysqlite3_backup_step()call (including busy/locked ones) and raises past a deadline (default 30s, overridable viaHERMES_BACKUP_SQLITE_BUSY_DEADLINE_SECONDS, non-positive disables bounding). The deadline check is gated on the status code (SQLITE_BUSY/SQLITE_LOCKED), not raw elapsed time, so a large-but-healthy copy is never wrongly aborted mid-flight.timeout=0—sqlite3.connect()'s defaulttimeout=5.0installs SQLite's own internal busy-handler that silently retries inside a singlebackup_step()call for up to 5s before theprogress=callback ever runs, which coarsens the deadline to ~5-8s regardless of the configured value. This is documented at length in code comments since it's easy to reintroduce by "simplifying."_safe_copy_db_ex()reports why a copy failed (busy-timeout abort vs. anything else) so callers can route a busy-timeout into the same harmless "transient/skipped" bucket already used for vanished-mid-backup files, instead of the harderrorslist. Bothhermes backupcall sites (the CLI path and the automatic_write_full_zip_backup_lockedpath) updated to use it.Sessions/,shared_proto_db/,BrowserMetrics-spare.pma) and reclassifies a benign vanished-file skip separately from a genuine failure.docs/rca-backup-sqlite-busy-retry-unbounded.md/docs/fix-backup-sqlite-busy-retry-unbounded.md— root cause (CPython C-source level) and fix write-up for the busy-retry bug.docs/rca-chrome-debug-transient-files-backup.md/docs/fix-chrome-debug-transient-files-backup.md— root cause and fix write-up for the transient-file misclassification.tests/hermes_cli/test_backup.py— 590 new lines: busy-bounded abort, short-lock-still-succeeds,timeout=insufficiency documented as a regression guard, large-non-busy-copy unaffected by a tight deadline, negative-deadline escape hatch, busy-timeout correctly reported as transient (not a hard error) at both call sites, transient chrome-debug ENOENT races tolerated.How to Test
pytest tests/hermes_cli/test_backup.py -q— 58 tests, all pass.BEGIN EXCLUSIVElock on a throwaway SQLite file in one process, run_safe_copy_db_ex()against it from another withHERMES_BACKUP_SQLITE_BUSY_DEADLINE_SECONDS=2— returns cleanly in ~2.1s instead of hanging.hermes backupagainst a real~/.hermeswith the Hermes-managed debug Chrome actively running — prints "Backup complete", exit code 0, restore hint present,zipfile.testzip() == Noneon the resulting archive.Checklist
Code
fix(scope):,feat(scope):, etc.)pytest tests/ -qand all tests passDocumentation & Housekeeping
docs/, docstrings) — or N/Acli-config.yaml.exampleif I added/changed config keys — or N/A (no new config keys; the deadline is env-var-overridable only)CONTRIBUTING.mdorAGENTS.mdif I changed architecture or workflows — or N/Asqlite3/stdlib, no platform-specific paths)Screenshots / Logs
Live pre-fix repro against a real locked file:
Post-fix, same locked file, 10s deadline override: