From 213837ff97cbe1f212a4266c6be2be8e806215da Mon Sep 17 00:00:00 2001 From: Barely Removable Date: Mon, 31 Aug 2026 23:58:23 -0700 Subject: [PATCH] Poll for run completion every 5 minutes instead of checking once MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The one-shot VERIFY_DELAY_MINUTES check was too rigid: MassPrice's processing time varies widely in practice (observed ~1 to over 20 minutes, and its queue can back up further under load — confirmed live, a run still sitting in "Queued" 15+ minutes in), so a single check window either misses slow-but-fine completions or has to be set needlessly long. Replaced with a poll loop: scheduler.py reschedules another one-off check every VERIFY_POLL_MINUTES (default 5) until automation's check_completion() reports "complete", up to VERIFY_MAX_ATTEMPTS (default 12, ~1 hour) before giving up and marking "not_confirmed" for good. verify_run() is split into a pure check_completion() (no storage side effects) so scheduler.py's loop owns the retry/give-up decision; automation.py just answers "is it done yet". Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01H6TgffxTvYhqxykAbVQg2v --- .env.example | 17 +++++---- CLAUDE.md | 67 +++++++++++++++++++++++------------- app.py | 2 +- automation.py | 86 ++++++++++++++++++++++++++-------------------- docker-compose.yml | 3 +- scheduler.py | 66 ++++++++++++++++++++++++----------- 6 files changed, 151 insertions(+), 90 deletions(-) diff --git a/.env.example b/.env.example index 7c1159e..c125470 100644 --- a/.env.example +++ b/.env.example @@ -18,13 +18,16 @@ HOST_PORT=5057 # Controls what "6:00 AM" means for your schedules TZ=America/Phoenix -# ── Run verification delay ────────────────────────────────────────── -# Minutes to wait after a run is confirmed sent before checking -# MassPrice's own Activity Log to see whether it actually completed. -# MassPrice's processing time varies a lot in practice (observed -# anywhere from ~1 to ~22 minutes) — this is a reasonable middle -# ground, not a guarantee. -VERIFY_DELAY_MINUTES=10 +# ── Run verification polling ───────────────────────────────────────── +# After a run is confirmed sent, checks MassPrice's own Activity Log +# every VERIFY_POLL_MINUTES to see whether it actually completed, +# retrying up to VERIFY_MAX_ATTEMPTS times before giving up and marking +# it "Not Confirmed". MassPrice's processing time varies a lot in +# practice (observed anywhere from ~1 minute to over 20) and its queue +# can back up further under load — the default (5 min x 12 = up to an +# hour of patience) is a reasonable middle ground, not a guarantee. +VERIFY_POLL_MINUTES=5 +VERIFY_MAX_ATTEMPTS=12 # ── Session-expiry email alert (optional) ─────────────────────────── # Sent once when the saved MassPrice session expires/is missing — not diff --git a/CLAUDE.md b/CLAUDE.md index a3bbed5..f71f80e 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -39,12 +39,22 @@ tool is confirmed working, so there's exactly one thing triggering runs. `workers = 1` for this reason — a second worker would instantiate a second scheduler and duplicate every run. Fine for a low-traffic single-user tool. - - Also schedules **one-off** `verify-` jobs (APScheduler - `date` trigger, not recurring) `VERIFY_DELAY_MINUTES` after a run is - confirmed sent — see `automation.verify_run()` below. - `rebuild_jobs()` only ever removes `rule-*` jobs, deliberately, so - editing a schedule mid-flight can't cancel a verification that's - already in progress for an earlier run. + - Also drives the **completion poll loop**: after a run is confirmed + sent, a one-off `verify--` job (APScheduler + `date` trigger, not recurring) fires `VERIFY_POLL_MINUTES` later and + calls `automation.check_completion()`. Not complete yet? Another + one-off job reschedules the next check the same interval later — + `_run_verification_check()` in `scheduler.py` owns this loop — up to + `VERIFY_MAX_ATTEMPTS` times, after which it's marked + `"not_confirmed"` for good. `rebuild_jobs()` only ever removes + `rule-*` jobs, deliberately, so editing a schedule mid-flight can't + cancel a poll loop that's already in progress for an earlier run. + These one-off jobs live only in the scheduler's in-memory jobstore + (no persistent jobstore is configured) — a container restart mid-poll + silently drops that one entry's remaining checks, leaving it stuck + on whatever state it was last in (usually "pending"). Low-impact + (an hour-long window, restarts are infrequent) but worth knowing if + an entry is ever seen stuck on "Pending" long after the fact. - **`automation.py`** — all Playwright logic. `list_rules()` scrapes `https://massprice.tcgplayer.com/Rule/List` for the live rule id/name pairs (cached to `rules_cache.json`, refreshed via the @@ -71,23 +81,34 @@ tool is confirmed working, so there's exactly one thing triggering runs. drives the real page rather than replaying a raw HTTP POST. - **Run verification** — confirming the modal only means MassPrice *accepted* the run; it still processes asynchronously on their side - (queued → running → Complete), taking anywhere from ~1 to ~22 minutes - in observed practice. `run_rule()` captures a "watermark" — the - `data-activitylogid` of that rule's current top entry on - `/Activity/List` (a stable, monotonically increasing ID; deliberately - *not* parsing the displayed timestamp string, which would need - fragile date/timezone handling) — **before** submitting, logs the run - as `status: "sent"` with `verification: "pending"`, and the caller in - `scheduler.py` schedules `verify_run()` to run `VERIFY_DELAY_MINUTES` - later. `verify_run()` re-checks `/Activity/List`: a new entry (higher - `data-activitylogid` than the watermark) whose status text contains - "Complete" → `verification: "complete"`; otherwise - `verification: "not_confirmed"` (which can mean "still processing", - not necessarily "failed" — the delay is a reasonable middle ground, - not a guarantee it's had enough time). `_find_latest_activity()` is - shared by the watermark capture and the follow-up check. The Activity - page's "Complete" column surfaces this; "Status" shows whether the - click itself was sent, independent of whether MassPrice finished it. + (queued → running → Complete), taking anywhere from ~1 minute to over + 20 in observed practice, and its queue can back up further under + load (observed directly: a run still sitting in "Queued" 15+ minutes + in). `run_rule()` captures a "watermark" — the `data-activitylogid` of + that rule's current top entry on `/Activity/List` (a stable, + monotonically increasing ID; deliberately *not* parsing the displayed + timestamp string, which would need fragile date/timezone handling) — + **before** submitting, logs the run as `status: "sent"` with + `verification: "pending"`, and the caller in `scheduler.py` starts a + poll loop (`automation.check_completion()`, every + `VERIFY_POLL_MINUTES`, up to `VERIFY_MAX_ATTEMPTS` times — see + `scheduler.py`'s own section above for the mechanics). Each check + re-scans `/Activity/List`: a new entry (higher `data-activitylogid` + than the watermark) whose status text contains "Complete" → + `verification: "complete"`, loop stops; otherwise the loop keeps + `verification: "pending"` and just updates `verify_message` with the + latest note, until attempts run out and it's marked + `verification: "not_confirmed"` for good — which can mean "still + processing somewhere past our patience", not necessarily "failed". + Also worth knowing: a still-"Queued" MassPrice entry has no + `data-activitylogid` yet (no "View" link exists until it finishes), + so `_find_latest_activity()` — shared by the watermark capture and + every poll — correctly falls through to the *previous* completed + entry rather than matching the in-flight one; that's why "no ID + higher than the watermark" is the right "not done yet" signal, not a + bug. The Activity page's "Complete" column surfaces all of this; + "Status" shows whether the click itself was sent, independent of + whether MassPrice finished it. - **Session persistence** — a Playwright `storage_state` (cookies + localStorage) is saved to `/data/auth_state.json` and reused across runs: scheduled runs never touch the login form at all, they just load diff --git a/app.py b/app.py index 5e09b42..55232b6 100644 --- a/app.py +++ b/app.py @@ -9,7 +9,7 @@ import automation import scheduler import storage -APP_VERSION = "0.7.0" +APP_VERSION = "0.8.0" APP_VERSION_DATE = "2026-09-01" app = Flask(__name__) diff --git a/automation.py b/automation.py index 212141b..f726a26 100644 --- a/automation.py +++ b/automation.py @@ -189,7 +189,8 @@ def run_rule(rule_id, rule_name=None): rule id. Logs the outcome to run_history.json and returns a dict: {"status": "sent"|"failure", "message": ..., "entry_id": ..., "watermark_activity_id": ...}. On "sent", the caller (scheduler.py) - schedules a delayed verify_run() call using entry_id/watermark_activity_id + starts a poll loop (check_completion(), every VERIFY_POLL_MINUTES, + up to VERIFY_MAX_ATTEMPTS times) using entry_id/watermark_activity_id to confirm the run actually completed on MassPrice's side.""" status = "failure" message = "" @@ -257,7 +258,7 @@ def run_rule(rule_id, rule_name=None): entry_id = _log_history(rule_id, rule_name, status, message) will_verify = status == "sent" and bool(rule_name) if will_verify: - _set_verification_pending(entry_id) + set_verification_pending(entry_id) return { "status": status, @@ -268,12 +269,11 @@ def run_rule(rule_id, rule_name=None): } -def verify_run(entry_id, rule_name, watermark_id): - """Delayed follow-up: check whether the run logged as entry_id - actually completed on MassPrice's side by now. Updates that - run_history.json entry's "verification" field in place.""" - verification = "not_confirmed" - verify_message = "" +def check_completion(rule_name, watermark_id): + """One-shot check: has a new "Complete" entry appeared for rule_name + past watermark_id yet? Returns ("complete", "") or ("not_yet", msg). + Pure check — no storage side effects; the caller (scheduler.py's + poll loop) decides what that means for the stored history entry.""" with sync_playwright() as p: browser = p.chromium.launch(headless=True, args=LAUNCH_ARGS) try: @@ -284,21 +284,18 @@ def verify_run(entry_id, rule_name, watermark_id): activity_id, status_text = _find_latest_activity(page, rule_name) if activity_id is None: - verify_message = "No matching activity found on MassPrice" - elif watermark_id is not None and activity_id <= watermark_id: - verify_message = "No new completion appeared within the allotted time" - elif status_text and "complete" in status_text.lower(): - verification = "complete" - else: - verify_message = f"Latest activity shows \"{status_text}\", not Complete" + return "not_yet", "No matching activity found on MassPrice" + if watermark_id is not None and activity_id <= watermark_id: + return "not_yet", "No new completion has appeared yet" + if status_text and "complete" in status_text.lower(): + return "complete", "" + return "not_yet", f'Latest activity shows "{status_text}", not Complete yet' except Exception as exc: - verify_message = str(exc) - logger.exception("verify_run failed for entry %s", entry_id) + logger.exception("check_completion failed for %s", rule_name) + return "not_yet", str(exc) finally: browser.close() - _update_verification(entry_id, verification, verify_message) - def _log_history(rule_id, rule_name, status, message): entry_id = uuid.uuid4().hex @@ -312,11 +309,11 @@ def _log_history(rule_id, rule_name, status, message): "timestamp": datetime.now(timezone.utc).isoformat(), "status": status, "message": message, - # "pending" only when a verify_run() has actually been - # scheduled for this entry (status == "sent" and rule_name - # was known) — set explicitly by run_rule() below, not here, - # since _log_history() itself doesn't know whether scheduling - # succeeded. + # "pending" only when a completion poll loop has actually + # been started for this entry (status == "sent" and + # rule_name was known) — set explicitly by run_rule() below, + # not here, since _log_history() itself doesn't know whether + # scheduling succeeded. "verification": None, "verify_message": None, }, @@ -325,29 +322,44 @@ def _log_history(rule_id, rule_name, status, message): return entry_id -def _set_verification_pending(entry_id): - history = storage.load("run_history.json", []) +def _find_history_entry(history, entry_id): for entry in history: if entry.get("id") == entry_id: - entry["verification"] = "pending" - break - else: + return entry + return None + + +def set_verification_pending(entry_id): + history = storage.load("run_history.json", []) + entry = _find_history_entry(history, entry_id) + if entry is None: return + entry["verification"] = "pending" storage.save("run_history.json", history) -def _update_verification(entry_id, verification, verify_message): +def set_verification_message(entry_id, message): + """Record the latest poll's note without changing the terminal + state — used between retries, while still "pending".""" history = storage.load("run_history.json", []) - for entry in history: - if entry.get("id") == entry_id: - entry["verification"] = verification - entry["verify_message"] = verify_message - entry["verified_at"] = datetime.now(timezone.utc).isoformat() - break - else: + entry = _find_history_entry(history, entry_id) + if entry is None: # Entry aged out of the 200-cap between being logged and this # delayed check running — nothing to update, not an error. return + entry["verify_message"] = message + storage.save("run_history.json", history) + + +def update_verification(entry_id, verification, verify_message): + """Set a terminal verification result ("complete" or "not_confirmed").""" + history = storage.load("run_history.json", []) + entry = _find_history_entry(history, entry_id) + if entry is None: + return + entry["verification"] = verification + entry["verify_message"] = verify_message + entry["verified_at"] = datetime.now(timezone.utc).isoformat() storage.save("run_history.json", history) diff --git a/docker-compose.yml b/docker-compose.yml index 19b4bbc..9941f64 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -16,7 +16,8 @@ services: - LOGIN_PASSWORD=${LOGIN_PASSWORD} - SECRET_KEY=${SECRET_KEY} - TZ=${TZ:-America/Phoenix} - - VERIFY_DELAY_MINUTES=${VERIFY_DELAY_MINUTES:-10} + - VERIFY_POLL_MINUTES=${VERIFY_POLL_MINUTES:-5} + - VERIFY_MAX_ATTEMPTS=${VERIFY_MAX_ATTEMPTS:-12} - GMAIL_USER=${GMAIL_USER:-} - GMAIL_APP_PASSWORD=${GMAIL_APP_PASSWORD:-} - ALERT_EMAIL=${ALERT_EMAIL:-} diff --git a/scheduler.py b/scheduler.py index 4d1c192..c702bb0 100644 --- a/scheduler.py +++ b/scheduler.py @@ -5,10 +5,14 @@ APScheduler-triggered runs and manual "Run Now" clicks are pushed onto one queue.Queue so exactly one browser session is ever active at a time. This must run in exactly one process; see gunicorn.conf.py's workers=1. -The same worker also handles delayed "verify_run" tasks: after a rule -run is confirmed sent, a one-off APScheduler job (not a recurring cron -job) fires VERIFY_DELAY_MINUTES later and enqueues a check of whether it -actually completed on MassPrice's side — see automation.verify_run(). +The same worker also drives a poll loop that confirms a run actually +completed on MassPrice's side: after a run is confirmed sent, a one-off +APScheduler job (not a recurring cron job) fires VERIFY_POLL_MINUTES +later and enqueues a check (automation.check_completion()). If it's not +complete yet, another one-off job reschedules the next check the same +interval later — up to VERIFY_MAX_ATTEMPTS times, after which it's +marked "not_confirmed" for good (which can mean "still processing +somewhere past our patience", not necessarily "failed"). """ import logging import os @@ -43,12 +47,14 @@ _started = False VALID_DAYS = ["mon", "tue", "wed", "thu", "fri", "sat", "sun"] -# How long to wait after a run is confirmed sent before checking whether -# it actually completed on MassPrice's side. MassPrice's own processing -# time varies a lot in practice (observed anywhere from ~1 to ~22 -# minutes) — this is a reasonable middle ground, not a guarantee; a -# "not_confirmed" result can mean "still processing", not just "failed". -VERIFY_DELAY_MINUTES = int(os.environ.get("VERIFY_DELAY_MINUTES", "10")) +# How often to re-check whether a sent run has completed on MassPrice's +# side, and how many times to try before giving up. MassPrice's own +# processing time varies a lot in practice (observed anywhere from ~1 to +# over 20 minutes, and its queue can back up further under load) — 5 +# minutes x 12 attempts gives an hour of patience before a stuck/failed +# run is reported as "not_confirmed" instead of polling forever. +VERIFY_POLL_MINUTES = int(os.environ.get("VERIFY_POLL_MINUTES", "5")) +VERIFY_MAX_ATTEMPTS = int(os.environ.get("VERIFY_MAX_ATTEMPTS", "12")) def _worker_loop(): @@ -64,31 +70,49 @@ def _worker_loop(): result["entry_id"], rule_name, result["watermark_activity_id"] ) elif kind == "verify": - _, entry_id, rule_name, watermark_id = item - automation.verify_run(entry_id, rule_name, watermark_id) + _, entry_id, rule_name, watermark_id, attempt = item + _run_verification_check(entry_id, rule_name, watermark_id, attempt) except Exception: logger.exception("Unhandled error processing %r", item) finally: _work_queue.task_done() +def _run_verification_check(entry_id, rule_name, watermark_id, attempt): + result, message = automation.check_completion(rule_name, watermark_id) + if result == "complete": + automation.update_verification(entry_id, "complete", "") + elif attempt >= VERIFY_MAX_ATTEMPTS: + elapsed = attempt * VERIFY_POLL_MINUTES + automation.update_verification( + entry_id, + "not_confirmed", + f"Still not confirmed after {attempt} checks over ~{elapsed} minutes " + f"— last check: {message}", + ) + else: + # Not done yet, but not giving up — keep "pending", just record + # the latest note, and queue the next check. + automation.set_verification_message(entry_id, message) + schedule_verification(entry_id, rule_name, watermark_id, attempt=attempt + 1) + + def enqueue_run(rule_id, rule_name=None): _work_queue.put(("run", rule_id, rule_name)) -def enqueue_verify(entry_id, rule_name, watermark_id): - _work_queue.put(("verify", entry_id, rule_name, watermark_id)) +def enqueue_verify(entry_id, rule_name, watermark_id, attempt): + _work_queue.put(("verify", entry_id, rule_name, watermark_id, attempt)) -def schedule_verification(entry_id, rule_name, watermark_id, delay_minutes=None): - delay = VERIFY_DELAY_MINUTES if delay_minutes is None else delay_minutes - run_date = datetime.now(_TZ) + timedelta(minutes=delay) +def schedule_verification(entry_id, rule_name, watermark_id, attempt=1): + run_date = datetime.now(_TZ) + timedelta(minutes=VERIFY_POLL_MINUTES) _scheduler.add_job( enqueue_verify, trigger="date", run_date=run_date, - args=[entry_id, rule_name, watermark_id], - id=f"verify-{entry_id}", + args=[entry_id, rule_name, watermark_id, attempt], + id=f"verify-{entry_id}-{attempt}", misfire_grace_time=600, ) @@ -102,8 +126,8 @@ def rebuild_jobs(): Only touches "rule-*" jobs — one-off "verify-*" jobs (see schedule_verification()) must survive a schedule edit elsewhere, - since they're tracking an already-in-flight run, not a recurring - schedule. + since they're tracking an already-in-flight run's poll loop, not a + recurring schedule. """ for job in _scheduler.get_jobs(): if job.id.startswith("rule-"):