Repository navigation
bug: cron tick suppressed by distributed lock leaves no execution record #1969
Description
Summary
When a cron tick is suppressed by the Redis distributed lock because the same schedule is already running, _execute_schedule() logs at INFO and returns without writing anything. No schedule_executions row is created, so the suppressed tick is invisible in execution history, the UI and monitoring — it looks exactly as if the tick never fired. Trinity already records this situation correctly for the other suppression path (APScheduler max_instances), so this is a missing call rather than a design gap.
Component
Scheduler
Priority
P2 — no execution is lost incorrectly (suppression is the right behaviour); what is lost is the audit trail that it happened.
Error
Only trace left behind, at INFO:
[INFO] scheduler.service: Schedule {schedule_id} already being executed by another instance
No corresponding row in schedule_executions. APScheduler still marks the job successful and advances next_run_at to the following occurrence.
Location
- File:
src/scheduler/service.py - Line: 809–822 —
_execute_schedule(), lock-denial branch - Function:
_execute_schedule()
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 recordedRoot Cause
There are two independent ways a schedule run can be suppressed, and only one of them is audited:
| Path | Mechanism | Audited? |
|---|---|---|
| APScheduler refuses the job | max_instances=1 → EVENT_JOB_MAX_INSTANCES → _on_job_max_instances() → _record_skipped_agent_schedule() |
✅ writes a status='skipped' row + publishes schedule_execution_skipped |
| Redis distributed lock denies the run | _execute_schedule() lock-denial branch |
❌ bare return |
These do not overlap. A manual trigger bypasses APScheduler entirely — _trigger_handler() runs the execution via asyncio.create_task, so APScheduler's per-job instance counter never sees it. When the cron tick for that same schedule then fires, APScheduler happily starts the job (its max_instances counter is zero), and the collision is caught one layer down by the Redis lock — precisely the branch that records nothing.
So the common real-world case, manual trigger shortly before the scheduled time, is the one case that produces no audit record at all.
Reproduction Steps
- Create an agent schedule whose cron fires at a known time.
- Shortly before that time, trigger the same schedule manually (MCP
trigger_agent_schedule, or the backend trigger endpoint), so the manual run is still in flight when the cron time arrives. - Wait for the cron tick.
- Observe: scheduler logs
already being executed by another instance; the APScheduler job is reported executed successfully andnext_run_atadvances. - Query
schedule_executionsfor that schedule — only the manual run is present. The suppressed cron tick has no row.
Suggested Fix
Call the existing audit helper from the lock-denial branch. _record_skipped_agent_schedule() was already parameterised in #1808 so additional callers can supply their own wording, so this needs no new machinery:
# src/scheduler/service.py — _execute_schedule()
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")
self._record_skipped_agent_schedule(
schedule_id,
skip_reason="Previous execution still running (distributed lock held)",
event_reason="Previous execution still running",
)
returnThis yields the same status='skipped' row and schedule_execution_skipped WebSocket event the max_instances path already produces, making the two suppression paths consistent.
Worth confirming in review that a manual run colliding with its own cron tick produces exactly one skipped row and not a duplicate — #91 (closed) covered a duplicate skipped+success pairing in a different flow, and the fix should not reintroduce that shape.
Environment
- Observed on a deployed instance running
1d3863d5 - Confirmed still present at
4d743fdb(2026-07-27) — the lock-denial branch is byte-identical
Related
src/scheduler/service.py—_execute_schedule(),_on_job_max_instances(),_record_skipped_agent_schedule()- freeze_schedules_if_sync_failing is never enforced — schedules keep firing while sync is failing (safety toggle is inert) #1808 — parameterised
_record_skipped_agent_schedule()for reuse by the sync-freeze gate - Scheduler creates duplicate execution records (skipped + success) for single trigger #91 (closed) — duplicate skipped + success records for a single trigger; regression to avoid
- Sibling gaps in the same manual-trigger path filed separately (undefined
execution_id; unpopulated origin columns)
Activity
vybe commentedon Aug 3, 2026
Prior art — this is the unfinished half of #1472
#1472 (closed 2026-07-08) enumerated several paths where a cron fire passes with no record and no advance, and its point 2 was exactly this branch:
The fix that closed #1472 addressed the autonomy-disabled path (point 1) via a new
_advance_next_run_only()helper, but the lock-contention branch was not touched. At4d743fdb,_advance_next_run_only()has exactly two callers — the autonomy gate and the #1808 git-sync freeze gate — and_execute_schedule()'s lock-denial branch is still a barelogger.info(...)+return.Why this path should record a row, unlike the autonomy gate
Worth flagging because #1472's fix made a deliberate decision not to write a row for the autonomy skip, and that reasoning should not be applied here by analogy. From the in-code comment:
That reasoning is sound and specific to a static config gate: autonomy-off is a steady state, so every tick would emit an identical row forever.
Lock contention is the opposite — it is a genuine per-fire event, rare, caused by a real overlap between two runs, and it is the case an operator most wants to see in history. Trinity already treats the sibling overlap case this way: APScheduler's
max_instancesrefusal writes astatus='skipped'row through_record_skipped_agent_schedule(). Recording here makes the two overlap paths consistent rather than adding steady-state noise.Note also that the
max_instancesaudit does not cover the common real-world trigger for this branch: a manual trigger runs viaasyncio.create_taskfrom_trigger_handler()and never enters APScheduler, so APScheduler's instance counter reads zero and starts the cron job normally — the collision is caught one layer down by the Redis lock, i.e. the unaudited branch.dolho commentedon Aug 4, 2026
/claim — picking this up. Branch:
fix/1969-lock-denied-tick-audit(stacked on #1974 / #1970, same file).github-actions commentedon Aug 4, 2026
@dolho This issue is already assigned to dolho. Use
/unclaimfirst if you want to take over.dolho commentedon Aug 4, 2026
PR: #1975
Correction to my claim note above: this is not stacked on #1974 — it branches off
devindependently. The two touch different hunks ofsrc/scheduler/service.pyand merge in either order.Merge origin/dev into fix/1969-lock-denied-tick-audit (resolve tests/…
fix(scheduler): audit a tick suppressed by the distributed lock (#1969)…
vybe commentedon Aug 4, 2026
Fixed by #1975, merged to dev 2026-08-04. The PR body lacked a closing keyword so status didn't auto-promote — bumped manually. Needs manual close at release. Sibling gap filed as #1994 (_execute_process_schedule).
fix(scheduler): audit a lock-denied process-schedule tick (#1994) (#2039
refactor(scheduler): remove the process-schedule remnant from the sch…
refactor(scheduler): remove the process-schedule remnant (#3432) (#3440)