fix(scheduler): audit a tick suppressed by the distributed lock (#1969)

[dolho]

Problem

When a cron tick is suppressed by the Redis distributed lock, _execute_schedule() logged at INFO and returned:

lock = self.lock_manager.try_acquire_schedule_lock(schedule_id)
if not lock:
    logger.info(f"Schedule {schedule_id} already being executed by another instance")
    return          # <-- nothing recorded

No schedule_executions row, so the suppressed tick is invisible in execution history, the UI, and monitoring — indistinguishable from a tick that never fired. APScheduler meanwhile marks the job successful and advances next_run_at.

Suppression itself is correct: two concurrent runs of one schedule is exactly what the lock exists to prevent. What was missing is the evidence that it happened.

Why this is a missing call, not a design gap

Two paths suppress a run, and only one was audited:

Path	Mechanism	Audited before
APScheduler refuses the job	max_instances=1 → EVENT_JOB_MAX_INSTANCES → _on_job_max_instances() → _record_skipped_agent_schedule()	✅ status='skipped' row + schedule_execution_skipped event
Redis lock denies the run	_execute_schedule() lock-denial branch	❌ bare return

They cannot both fire for one tick, which is what makes calling the same helper from both safe:

• a max_instances refusal means the job never started, so _execute_schedule is never entered and no lock is attempted;
• reaching the lock branch means APScheduler already let the job start, so no max-instances event is emitted.

The gap bit hardest on the common case. A manual trigger bypasses APScheduler entirely (_trigger_handler dispatches via asyncio.create_task), so its per-job instance counter stays at zero, the cron job starts normally, and the collision is caught one layer down — in precisely the unaudited branch. Manual trigger shortly before the scheduled time was the one case producing no audit record at all.

Fix

The branch calls the existing helper, exactly as the issue suggests. _record_skipped_agent_schedule() was already parameterised in #1808 for this kind of reuse, so no new machinery is involved.

The wording names the lock, not the max_instances default — reusing the default would file a lock collision as a max_instances refusal and send anyone debugging it to the wrong mechanism. Both now produce the same status='skipped' row shape and the same schedule_execution_skipped WebSocket event.

The #91 regression shape

The issue asks to confirm a manual run colliding with its own cron tick produces exactly one skipped row, not a duplicate. Three tests cover it:

• one denial → exactly one record;
• three denials → three records, one per suppressed tick (matching the cardinality the max_instances path already produces);
• a source guard that _on_job_max_instances still never routes through _execute_schedule. That mutual exclusion is the property the whole fix rests on, and it is the kind of thing a future refactor breaks silently — if the listener ever reached _execute_schedule, a single tick would be audited twice, which is the Scheduler creates duplicate execution records (skipped + success) for single trigger #91 shape.

Verification

tests/unit/test_1969_lock_denied_tick_audit.py — 12 checks, 5 of which fail against the pre-fix tree:

$ git stash push -- src/ && pytest unit/test_1969_lock_denied_tick_audit.py -q
5 failed, 7 passed
$ git stash pop && pytest unit/test_1969_lock_denied_tick_audit.py -q
12 passed

The 7 that pass either way are deliberate — they pin behaviour the fix must preserve, and are the reason to trust the change is narrow:

• the audited tick still does not run the schedule (auditing suppression must not undo it — that would be the concurrent execution the lock prevents);
• the granted-lock path stays silent (a skipped row on every successful tick would invert the meaning of the status for every consumer of the history);
• the pre-existing lock release survives on both the success and the raise path, and no .release() is attempted when no lock was handed out. The new branch sits directly above that finally; a lock leaked there would wedge the schedule until the TTL.

The file ends with an end-to-end pass against a real temp SQLite DB, asserting a status='skipped' row with the lock reason actually lands. The wiring assertions alone would still pass with a broken write path.

Also green: scheduler_tests/test_skipped_executions.py + test_service.py (34 tests, the existing coverage of the DB write path and the max_instances listener), and the adjacent unit suites test_1808, test_1945, test_1557, test_schedule_status_observability (44 tests).

Deliberately not included

The DB's next_run_at projection is not advanced on a denied tick. That is the #1472 "receding Next: Nd ago" class, and the existing max_instances path does not advance it either — adding it to only one of the two would reintroduce exactly the inconsistency this PR removes. Worth its own issue if it bites; flagging rather than silently expanding scope here.

Acceptance criteria

• A lock-denied tick writes a status='skipped' row and publishes schedule_execution_skipped
• The recorded reason distinguishes the lock from max_instances
• Exactly one row per suppressed tick — no duplicate skipped + success pairing (Scheduler creates duplicate execution records (skipped + success) for single trigger #91)
• Suppression behaviour itself unchanged: the schedule still does not run, the lock is still released

Sibling issues

Independent of #1974 (#1970, execution-origin columns) — different hunks in service.py, mergeable in either order. #1968 (execution_id: undefined) is untouched.

Related to #1969

🤖 Generated with Claude Code

[github-actions]

⚠️ Nightly unit-suite check skipped — merge conflict against dev.

Resolve by running git merge dev locally and pushing the result. The next nightly run will re-test once the conflict is gone.

[dolho]

/review — self-review (PR #1975, #1969)

Branch: fix/1969-lock-denied-tick-audit → dev · 3 files, +405
Scope: CLEAN — one call added, its test, its registry entry. This is the smallest of the five.
Plan completion: 4 AC DONE.

[I1] Row cardinality on a chronically-overrunning schedule (Confidence: 7/10)

A schedule whose run outlasts its own cron interval now writes one skipped row per suppressed tick — a 5-minute cron with a 30-minute job produces ~5 rows per run.

I checked this against the sibling before shipping: the max_instances path already writes at exactly this cardinality, so the two stay consistent and the volume is bounded by the schedule's own cadence. Contrast the autonomy-off branch, which deliberately writes nothing — that one is a static config gate on a default-OFF fleet, so a row per tick would flood the table for agents that never intended to run. Different situations, different answers; worth stating because "why does this branch log and that one not" is the obvious review question.

[I2] next_run_at is not advanced on a denied tick (Confidence: 7/10)

The #1472 "receding Next: Nd ago" class. Deliberately not fixed here: the existing max_instances path does not advance it either, and fixing one of the two would reintroduce exactly the asymmetry this PR removes. Flagged in the PR body as its own issue if it bites.

[I3] _record_skipped_agent_schedule calls asyncio.create_task internally (Confidence: 6/10)

Pre-existing, in the helper rather than this diff. The new caller is async so a loop is running (the sync _on_job_max_instances listener is the one on thinner ice). Same weak-reference concern I fixed on #1976 — but here a dropped task loses only a WebSocket broadcast, not a lock or a live row, so it does not carry the same stakes. Not fixed; noted.

Clean categories

• SQL safety — no new SQL; reuses create_skipped_execution.
• Race conditions — the branch is on the denied path, so it holds no lock and touches no shared state.
• Auth — no endpoint change.
• Duplicate rows (Scheduler creates duplicate execution records (skipped + success) for single trigger #91 regression shape) — the two suppression paths are provably mutually exclusive: a max_instances refusal means the job never starts, so _execute_schedule is never entered; reaching the lock branch means it already did. Pinned by a source guard that the listener never routes through _execute_schedule.
• Error handling — the audit helper still swallows its own failures, which is now load-bearing for a second caller on the cron path; pinned by test.

Summary

• Critical: 0
• Informational: 3 — none blocking, two are deliberate non-changes
• Scope: clean

CI: 17 pass / 3 skip, green.

[vybe]

Validated via /validate-pr — textbook narrow fix: exactly the issue's suggested one-call change, 5/12 regression tests fail pre-fix, lock-release + granted-path silence + #91 single-row cardinality all pinned, e2e SQLite row proof. I resolved the tests/registry.json tail conflict (kept #1969 + #1971 entries) and full CI re-ran green. Follow-up worth filing: the identical unaudited lock-denial branch in _execute_process_schedule (out of #1969's scope).