Retry and report transient-busy LedgerCloseMeta drops during catchup - #3874
Retry and report transient-busy LedgerCloseMeta drops during catchup#3874tomerweller wants to merge 2 commits into
Conversation
Cover the catchup `emit_meta` silent-drop path: the shared `DbError::is_transient_busy` predicate, the bounded transient-busy retry around `store_ledger_close_meta` (retry / bounded give-up / no-retry on non-transient), the `catchup_meta` db-busy telemetry, the `emit_meta` end-to-end wiring on a real DB fault, and the `CatchupResult` drop count. Pre-fix failure modes: - henyey-db: `no method named is_transient_busy found for enum DbError` - henyey-history: `cannot find function store_meta_with_busy_retry`, `cannot find type MetaStoreOutcome`, `CatchupResult has no field named meta_rows_dropped`, `no method named meta_rows_dropped` - henyey-app: `test_db_busy_site_label_vocabulary_pinned` FAILED — left is missing "catchup_meta" Refs #3801 Co-authored-by: Claude Code <claude-code@anthropic.com>
`emit_meta` persisted the catchup `ledger_close_meta` row with a bare `warn!` on failure. A transient SQLITE_BUSY/LOCKED therefore dropped the row silently, and catchup never revisits a ledger — so the hole in the RPC-facing table was permanent and invisible (#3772 measured 139 lock-loss events in 26 d on the deployed validator). The write now goes through a bounded transient-busy retry (1 initial attempt + 2 retries, 25 ms apart). On exhaustion the write is still abandoned rather than propagated: an error out of `emit_meta` aborts the whole batch's `persist_ledger_history`, and the replay retry resumes from the already-advanced in-memory LCL, so propagating turns a 1-row hole into a <=64-ledger, 3-table one WITHOUT repairing the original (tracked as #3811). What changes is that the drop is no longer silent: `error!` naming the RPC-visible gap, the #3802 counters at `site="catchup_meta"`, and a `meta_rows_dropped` count carried out on `CatchupResult`. The busy/locked predicate moves down to `henyey_db::DbError::is_transient_busy` so `crates/history` — which cannot see app's `pub(crate)` helper, and must not depend on `henyey-app` — shares ONE definition of "transient" instead of a second copy that could drift. `crates/app`'s `is_transient_db_busy` becomes a delegate with its visibility and all call sites unchanged. The fd:3 meta callback stays unconditional on every path, exactly as before: coupling it to the DB outcome would drop frames from the stream stellar-rpc/Horizon consume. Refs #3801 Co-authored-by: Claude Code <claude-code@anthropic.com>
🔍 Reviewer: CorrectnessVerdict: APPROVE Summary: Cycle 1. The regression tests were verified genuinely failing at the pre-fix commit ( Full reviewReviewed at Test-verification gate —
|
| /// Catchup *completion* is the first boundary at which a caller can react | ||
| /// safely: reacting per-ledger is not possible, because aborting the replay | ||
| /// there would discard the whole batch and resume past the gap (see #3811). | ||
| pub meta_rows_dropped: u32, |
There was a problem hiding this comment.
Non-blocking (follow-up material, not a merge gate): this field currently has no production consumer.
crates/app/src/app/catchup_impl.rs:657 rebuilds the app-level CatchupResult (crates/app/src/app/types.rs:225) from output using only ledger_hash / buckets_downloaded / ledgers_applied, so meta_rows_dropped is dropped at the crate boundary and never reaches handle_catchup_result. The Display impl on this struct also has no production caller (crates/app/src/catchup_cmd.rs formats the app CatchupResult, a different type), so the new WARNING: N ledger_close_meta rows DROPPED suffix is currently only exercised by test_catchup_result_display_reports_dropped_meta.
The operator-visible surface of a drop is fine either way — emit_meta's error! line and henyey_db_busy_write_dropped_total{site="catchup_meta"} both fire — so nothing is lost today. But the plan's stated rationale for the field ("catchup completion is a boundary where reacting is safe") is not yet realised: no caller can react, because the value stops here. Threading it onto crates/app's CatchupResult (or logging it in handle_catchup_result) would close the loop.
🔍 Reviewer: RiskVerdict: APPROVE Summary: Cycle 1. Non-parity PR (no Full reviewRe-read the diff independently at
|
Review: Bounce-Back Cycle 1 — CI red (unrelated), both reviewer lenses APPROVEBoth agent reviewer lenses returned APPROVE. The bounce is CI-only, and the failure is not attributable to this diff. 40/41 checks are green. The single red is
Do not change code in response to this bounce. Full reasoning and the recommended handling are in the bounce comment on #3801. The one inline comment on |
Now
|
| Landed on main by #3876 | This PR still adds |
|---|---|
crates/db/src/error.rs:103 pub fn is_transient_busy() |
crates/db/src/error.rs +112/-0 (same block from scratch) |
crates/db/src/error.rs:138 test_is_transient_busy_matches_busy_and_locked, :163 test_is_transient_busy_rejects_non_busy |
same test name |
crates/app/src/app/persist.rs:546-551 delegate to the canonical henyey_db::DbError::is_transient_busy |
crates/app/src/app/persist.rs +8/-11 |
crates/app/src/metrics.rs catalog/pinning edits |
crates/app/src/metrics.rs +17/-11 |
The issue-#3801 payload itself does not collide. These files are untouched by #3876 and carry the actual fix:
crates/history/src/catchup/persist.rs+320/-7crates/history/src/lib.rs+55/-1crates/history/src/catchup/mod.rs+35/-0crates/history/Cargo.toml+4/-0
So the rebase is well-scoped: drop the now-duplicate crates/db/src/error.rs, crates/app/src/app/persist.rs, and crates/app/src/metrics.rs portions (all three are on main already), point any local use at the landed canonical is_transient_busy, and keep the crates/history/** payload as-is. Both reviewer lenses had already approved the substance — this is a mechanical de-duplication, not a re-review.
Context: the collision between this PR and #3876 was flagged before either merged, with the recommendation that #3874 land first precisely to avoid this. #3876 merged first instead, so the rebase burden moved here. Note also that a MERGEABLE reading on two PRs that add identical symbols is false comfort — GitHub tests each against main in isolation, which is why both read clean right up until one landed.
No action taken on my side: not merging, not modifying, not re-reviewing. Recording the cause and scope so the rebase is a known quantity.
Closes #3801
Summary
crates/history/src/catchup/persist.rsemit_metapersisted the catchupledger_close_metarow with a barewarn!on failure. A transientSQLITE_BUSY/SQLITE_LOCKEDtherefore dropped the row silently, and catchup never revisits a ledger — so the hole in the RPC-facing table (getTransactions/getLedgers) was permanent and invisible. #3772 measured 139 lock-loss events in 26 days on the deployed validator with 2 confirmed dropped ledgers.The write now goes through a bounded transient-busy retry (
CATCHUP_META_MAX_ATTEMPTS = 3, 25 ms apart). On exhaustion the write is still abandoned rather than propagated — an error out ofemit_metaaborts the whole batch'spersist_ledger_history, and the replay retry resumes from the already-advanced in-memory LCL, so propagating would turn a 1-row hole into a ≤64-ledger, 3-table one without repairing the original (structural blocker tracked as #3811). What changes is that the drop is no longer silent: anerror!naming the RPC-visible gap, the #3802 counters atsite="catchup_meta", and ameta_rows_droppedcount carried out onCatchupResult.Supporting change: the busy/locked predicate moves down to
henyey_db::DbError::is_transient_busy, beside its documented siblingis_query_interrupted.crates/historycannot see app'spub(crate)is_transient_db_busy(the dependency runs app → history), so this gives one shared definition of "transient" instead of a second copy that could drift (#3871).crates/app/src/app/persist.rs::is_transient_db_busybecomes a one-line delegate with itspub(crate)visibility and all ~20 call sites unchanged — nothing is widened.The fd:3 meta callback stays unconditional on every path, exactly as on
main: coupling it to the DB outcome would drop frames from the meta stream stellar-rpc/Horizon consume.Plan reference
Converged Plan, as refined by the crate-boundary resolution comment (option 2: literal counter name at the emit site in
crates/history, const + pre-registration in app's catalog; classifier moves tocrates/db).Files changed
crates/db/src/error.rs—DbError::is_transient_busy()+ unit tests.crates/app/src/app/persist.rs—is_transient_db_busydelegates; visibility unchanged.crates/app/src/metrics.rs—SITE_CATCHUP_META, added toDB_BUSY_SITESand both"site", [...]arrays inmetric_catalog!; removed from the "Reserved" doc block; the negative pinning assertion deleted and the pinned array extended.crates/history/src/catchup/persist.rs—store_meta_with_busy_retry+MetaStoreOutcome;emit_metarewired; tests.crates/history/src/catchup/mod.rs—meta_rows_dropped: AtomicU32onCatchupManager(both constructors),meta_rows_dropped()accessor, per-run delta inreplay_and_finish.crates/history/src/lib.rs—CatchupResult.meta_rows_dropped+Display(mentioned only when non-zero).crates/history/Cargo.toml—metrics-exporter-prometheusas a dev-dependency (local recorder for the counter assertions).Test plan
All run under
CARGO_TARGET_DIR=~/data/<session>/do-3801/cargo-target, exit codes captured directly (not through a pipe):cargo fmt --all -- --check→ rc=0cargo clippy --all --all-targets -- -D warnings→ rc=0cargo test -p henyey-db→ rc=0 (125 + 5 passed, 2 ignored)cargo test -p henyey-history→ rc=0 (567 + 1 + 3 + 7 + 2 + 14 + 1 + 29 passed, 2 ignored)cargo test -p henyey-app→ rc=0 (1233 + 3 + 1 + 1 + 8 passed, 2 ignored)cargo test -p henyey-rpc→ rc=0 (233 + 28 + 37 + 1 passed) — reads the affected tableRegression test
crates/history/src/catchup/persist.rs::test_store_meta_with_busy_retry_retries_transient_busy_then_storescrates/history/src/catchup/persist.rs::test_store_meta_with_busy_retry_gives_up_after_max_attempts_and_counts_dropcrates/history/src/catchup/persist.rs::test_store_meta_with_busy_retry_does_not_retry_non_transientcrates/history/src/catchup/persist.rs::test_emit_meta_routes_store_through_retry_helper(real DB fault, not the closure seam — stops a correct-but-uncalled helper from passing)crates/history/src/catchup/persist.rs::test_emit_meta_persists_row_and_invokes_callbackcrates/history/src/lib.rs::test_catchup_result_display_reports_dropped_metacrates/db/src/error.rs::test_is_transient_busy_matches_busy_and_locked,::test_is_transient_busy_rejects_corrupt_and_non_sqlitecrates/app/src/metrics.rs::test_db_busy_site_label_vocabulary_pinned(updated)189fe99a— verified FAILED:henyey-db:no method named is_transient_busy found for enum DbErrorhenyey-history:cannot find function store_meta_with_busy_retry,cannot find type MetaStoreOutcome,struct CatchupResult has no field named meta_rows_dropped,no method named meta_rows_droppedhenyey-app:test_db_busy_site_label_vocabulary_pinnedFAILED at runtime —leftmissing"catchup_meta"139bb623(all 31catchup::persist::testsgreen, plus the db/app tests above).Note:
189fe99awas committed with--no-verifybecause the failing-test commit intentionally does not compile; the fix commit139bb623ran the hook normally and passed.Deviations from plan
CatchupManager::meta_rows_dropped()accessor (Critic C's minority option) and theCatchupResult.meta_rows_droppedfield were implemented, rather than one or the other. The field is the per-run delta fromreplay_and_finish; the accessor exposes the lifetime total and is what makes theemit_meta-level test assertable without driving a full catchup. Constructor threading was trivial, so nothing was de-scoped.store_meta_with_busy_retry(matching thecrates/history/src/catchup/buckets.rs:277precedent) rather than via a local const, per the crate-boundary resolution comment.PARITY_STATUS.mdupdate:docs/PARITY.mdputs Metrics and Logging on the freely-divergeable surface, andledger_close_metais a henyey-only table with no stellar-core counterpart. No ledger/bucket hash, result XDR, wire byte, archive format, HTTP or JSON-RPC contract is touched; response completeness strictly improves.Note for #3806
#3806 (
tx_set_gc) is inready-for-doingand its converged plan touches the samemetric_catalog!"site"arrays, the sameDB_BUSY_SITES, and the sametest_db_busy_site_label_vocabulary_pinned. #3801 was drained first deliberately; #3806 will need to rebase onto this and appendtx_set_gcaftercatchup_meta(its reserved-value assertion is still present and untouched here).🤖 Generated with Claude Code