Files
pumpfun-bonkfun-bot_github/tests/regression/verify_cleanup_survives_shutdown.py
T
978946f8ed fix(trading,monitoring,cookbook): keep clean shutdowns clean, guard the migration decoder (#228)
* fix(trading): balance task_done against get in the token queue processor

`_process_token_queue` called `task_done()` from a `finally` that also runs
when `queue.get()` itself is cancelled, at which point no item was taken, so
the call was unbalanced and raised:

    ValueError: task_done() called too many times

Cancelling that task is how `start()` shuts yolo mode down, and the
cancellation almost always lands while parked on `get()`. `start()` catches
only `CancelledError` around the await, so the ValueError reached the outer
handler and every clean yolo-mode shutdown was logged as `Trading stopped due
to error` with a traceback. Nothing was lost, since `_cleanup_resources()`
still ran, but the log said a good run had failed.

Track whether an item was taken and call `task_done()` only then. The
stale-token `continue` path did take one and still calls it, or `join()` would
never return.

Closes #210

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* fix(monitoring): stop logging a normal WebSocket close as a ping error

Every WebSocket listener runs a `_ping_loop` that caught `CancelledError` and
then fell through to a broad `except Exception: logger.exception("Ping error")`.
When the connection closes normally, `websocket.ping()` raises
`ConnectionClosedOK` or `ConnectionClosedError` — neither is a `CancelledError`,
so both landed in the broad handler and printed a traceback at ERROR:

    ERROR:monitoring.universal_logs_listener:Ping error
    websockets.exceptions.ConnectionClosedError: sent 1000 (OK); no close frame received

Close code 1000 is a normal closure. Nothing was wrong, but a completed run
reported a failure to anyone reading the logs or alerting on ERROR.

Catch `ConnectionClosed` before the broad handler and exit the loop at debug.
The broad handler stays for anything genuinely unexpected.

#206 had narrowed the race by cancelling the ping task in a `finally` on the
read loop, but the ping can still fire between the connection closing and the
cancellation landing, and a server-initiated close always reached the loop this
way. The pumpportal listener has the same loop and is fixed here too.

Closes #203

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* fix(cookbook,tools): reject payloads that are not the migration event

`parse_migrate_instruction` skipped the first 8 bytes as a discriminator but
never checked them, so every `Program data:` line in a migration transaction
was decoded against the migration schema whatever event it actually was. The
schema needs 301 bytes; any payload at least that long came back as a fully
populated dict of meaningless values rather than as a failure — a
`baseMintDecimals` of 176 where the field can only legitimately be 0-9. Shorter
payloads happened to fail inside `struct.unpack`, which is why the underrun was
never the visible symptom.

The event is the wrapper program's `CreatePoolEvent`, not the
`CompletePumpAmmMigrationEvent` in `idl/pump_fun_idl.json` — confirmed against
mainnet, where every payload the program emits carries discriminator
`b1310cd2a076a774`, which is `sha256("event:CreatePoolEvent")[:8]`. Assert it
before reading any field. The field layout itself was already correct.

Both copies of the decoder are fixed. In the cookbook script, `parsed_data` was
also reassigned on every `Program data:` line, so a later non-matching line
would wipe a good parse now that the guard returns None; keep the first match.

Closes #198

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* refactor(cookbook): declare BondingCurveState fields instead of __dict__.update

The class assigned its parsed fields through `self.__dict__.update(...)`. The
fields were correct at runtime, but nothing declared them, so type checkers and
editors could not see them: reading `state.virtual_token_reserves` in any
consumer produced an "attribute is unknown" warning, with no autocomplete and
no go-to-definition for any reserve field.

Declare the fields and assign them from the parse result. Where several struct
versions share the leading fields, pick the struct in the branch and assign
once after it, so the optional trailing fields resolve through one `.get` each
rather than through a pre-set default that a later update may or may not
overwrite. This also drops construct's `_io` from the instance dict.

No behaviour change: parsed state for a live curve is identical field for field
before and after, across all three classes. `src/` is unaffected — its curve
manager works on plain dicts and never used this class.

Closes #204

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* fix(trading): finish shutdown cleanup through the cancellation that triggered it

`start()` reclaims account rent from a `finally` that awaited
`_cleanup_resources`. Shutdown reaches that coroutine as a cancellation, and
cleanup awaits once per account — a settle wait, then an RPC read — so the first
of those re-raised `CancelledError` and every account after it kept its rent.
The run then ended without even logging that it shut down, so nothing in the log
said cleanup had been cut short.

Seen on a live run interrupted during the settle wait: it stopped after two of
its accounts. Three other runs interrupted a moment earlier finished cleanly, so
this is a race rather than a certainty.

Run cleanup as its own task and wait through the cancellation with
`asyncio.wait`, which neither cancels the task on timeout nor re-raises what it
failed with. Bounded by `_CLEANUP_SHUTDOWN_BUDGET` so a stuck RPC cannot hold
the process open; rent left behind is recoverable, so the warning names
`tools/cleanup_accounts.py` rather than retrying here.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-09-25 14:28:43 +02:00

188 lines
6.2 KiB
Python

"""Verify shutdown cleanup finishes instead of being aborted by its own cancellation.
`UniversalTrader.start` reclaims account rent from a `finally` that awaits
`_cleanup_resources`. Shutdown reaches that coroutine as a cancellation, and
cleanup awaits once per account — a 15s settle wait, then an RPC read — so the
first of those re-raised `CancelledError` and every account after it kept its
rent. The run then ended without even logging that it shut down, so nothing in
the log said cleanup had been cut short.
Observed live on 2026-09-25: a run interrupted during cleanup's settle wait
stopped after two of its accounts and never printed `Universal Trader has shut
down`. Three other runs interrupted a moment earlier finished cleanly, so this is
a race, not a certainty — which is what makes it worth pinning.
The rent is recoverable by hand with `tools/cleanup_accounts.py <MINT>`, so the
budget cuts cleanup off rather than holding the process open on a stuck RPC.
Offline machine checks, no network and no funds moved. `_cleanup_resources` is
replaced with a stub that awaits, so the cancellation lands mid-cleanup:
1. Cleanup started before the cancellation still runs to completion.
2. The caller returns rather than propagating, so the shutdown line is reached.
3. Cleanup that overruns the budget is cancelled, and the warning names the
command that reclaims the rent.
4. A cleanup that raises is logged, not propagated.
5. The budget is a positive, finite number — an unbounded wait would hang a
shutdown behind a stuck RPC.
Usage:
uv run tests/regression/verify_cleanup_survives_shutdown.py
"""
import asyncio
import logging
import math
import sys
from pathlib import Path
_STUB_FAILURE = "stub cleanup failure"
PROJECT_ROOT = Path(__file__).resolve().parents[2]
sys.path.insert(0, str(PROJECT_ROOT / "src"))
from trading.universal_trader import UniversalTrader # noqa: E402
class RecordCapture(logging.Handler):
"""Collects records at WARNING or above."""
def __init__(self) -> None:
super().__init__(level=logging.WARNING)
self.records: list[logging.LogRecord] = []
def emit(self, record: logging.LogRecord) -> None:
self.records.append(record)
def _check(label: str, passed: bool, detail: str) -> bool: # noqa: FBT001
print(f" [{'PASS' if passed else 'FAIL'}] {label}: {detail}")
return passed
async def _shutdown_with( # noqa: ANN202
cleanup, # noqa: ANN001
budget=None, # noqa: ANN001
):
"""Cancel a caller parked in _cleanup_without_interruption, as start() does.
Returns:
Tuple of (how the caller ended, WARNING+ records emitted)
"""
trader = object.__new__(UniversalTrader)
trader._cleanup_resources = cleanup # noqa: SLF001
if budget is not None:
trader._CLEANUP_SHUTDOWN_BUDGET = budget # noqa: SLF001
capture = RecordCapture()
logger = logging.getLogger("trading.universal_trader")
logger.addHandler(capture)
try:
task = asyncio.create_task(trader._cleanup_without_interruption()) # noqa: SLF001
await asyncio.sleep(0.05)
task.cancel()
try:
await task
outcome = None
except BaseException as exc: # noqa: BLE001
outcome = exc
finally:
logger.removeHandler(capture)
return outcome, capture.records
async def check_cleanup_completes_through_cancellation() -> bool:
print("\n1. Cleanup started before the cancellation still finishes")
finished = []
async def cleanup() -> None:
await asyncio.sleep(0.3)
finished.append("done")
await _shutdown_with(cleanup)
return _check(
"cleanup ran to completion",
finished == ["done"],
"finished" if finished else "aborted at its first await",
)
async def check_caller_returns_normally() -> bool:
print("\n2. The caller returns, so the shutdown line is reached")
async def cleanup() -> None:
await asyncio.sleep(0.2)
outcome, _ = await _shutdown_with(cleanup)
return _check(
"caller outcome",
outcome is None,
"returned normally"
if outcome is None
else f"{type(outcome).__name__} propagated — shutdown line skipped",
)
async def check_budget_cuts_off_a_hung_cleanup() -> bool:
print("\n3. Cleanup that overruns the budget is cut off, with a usable warning")
async def cleanup() -> None:
await asyncio.sleep(3600)
outcome, records = await _shutdown_with(cleanup, budget=0.3)
messages = " ".join(r.getMessage() for r in records)
named = "cleanup_accounts.py" in messages
return _check(
"returned within the budget",
outcome is None and named,
f"returned={outcome is None}, warning names the recovery command={named}",
)
async def check_failing_cleanup_is_logged_not_raised() -> bool:
print("\n4. A cleanup that raises is logged, not propagated")
async def cleanup() -> None:
await asyncio.sleep(0.1)
raise RuntimeError(_STUB_FAILURE)
outcome, records = await _shutdown_with(cleanup)
logged = any("Cleanup failed" in r.getMessage() for r in records)
return _check(
"caller outcome",
outcome is None and logged,
f"returned={outcome is None}, logged={logged}",
)
def check_budget_is_bounded() -> bool:
print("\n5. The budget is positive and finite")
budget = UniversalTrader._CLEANUP_SHUTDOWN_BUDGET # noqa: SLF001
ok = isinstance(budget, int | float) and budget > 0 and math.isfinite(budget)
return _check("_CLEANUP_SHUTDOWN_BUDGET", ok, f"{budget!r}")
async def main() -> None:
print("=" * 72)
print("Verifying shutdown cleanup is not aborted by its own cancellation")
print("=" * 72)
results = [
await check_cleanup_completes_through_cancellation(),
await check_caller_returns_normally(),
await check_budget_cuts_off_a_hung_cleanup(),
await check_failing_cleanup_is_logged_not_raised(),
check_budget_is_bounded(),
]
print("\n" + "=" * 72)
if all(results):
print(f"ALL {len(results)} CHECKS PASSED")
else:
print(f"{results.count(False)}/{len(results)} CHECKS FAILED")
sys.exit(1)
if __name__ == "__main__":
asyncio.run(main())