Poll for run completion every 5 minutes instead of checking once

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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01H6TgffxTvYhqxykAbVQg2v

.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

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-<entry_id>` 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-<entry_id>-<attempt>` 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

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__)

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)
 
 

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:-}

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-"):