fix(scheduler): audit a lock-denied process-schedule tick (#1994)

[dolho]

Fixes #1994

What

_execute_process_schedule logged at INFO and returned bare when the distributed lock denied a tick, so no process_schedule_executions row was written. A suppressed tick was indistinguishable from a tick that never fired — in the execution history, the UI, and monitoring alike — while APScheduler still reported the job successful.

The exact branch #1975 fixed on the agent-schedule path, surviving on the process-schedule one. Suppression itself is correct: two concurrent runs of one schedule is what the lock exists to prevent. What was missing is the evidence it happened.

Why one added call is enough

The two suppression paths do not overlap, which is also what keeps this from re-creating #91's duplicate skipped + success pairing:

• APScheduler refuses the job (max_instances=1) → EVENT_JOB_MAX_INSTANCES → _on_job_max_instances → a skipped row. The job never starts, so _execute_process_schedule is never entered and no lock is attempted.
• The Redis lock denies the run → this branch. Reaching it means APScheduler already let the job start, so no max-instances event fires.

Exactly one of the two per tick. Pinned by a source-level test, since the two entry points are wired to APScheduler rather than to each other.

The reason string

_record_skipped_process_schedule gains skip_reason / event_reason, for the same reason its agent-schedule sibling did in #1808: the helper hard-coded the max_instances wording, so reusing it as-is would file a lock collision as a max_instances refusal and send anyone debugging it to the wrong mechanism.

The defaults preserve the original wording, so the existing EVENT_JOB_MAX_INSTANCES caller — which is otherwise untouched — behaves identically. There is a test asserting exactly that, because parameterising a shared helper is only safe if the caller that did not change keeps its old behaviour.

Tests

tests/unit/test_1994_process_schedule_lock_audit.py — 14 tests, structured to mirror test_1969_lock_denied_tick_audit.py so the two paths stay reviewable side by side.

The defect, and the halves that must not move:

• a denied tick records exactly one row (and three denials record three)
• the reason names the lock, not max_instances
• the denial does not run the schedule — auditing a suppression must not undo it
• the happy path stays silent; a skipped row on every successful tick would invert the meaning of the status for every consumer of the history
• the lock is released on both success and raise, and .release() is never called on None
• the lock key stays process_{id}, deliberately distinct from the agent path's bare {id} — the new call sits directly under it, and a namespace slip would make an agent schedule and a process schedule with the same id contend for one lock
• the audit helper still swallows its own exceptions, now load-bearing for a second caller on the cron path
• the max_instances caller keeps the original wording

Plus one end-to-end case against a real SQLite file: a denied tick lands a status='skipped' row carrying the right schedule/process ids and a lock-shaped error. Every other assertion proves the branch calls the helper; this proves a row an operator can actually see turns up. Schema comes from the shipped ensure_process_schedules_table() rather than hand-written DDL, so it cannot drift from production.

src/scheduler is a standalone package that cannot import the backend, so the service is driven directly with an injected fake DB and lock manager — SchedulerService.__init__ takes both by injection, so nothing reaches Redis.

tests/unit/test_1994_process_schedule_lock_audit.py   14 passed
  + test_1969_lock_denied_tick_audit.py               26 passed
  + scheduler_tests/test_skipped_executions.py        38 passed
lint_sys_modules.py                                   no new violations

Mutation check. Reverting only src/scheduler/service.py fails 6 of 14, including the end-to-end row test.

Scope

One branch, one helper signature, one new test file. No schema change, no migration, no new endpoint, no config.

🤖 Generated with Claude Code

[dolho]

Verified against the real instance

Real scheduler image built from this branch (docker/scheduler/Dockerfile — so this also proves the change packages and imports, the #1033 class), run against the instance's real PostgreSQL with a genuinely contended Redis lock held by a second LockManager.

Setup, and two deliberate choices

The branch was reached by calling it directly, not by arming APScheduler. SchedulerService.initialize() against the live DB would register and fire the instance's real schedules. _execute_process_schedule() is exactly what a cron tick invokes once the job is running, so calling it is the same code path without the blast radius.

The lock is really contended. A second LockManager over the same Redis takes process_{id} first; the run under test then gets None from a real acquire(blocking=False). The script asserts that denial before proceeding, so the test cannot pass vacuously against a lock that was never held.

I did not start the instance's own Redis. trinity-redis/trinity-backend have been down ~37h and trinity-scheduler is crash-looping on the missing Redis with restart: unless-stopped — starting it would have let that scheduler connect and fire real schedules with the backend down. Used a dedicated redis:7-alpine (same image as the stack) instead. The instance's scheduler was never woken; verified restarting before and after.

A/B on the real database

Same script, same Redis, same live Postgres — only the image differs.

image	rows in process_schedule_executions
built from origin/dev (unfixed)	0 — the bug: the tick vanished
built from fix/1994-…	1

[holder] acquired process___test-1994-lock-audit: True
[tick]   second acquire returns: None (None == genuinely denied)
[tick]   _execute_process_schedule returned

The row, straight out of Postgres:

 schedule_id            | process_id       | process_name     | status  | triggered_by | duration_ms | error
------------------------+------------------+------------------+---------+--------------+-------------+---------------------------------------------------------
 __test-1994-lock-audit | __test-1994-proc | test-1994-rollup | skipped | schedule     |           0 | Previous execution still running (distributed lock held)

The untouched caller keeps its wording

Invoked exactly as _on_job_max_instances does — positional id, no reason overrides — against the same live DB:

 status  | error
---------+----------------------------------------------------------
 skipped | Previous execution still running (max_instances reached)

So the two suppression causes are distinguishable in the real execution history, and parameterising the shared helper did not change the caller that did not change.

Footprint

Both process_schedules and process_schedule_executions were empty on this instance before the test and are empty again after — worth stating plainly: process schedules are an unused surface here, so this P3 is a latent-audit-gap fix, not one with observed production impact.

Created and then removed: one __test-1994-* schedule row, its execution rows, a throwaway Redis container, two test images, and a detached control worktree. Nothing pre-existing was read-modified or deleted.

[vybe]

Scoped to one branch on the process-schedule path, mirroring #1969's fix on the agent-schedule path.

The load-bearing argument — that the max_instances refusal and the lock denial are mutually exclusive per tick, so calling the shared helper from both cannot re-create #91's duplicate skipped+success pairing — is correct and, better, pinned by a source-level test rather than asserted in prose.

Parameterising _record_skipped_process_schedule is the right call over hard-coding a second wording, and the defaults preserve the untouched EVENT_JOB_MAX_INSTANCES caller's behaviour with a test asserting exactly that. The end-to-end SQLite case builds its schema from the shipped ensure_process_schedules_table(), so it cannot drift from production.

Body patched to Fixes #1994 so the issue auto-promotes to status-in-dev on merge.