diff --git a/BUGS.md b/BUGS.md index 119ebbf..1e751d1 100644 --- a/BUGS.md +++ b/BUGS.md @@ -1,21 +1,23 @@ # Known bugs A second full-codebase audit on 2026-07-27 found **25 further issues** (4 critical, 6 high, -7 medium, 8 low), listed below as B-25 … B-49. B-25 is fixed as of 2026-07-27; the other 24 -are open. The 139-test suite was green at the time of the audit, so none of these were caught -by existing coverage — every fix lands with a regression test (B-25's four tests brought the -suite to 143). +7 medium, 8 low), listed below as B-25 … B-49. B-25 and B-26 are fixed as of 2026-07-27; the +other 23 are open. The 139-test suite was green at the time of the audit, so none of these +were caught by existing coverage — every fix lands with a regression test (B-25 and B-26 +together brought the suite from 139 to 148). -The recurring pattern across B-26, B-27, B-29 and B-36 is worth stating once: the code is -rigorous about the failure modes that have actually been hit, and silent about the ones that -have not. Outgoing transactions reconcile; deposits do not. Broadcast failures are -audit-logged; *pre*-broadcast failures (no client, insufficient pool funds) are not. +The recurring pattern across B-27, B-29 and B-36 is worth stating once: the code is rigorous +about the failure modes that have actually been hit, and silent about the ones that have not. +Outgoing transactions reconcile; deposits do not. -**Highest remaining priority: make `paying_out` fully recoverable, not just idempotent.** -B-25 made a payout retry *safe* (persisted before broadcast, guarded against double-spend); -B-26 is what would make a retry actually *happen* automatically. Together with the -already-known "scheduler doesn't resume" gap, that's every way the lottery currently stops -and cannot restart on its own. +**`paying_out` is now fully recoverable, not just idempotent.** B-25 made a payout retry +*safe* (persisted before broadcast, guarded against double-spend); B-26 made it *automatic* +(the scheduler retries a stuck `paying_out` round on its own, throttled, and every failure — +including ones that used to fail silently — is now audit-logged with a reason). Together +these close every way a payout specifically could wedge the lottery forever. What's still open +in the same family is narrower: the "drawing" phase (waiting on a block) has no equivalent +resume-after-restart or stall visibility — see B-36 and the "scheduler doesn't resume" entry +in CLAUDE.md's Known gaps, which this doesn't touch. For limitations that are accepted by design rather than bugs (single-shared-token admin auth, single-process assumptions, no user-facing history, etc.), see "Known gaps / TODO" in @@ -25,27 +27,6 @@ single-process assumptions, no user-facing history, etc.), see "Known gaps / TOD ## Critical -### B-26 — A transient failure at payout time wedges the lottery permanently - -`rounds/scheduler.py:166-169`: if `listener.client is None` when `_trigger_payout` starts, it -returns. `_trigger_payout` is called exactly once, from `_close_and_draw`, and `_tick` -ignores any round not in `open`/`closing` (`:58`). The round stays in `paying_out`, no new -round can open, and — unlike the `except Exception` branch — nothing is written to -`audit_log`, so `/admin` shows a stalled state with no explanation. - -The payout runs immediately after a ~2-minute wait on a block, so an Electrum drop in that -window is entirely plausible. Same shape at `:215-217`: `InsufficientFundsError` returns -without calling `_log_payout_failure`. - -CLAUDE.md lists "payout retry" as an accepted gap, but treats it as an operational -inconvenience; in practice it is a single point of failure that stops the whole platform. - -**Proposed fix.** (a) Call `_log_payout_failure` on *every* early return, with a reason in the -payload, so the operator sees it. (b) Make `_tick` handle `paying_out`: if the round has no -non-terminal payout `PendingTransaction`, re-run `_trigger_payout`. That turns every early -return into a retry rather than a dead end, and — combined with B-25's idempotency guard — -also covers the process-restart case. - ### B-27 — Every RBF bump resets the reconciler's abandon clock, so it never fires `tx/broadcast.py:122` sets `pending.broadcast_at = now` on each bump, but @@ -392,13 +373,54 @@ not just this round's — so a stale payout from an earlier round that the recon abandoned yet can't be double-spent by a fresh attempt. `should_bump`/reconciler retry timing around a fee-bumped payout is unaffected by this fix (see B-27, still open). -This makes a payout retry *safe*; it does not yet make one *automatic* — that is B-26, still -open. Regression tests: `tests/unit/test_scheduler.py` +This made a payout retry *safe*; B-26 (below) is what makes one *automatic*. Regression +tests: `tests/unit/test_scheduler.py` (`test_trigger_payout_persists_before_broadcasting`, `test_trigger_payout_broadcast_failure_leaves_a_recoverable_row`, `test_trigger_payout_skips_when_already_in_flight`, `test_reserved_payout_outpoints_excludes_utxos_claimed_by_a_stale_payout`). +### B-26 — A transient failure at payout time wedges the lottery permanently + +`rounds/scheduler.py`: if `listener.client is None` when `_trigger_payout` starts, it returned +without recording anything. `_trigger_payout` was called exactly once, from `_close_and_draw`, +and `_tick` ignored any round not in `open`/`closing`. The round stayed in `paying_out`, no new +round could open, and — unlike the generic `except Exception` branch — nothing was written to +`audit_log`, so `/admin` showed a stalled state with no explanation. + +The payout runs immediately after a ~2-minute wait on a block, so an Electrum drop in that +window is entirely plausible. Same shape applied to `InsufficientFundsError`, a missing +`fee_address` and a missing winner user — none of them logged anything either. + +CLAUDE.md listed "payout retry" as an accepted gap, but treated it as an operational +inconvenience; in practice it was a single point of failure that stopped the whole platform, +including across a process restart while a round was `paying_out`. + +**Fixed:** two changes, matching the proposed fix exactly. (a) Every early return in +`_trigger_payout` — not connected, no `fee_address`, winner not found, insufficient pool +UTXOs, a build error, a rejected broadcast — now calls `_log_payout_failure` with a `reason` +string in the payload, so `/admin`'s audit log always shows *why* a round is stuck, not just +that it is. (b) `_tick` now handles `status == "paying_out"` by calling the new +`_retry_payout_if_due`, which re-invokes `_trigger_payout` unless the most recent +`payout_failed` audit entry for this round is younger than `_PAYOUT_RETRY_INTERVAL_SECONDS` +(60s) — throttled so a persistently-broken payout (e.g. an operator hasn't set `fee_address` +yet) doesn't retry, and re-log a failure, on every 5-second tick. + +Because B-25 already made `_trigger_payout` idempotent (it no-ops if a non-terminal payout +`PendingTransaction` already exists for the round) and persists before broadcasting, this +retry is safe to fire on a process restart too: a round found `paying_out` at startup — whose +payout may have already broadcast, may never have been attempted, or may have been abandoned +by the reconciler — is retried the same way, closing the `paying_out` half of the "scheduler +doesn't resume mid-flight rounds after a restart" gap in CLAUDE.md (the "drawing"/block-wait +half is unrelated and still open, see B-36). + +Regression tests: `tests/unit/test_scheduler.py` +(`test_trigger_payout_logs_a_failure_when_not_connected`, +`test_trigger_payout_logs_a_failure_when_fee_address_missing`, +`test_tick_retries_a_stuck_paying_out_round_with_no_recent_failure`, +`test_tick_throttles_retry_after_a_recent_payout_failure`, +`test_tick_retries_once_the_throttle_window_has_elapsed`). + A full-codebase audit on 2026-07-26 (commit `d4e0974`) found 24 bugs across every Python module under `app/`, both static frontends, and the Docker/Caddy deployment — 5 critical, 7 high, 7 medium, 5 low. All 24 were fixed and verified against the current code on diff --git a/app/rounds/scheduler.py b/app/rounds/scheduler.py index 0a3dcf0..1159c6b 100644 --- a/app/rounds/scheduler.py +++ b/app/rounds/scheduler.py @@ -8,7 +8,7 @@ from sqlalchemy import func, select from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker from app.audit.log import write_audit_log -from app.db.models import PendingTransaction, Round, RoundParticipant, User +from app.db.models import AuditLog, PendingTransaction, Round, RoundParticipant, User from app.electrum.listener import ElectrumListener from app.electrum.scripthash import address_to_scripthash from app.rounds.config import get_round_config @@ -23,6 +23,13 @@ logger = logging.getLogger(__name__) _TICK_INTERVAL_SECONDS = 5 +# B-26: how long to wait after a payout failure before automatically retrying it. +# Long enough that a persistently-broken payout (misconfigured fee_address, +# insufficient pool UTXOs) doesn't re-attempt — and re-write a payout_failed audit +# entry — every _TICK_INTERVAL_SECONDS; short enough that a transient failure +# (a dropped Electrum connection, a momentarily-empty pool) self-heals quickly. +_PAYOUT_RETRY_INTERVAL_SECONDS = 60 + class RoundScheduler: """Background task implementing flowchart.mmd's DRAW subgraph: closes the @@ -56,8 +63,17 @@ class RoundScheduler: round_id, status, opened_at = round_.id, round_.status, round_.opened_at round_duration_seconds = (await get_round_config(session)).round_duration_seconds + if status == "paying_out": + # B-26: _trigger_payout used to run exactly once, from _close_and_draw — + # any failure after that (no Electrum client, insufficient pool UTXOs, a + # rejected broadcast) or a process restart while paying_out left the round + # wedged here forever. Every tick now re-checks and retries, throttled by + # _retry_payout_if_due so a persistent failure doesn't retry on every tick. + await self._retry_payout_if_due(round_id) + return + if status not in ("open", "closing"): - return # already drawing/paying_out; progress happens elsewhere + return # "drawing" — progress happens inside the in-flight _close_and_draw call if status == "open": opened_at = opened_at.replace(tzinfo=timezone.utc) @@ -161,6 +177,32 @@ class RoundScheduler: await asyncio.sleep(_TICK_INTERVAL_SECONDS) return self._listener.tip_height, header_hex_to_block_hash(self._listener.tip_header_hex) + async def _retry_payout_if_due(self, round_id: int) -> None: + """B-26: whether a "paying_out" round is due for another payout attempt. + + Throttled by the most recent payout_failed audit entry for this round + (written by _log_payout_failure on every early return in _trigger_payout, + including ones that used to fail silently) rather than by any new DB state, + since a failed attempt doesn't necessarily leave a PendingTransaction behind + (a build failure like a missing fee_address never gets that far). No entry + yet means this round hasn't failed before — either it's a fresh "paying_out" + (the very first call already happened from _close_and_draw and hasn't had a + chance to fail yet) or the process restarted before ever recording one — + either way it's due immediately. + """ + async with self._session_factory() as session: + last_failure_at = await session.scalar( + select(AuditLog.created_at) + .where(AuditLog.event_type == "payout_failed", AuditLog.round_id == round_id) + .order_by(AuditLog.id.desc()) + .limit(1) + ) + if last_failure_at is not None: + last_failure_at = last_failure_at.replace(tzinfo=timezone.utc) + if datetime.now(timezone.utc) < last_failure_at + timedelta(seconds=_PAYOUT_RETRY_INTERVAL_SECONDS): + return # too soon — avoid hammering a persistently-broken payout + await self._trigger_payout(round_id) + async def _trigger_payout(self, round_id: int) -> None: """Four phases, so no DB session is held across a network call (B-18): read what's needed, build the tx, persist the intent, then broadcast. @@ -177,6 +219,7 @@ class RoundScheduler: client = self._listener.client if client is None: logger.error("round %s payout deferred: not connected", round_id) + await self._log_payout_failure(round_id, None, "electrum client not connected") return # --- Phase 1: read (session closed before any network I/O) --------------- @@ -214,9 +257,11 @@ class RoundScheduler: logger.error( "round %s payout blocked: no fee_address configured (set it via the admin endpoint)", round_id ) + await self._log_payout_failure(round_id, winner_user_id, "no fee_address configured") return if winner_address is None: logger.error("round %s payout blocked: winner user %s not found", round_id, winner_user_id) + await self._log_payout_failure(round_id, winner_user_id, "winner user not found") return winner_share = pool_amount_sats * 70 // 100 @@ -247,15 +292,16 @@ class RoundScheduler: ) except InsufficientFundsError: logger.exception("round %s payout failed: insufficient pool UTXOs", round_id) + await self._log_payout_failure(round_id, winner_user_id, "insufficient pool UTXOs") return except Exception: # Anything else — a malformed fee_address (EmbitError) or similar. This # used to escape all the way to run()'s catch-all, which logged it # without recording anything, leaving no trace of *why* the round was - # stuck (B-05). The round stays in "paying_out" either way: automatic - # payout retry is still an open gap. + # stuck (B-05). _retry_payout_if_due (B-26) is what turns this recorded + # failure into an automatic retry instead of a dead end. logger.exception("round %s payout build failed", round_id) - await self._log_payout_failure(round_id, winner_user_id) + await self._log_payout_failure(round_id, winner_user_id, "payout build failed") return # --- Phase 3: persist the intent, *then* broadcast (B-25) ----------------- @@ -287,7 +333,7 @@ class RoundScheduler: # and, finding nothing, abandon it and clear payout_txid (B-25) — instead # of the round being stuck with a payout_txid that never went anywhere. logger.exception("round %s payout broadcast failed", round_id) - await self._log_payout_failure(round_id, winner_user_id) + await self._log_payout_failure(round_id, winner_user_id, "broadcast rejected") return async with self._session_factory() as session: @@ -304,15 +350,19 @@ class RoundScheduler: logger.info("round %s payout broadcast: txid=%s", round_id, built.txid) - async def _log_payout_failure(self, round_id: int, winner_user_id: int | None) -> None: + async def _log_payout_failure(self, round_id: int, winner_user_id: int | None, reason: str) -> None: """Leaves an operator-visible trace in the audit log for a round stuck in - "paying_out" — the logs alone don't show up in /admin.""" + "paying_out" — the logs alone don't show up in /admin. Called from every + early return in _trigger_payout (B-26), not just the generic exception + branch as before, so _retry_payout_if_due always has an entry to throttle + against and /admin always shows *why* a round is stuck rather than just + that it is.""" try: async with self._session_factory() as session: await write_audit_log( session, "payout_failed", - {"round_id": round_id}, + {"round_id": round_id, "reason": reason}, user_id=winner_user_id, round_id=round_id, ) diff --git a/tests/unit/test_scheduler.py b/tests/unit/test_scheduler.py index 7bcf771..7b323d2 100644 --- a/tests/unit/test_scheduler.py +++ b/tests/unit/test_scheduler.py @@ -247,3 +247,109 @@ async def test_reserved_payout_outpoints_excludes_utxos_claimed_by_a_stale_payou reserved = await _reserved_payout_outpoints(session) assert reserved == {(reserved_txid, 2)} + + +# --- B-26: a "paying_out" round must retry its payout automatically --------------- + + +async def test_trigger_payout_logs_a_failure_when_not_connected(payout_session_factory): + """Before B-26, this early return logged nothing beyond a log line — invisible + in /admin and unusable as a signal for an automatic retry.""" + await _seed_paying_out_round(payout_session_factory) + scheduler = RoundScheduler(payout_session_factory, FakePayoutListener(client=None)) + + await scheduler._trigger_payout(1) + + async with payout_session_factory() as session: + entries = (await session.scalars(select(AuditLog).where(AuditLog.event_type == "payout_failed"))).all() + assert len(entries) == 1 + assert entries[0].payload_json.count("electrum client not connected") == 1 + + +async def test_trigger_payout_logs_a_failure_when_fee_address_missing(payout_session_factory): + winner_id = await _seed_paying_out_round(payout_session_factory) + async with payout_session_factory() as session: + config = (await session.scalars(select(RoundConfig))).one() + config.fee_address = "" + await session.commit() + + entries = [{"tx_hash": "77" * 32, "tx_pos": 0, "height": 10, "value": _POOL_AMOUNT_SATS + 100_000}] + scheduler = RoundScheduler(payout_session_factory, FakePayoutListener(FakePayoutClient(entries))) + + await scheduler._trigger_payout(1) + + async with payout_session_factory() as session: + entry = (await session.scalars(select(AuditLog).where(AuditLog.event_type == "payout_failed"))).one() + assert "no fee_address configured" in entry.payload_json + assert entry.user_id == winner_id + + +async def test_tick_retries_a_stuck_paying_out_round_with_no_recent_failure(payout_session_factory): + """The scenario B-26 exists for: a round stuck in "paying_out" (a prior failure, + or a process restart mid-payout) with no non-terminal PendingTransaction. A + fresh tick must retry rather than leaving it wedged forever.""" + await _seed_paying_out_round(payout_session_factory) + entries = [{"tx_hash": "88" * 32, "tx_pos": 0, "height": 10, "value": _POOL_AMOUNT_SATS + 100_000}] + client = FakePayoutClient(entries) + scheduler = RoundScheduler(payout_session_factory, FakePayoutListener(client)) + + await scheduler._tick() + + assert client.broadcasted + async with payout_session_factory() as session: + round_ = await session.get(Round, 1) + assert round_.payout_txid is not None + pending = (await session.scalars(select(PendingTransaction))).one() + assert pending.status == "pending" + + +async def test_tick_throttles_retry_after_a_recent_payout_failure(payout_session_factory): + """A payout that just failed must not be retried on the very next tick, or a + persistently-broken payout (e.g. no fee_address) would spam a retry — and a + fresh payout_failed audit entry — every _TICK_INTERVAL_SECONDS.""" + await _seed_paying_out_round(payout_session_factory) + async with payout_session_factory() as session: + session.add( + AuditLog( + event_type="payout_failed", + payload_json='{"round_id": 1, "reason": "insufficient pool UTXOs"}', + round_id=1, + created_at=datetime.now(timezone.utc), + ) + ) + await session.commit() + + entries = [{"tx_hash": "99" * 32, "tx_pos": 0, "height": 10, "value": _POOL_AMOUNT_SATS + 100_000}] + client = FakePayoutClient(entries) + scheduler = RoundScheduler(payout_session_factory, FakePayoutListener(client)) + + await scheduler._tick() + + assert not client.broadcasted + async with payout_session_factory() as session: + assert (await session.scalars(select(PendingTransaction))).all() == [] + + +async def test_tick_retries_once_the_throttle_window_has_elapsed(payout_session_factory): + await _seed_paying_out_round(payout_session_factory) + async with payout_session_factory() as session: + session.add( + AuditLog( + event_type="payout_failed", + payload_json='{"round_id": 1, "reason": "insufficient pool UTXOs"}', + round_id=1, + created_at=datetime.now(timezone.utc) - timedelta(seconds=120), + ) + ) + await session.commit() + + entries = [{"tx_hash": "aa" * 32, "tx_pos": 0, "height": 10, "value": _POOL_AMOUNT_SATS + 100_000}] + client = FakePayoutClient(entries) + scheduler = RoundScheduler(payout_session_factory, FakePayoutListener(client)) + + await scheduler._tick() + + assert client.broadcasted + async with payout_session_factory() as session: + pending = (await session.scalars(select(PendingTransaction))).one() + assert pending.status == "pending"