Retry a stuck payout automatically, and log every failure (B-26)
_trigger_payout used to run exactly once, from _close_and_draw. Any failure after that point — no Electrum client, insufficient pool UTXOs, a missing fee_address, a rejected broadcast — wedged the round in paying_out forever, and every one of those early returns except the generic exception handler logged nothing at all: /admin showed a stalled round with no explanation. A process restart while paying_out hit the same dead end. _tick now handles status == "paying_out": it calls the new _retry_payout_if_due, which re-invokes _trigger_payout unless the most recent payout_failed audit entry for the round is younger than _PAYOUT_RETRY_INTERVAL_SECONDS (60s) — throttled so a persistently broken payout (e.g. no fee_address set yet) doesn't retry, and re-log a failure, on every 5-second tick. Every early return in _trigger_payout now calls _log_payout_failure with a reason string, so that throttle always has something to check against and /admin always shows why a round is stuck. This is safe to fire on a restart too, because B-25 already made _trigger_payout idempotent (it no-ops if a non-terminal payout PendingTransaction already exists) and persists before broadcasting — so a round found paying_out at startup, whatever state its payout was actually in, gets retried the same way. That closes 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 untouched (see BUGS.md B-36). BUGS.md moves B-26 to "Previously fixed" with the fix description; the suite grows from 143 to 148 tests. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
+59
-9
@@ -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,
|
||||
)
|
||||
|
||||
Reference in New Issue
Block a user