jpmschweitzer/scheduler
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 5 Wiki Activity

fix(orchestrator): record the terminal states that were never written

Browse Source 
Two defects with one shape: an execution reaches a terminal condition and the
orchestrator fails to write it down, so the system's own record disagrees with
what happened. Neither produced an error. Both produced silence.

T-2 -- a restart mid-task unscheduled that task forever.

get_tasks_for_minute excludes any task holding a task_executions row with
status='running'. The row is written before the executor runs and updated
after, so a process dying in between left it 'running' permanently, and the
task was then excluded from every future minute with no error, no alarm and no
log line. It did not fail; it went quiet.

test_example_task had held such a row since 2025-12-07 -- 5916 hours. It is
disabled, so nothing was broken by that instance; the mechanism is the point,
and the exposure is daily, because Watchtower restarts this container at 4 AM
while the config backup starts at 03:05 and runs ~21 minutes.

Startup now reconciles them, where the reasoning is sound by construction: this
process has just begun, so nothing it can see is genuinely running.

Marked 'orphaned', not 'failed'. When the process dies mid-task the work may
well have completed -- a backup that finished and never got to update its row
is indistinguishable from one that died halfway -- and 'failed' would assert an
outcome nobody observed. Same error as the health-report diagnostic fixed in
18be804: naming a cause you did not witness.

Not extended to a duration-based sweep. While this process lives, execute_task's
finally clause always closes the row, so a stale row implies a dead owner. A
time-based rule would have to tell a slow task from a dead one, and getting that
wrong closes the record of a task still working.

T-3 -- the 'timeout' status was unreachable.

execute_task has an `except asyncio.TimeoutError` branch that records
status='timeout'. It could never run: _run_executor wrapped the awaited call in
`except Exception`, and since 3.11 asyncio.TimeoutError IS the builtin
TimeoutError (OSError -> Exception), so the broad handler caught it first and
converted it to an ordinary error tuple. Confirmed in the deployed runtime and
against the history -- 18,785 executions since 2025-12-07, of which 'timeout'
rows: zero. Every timeout in eight months was filed as a generic failure,
erasing the distinction between "too slow for its window" and "broken".

A narrower except after a broader one is dead code, and no linter is configured
here to say so.

One trap in fixing it: while the branch was unreachable a timeout travelled the
normal path, which DOES update scheduled_tasks. Making the branch reachable
without that write would have traded a wrong status for a stale one, so
_update_task_outcome now mirrors terminal outcomes onto the parent row.

The timeout message also states that the work may still be running -- after
T-74 executors are handed to asyncio.to_thread, and a thread cannot be
cancelled, so wait_for frees the loop while the work continues.

Both fixes are mutation-checked: removing the startup call fails the ordering
test, removing the narrow except clause fails the propagation test. Suite goes
118 -> 126 passing with the same 36 pre-existing failures.

Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
jpmschweitzer
2026-08-11 12:09:35 +02:00
co-authored by Claude
parent d91d0f2c63
commit e45de4fec7
6 changed files with 401 additions and 2 deletions
Download Patch File Download Diff File Expand all files Collapse all files
.pql/changelog/ticket_history/2026-08.sql
+47
View File
@@ -0,0 +1,47 @@
INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0FHPBBXXKBRWGR3FJZRK58', 'description', NULL, 'DELETE /tasks/{task_name} returns 500 whenever the task has at least one row in task_executions:
psycopg2.errors.ForeignKeyViolation: update or delete on table "scheduled_tasks"
violates foreign key constraint "task_executions_task_id_fkey" on table "task_executions"
DETAIL: Key (id)=(46) is still referenced from table "task_executions".
src/main.py:355. Since every task that has ever fired has execution history, the endpoint works only for tasks that have never run — which is close to none of them. Found on 2026-08-11 while cleaning up a temporary probe task created for T-74; it had to be removed with hand-written SQL against two tables, which is not something the API should require.
The caller gets a bare "Internal Server Error" with no indication that history is the obstacle, so it reads as the service being broken rather than the request being refusable.
Deciding what delete should MEAN is the actual work here, and it should not be guessed:
- cascade — drop the execution history with the task. Simple, and silently destroys the audit trail for a task someone deletes by mistake.
- soft delete — mark it deleted and keep the history. Keeps the audit trail, adds a state every query then has to filter on.
- refuse with 409 and a real message ("task has N executions; pass ?purge=true"). Explicit, and makes the destructive variant a deliberate act.
The third is the smallest correct change and matches how the rest of this system treats destructive operations. Whichever is chosen, a 500 on a foreseeable, well-defined condition is the part that is simply wrong.', NULL, '2026-08-11 09:53:56', '2026-08-11 09:53:56.969', '2026-08-11 09:53:56.969', NULL, '8b2dfce5342a7cd89bbe6d04c03157f1', 2) ON CONFLICT(hash) DO NOTHING;
INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0GQAR5KXM3PTG0QT3R1PV8', 'description', NULL, 'get_tasks_for_minute (src/tasks/executor.py:70) excludes any task holding a task_executions row with status=''running'':
AND id NOT IN (SELECT task_id FROM task_executions WHERE status = ''running'')
Nothing ever reconciles that row. It is written before the executor runs and updated after, so a process that dies in between leaves it ''running'' permanently — and the task is then excluded from every future minute, forever, with no error, no alarm and no log line. The task simply stops existing as far as the scheduler is concerned.
This is not hypothetical. test_example_task has held a ''running'' row since 2025-12-07 — 5916 hours. It happens to be disabled, so nothing is broken today; the mechanism is what matters, not this instance.
The exposure is real and daily: Watchtower restarts this container every morning at 4 AM. Any task still running at that moment is permanently unscheduled by it. The config backup runs 03:05 and takes ~21 minutes, which is not far off.
The failure mode is the one this system keeps producing: it looks like nothing. A backup that stops running forever produces no failure — it produces silence, and silence reads as health.
FIX: reconcile at startup. Any row left ''running'' when the process starts cannot be running, because the process that owned it is gone. Mark those ''orphaned'' (or ''failed'' with a message naming the restart) during app startup, before the scheduler begins its first minute. Consider also a stale-row guard for rows older than the task''s timeout_seconds, which covers a killed worker without a restart.
The audit trail is preserved either way — this is a status correction, not a deletion.', NULL, '2026-08-11 09:59:05', '2026-08-11 09:59:05.288', '2026-08-11 09:59:05.288', NULL, '1b14bc4af4acc6df0dc2d21675edf31f', 2) ON CONFLICT(hash) DO NOTHING;
INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0GQBTCRCTXK6EJF0T8CS2C', 'description', NULL, 'execute_task has an `except asyncio.TimeoutError` handler (src/tasks/executor.py:179) that records status=''timeout''. It can never run.
_run_executor wraps the awaited call in `except Exception` (line 219) and returns the error as a value. Since Python 3.11 asyncio.TimeoutError IS the builtin TimeoutError, which inherits OSError -> Exception, so the broad handler catches it first and converts it into an ordinary (None, error) tuple. execute_task then sees a non-None error and files status=''failed''.
Verified in the deployed runtime:
asyncio.TimeoutError is TimeoutError: True
MRO: TimeoutError -> OSError -> Exception -> BaseException
And confirmed against 8 months of history — 18,785 executions, and the count of status=''timeout'' rows is zero:
success 16690 | failed 2093 | running 2 | timeout 0
So every timeout since 2025-12-07 has been recorded as a generic failure carrying a traceback. Operationally that erases the distinction that matters most when a job misbehaves: "this job is too slow for its window" and "this job is broken" need different responses, and right now they look identical in the history.
FIX: catch asyncio.TimeoutError explicitly in _run_executor, ahead of the broad handler, and let it propagate (or return a marker execute_task can distinguish). Note the ordering is the whole bug — a narrower except after a broader one is dead code, and there is no linter configured here to say so.
Related: a thread started by asyncio.to_thread cannot be cancelled, so after T-74 a timeout frees the loop while the work continues to completion. Whatever ''timeout'' comes to mean should say so rather than implying the work stopped.', NULL, '2026-08-11 09:59:05', '2026-08-11 09:59:05.545', '2026-08-11 09:59:05.545', NULL, 'af08842306d6326036b1865b8cbf7c58', 2) ON CONFLICT(hash) DO NOTHING;
.pql/changelog/ticket_idmap/2026-08.sql
+3
View File
@@ -0,0 +1,3 @@
INSERT INTO ticket_idmap (record_id, ticket_id, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0FHPBBXXKBRWGR3FJZRK58', 'T-1', '2026-08-11 09:53:56.835', '2026-08-11 09:53:56.835', NULL, '3d980945e785a6bc7ca8fcaa8250e22b', 2) ON CONFLICT(record_id) DO UPDATE SET ticket_id=excluded.ticket_id, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= ticket_idmap.updated_at;
INSERT INTO ticket_idmap (record_id, ticket_id, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0GQAR5KXM3PTG0QT3R1PV8', 'T-2', '2026-08-11 09:59:05.153', '2026-08-11 09:59:05.153', NULL, 'c8655ec9601ba93fe822395329e62262', 2) ON CONFLICT(record_id) DO UPDATE SET ticket_id=excluded.ticket_id, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= ticket_idmap.updated_at;
INSERT INTO ticket_idmap (record_id, ticket_id, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0GQBTCRCTXK6EJF0T8CS2C', 'T-3', '2026-08-11 09:59:05.427', '2026-08-11 09:59:05.427', NULL, '3bce28c3d803d3f5036cfbb1ac11969c', 2) ON CONFLICT(record_id) DO UPDATE SET ticket_id=excluded.ticket_id, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= ticket_idmap.updated_at;
.pql/changelog/tickets/2026-08.sql
+50
View File
@@ -0,0 +1,50 @@
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0FHPBBXXKBRWGR3FJZRK58', 'bug', NULL, 'DELETE /tasks/{name} 500s for any task that has ever run', NULL, 'backlog', 'high', NULL, NULL, NULL, '2026-08-11 09:53:56.826', '2026-08-11 09:53:56.826', NULL, '86310746d98f53b722c7336b0bab980a', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0FHPBBXXKBRWGR3FJZRK58', 'bug', NULL, 'DELETE /tasks/{name} 500s for any task that has ever run', 'DELETE /tasks/{task_name} returns 500 whenever the task has at least one row in task_executions:
psycopg2.errors.ForeignKeyViolation: update or delete on table "scheduled_tasks"
violates foreign key constraint "task_executions_task_id_fkey" on table "task_executions"
DETAIL: Key (id)=(46) is still referenced from table "task_executions".
src/main.py:355. Since every task that has ever fired has execution history, the endpoint works only for tasks that have never run — which is close to none of them. Found on 2026-08-11 while cleaning up a temporary probe task created for T-74; it had to be removed with hand-written SQL against two tables, which is not something the API should require.
The caller gets a bare "Internal Server Error" with no indication that history is the obstacle, so it reads as the service being broken rather than the request being refusable.
Deciding what delete should MEAN is the actual work here, and it should not be guessed:
- cascade — drop the execution history with the task. Simple, and silently destroys the audit trail for a task someone deletes by mistake.
- soft delete — mark it deleted and keep the history. Keeps the audit trail, adds a state every query then has to filter on.
- refuse with 409 and a real message ("task has N executions; pass ?purge=true"). Explicit, and makes the destructive variant a deliberate act.
The third is the smallest correct change and matches how the rest of this system treats destructive operations. Whichever is chosen, a 500 on a foreseeable, well-defined condition is the part that is simply wrong.', 'backlog', 'high', NULL, NULL, NULL, '2026-08-11 09:53:56.826', '2026-08-11 09:53:56.969', NULL, '248bb53ca2bae0f12fabd9d88a1ca171', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0GQAR5KXM3PTG0QT3R1PV8', 'bug', NULL, 'A restart mid-task unschedules that task forever, silently', NULL, 'backlog', 'high', NULL, NULL, NULL, '2026-08-11 09:59:05.153', '2026-08-11 09:59:05.153', NULL, '0bda80455ba51ea4cb0cb91e302ac216', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0GQAR5KXM3PTG0QT3R1PV8', 'bug', NULL, 'A restart mid-task unschedules that task forever, silently', 'get_tasks_for_minute (src/tasks/executor.py:70) excludes any task holding a task_executions row with status=''running'':
AND id NOT IN (SELECT task_id FROM task_executions WHERE status = ''running'')
Nothing ever reconciles that row. It is written before the executor runs and updated after, so a process that dies in between leaves it ''running'' permanently — and the task is then excluded from every future minute, forever, with no error, no alarm and no log line. The task simply stops existing as far as the scheduler is concerned.
This is not hypothetical. test_example_task has held a ''running'' row since 2025-12-07 — 5916 hours. It happens to be disabled, so nothing is broken today; the mechanism is what matters, not this instance.
The exposure is real and daily: Watchtower restarts this container every morning at 4 AM. Any task still running at that moment is permanently unscheduled by it. The config backup runs 03:05 and takes ~21 minutes, which is not far off.
The failure mode is the one this system keeps producing: it looks like nothing. A backup that stops running forever produces no failure — it produces silence, and silence reads as health.
FIX: reconcile at startup. Any row left ''running'' when the process starts cannot be running, because the process that owned it is gone. Mark those ''orphaned'' (or ''failed'' with a message naming the restart) during app startup, before the scheduler begins its first minute. Consider also a stale-row guard for rows older than the task''s timeout_seconds, which covers a killed worker without a restart.
The audit trail is preserved either way — this is a status correction, not a deletion.', 'backlog', 'high', NULL, NULL, NULL, '2026-08-11 09:59:05.153', '2026-08-11 09:59:05.288', NULL, '23a72bff9ffc3592c796741df8a7232e', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0GQBTCRCTXK6EJF0T8CS2C', 'bug', NULL, 'The ''timeout'' execution status is unreachable; timeouts are filed as generic failures', NULL, 'backlog', 'medium', NULL, NULL, NULL, '2026-08-11 09:59:05.427', '2026-08-11 09:59:05.427', NULL, '31a32d6dce87263657892d48552d1f0a', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06FZ0GQBTCRCTXK6EJF0T8CS2C', 'bug', NULL, 'The ''timeout'' execution status is unreachable; timeouts are filed as generic failures', 'execute_task has an `except asyncio.TimeoutError` handler (src/tasks/executor.py:179) that records status=''timeout''. It can never run.
_run_executor wraps the awaited call in `except Exception` (line 219) and returns the error as a value. Since Python 3.11 asyncio.TimeoutError IS the builtin TimeoutError, which inherits OSError -> Exception, so the broad handler catches it first and converts it into an ordinary (None, error) tuple. execute_task then sees a non-None error and files status=''failed''.
Verified in the deployed runtime:
asyncio.TimeoutError is TimeoutError: True
MRO: TimeoutError -> OSError -> Exception -> BaseException
And confirmed against 8 months of history — 18,785 executions, and the count of status=''timeout'' rows is zero:
success 16690 | failed 2093 | running 2 | timeout 0
So every timeout since 2025-12-07 has been recorded as a generic failure carrying a traceback. Operationally that erases the distinction that matters most when a job misbehaves: "this job is too slow for its window" and "this job is broken" need different responses, and right now they look identical in the history.
FIX: catch asyncio.TimeoutError explicitly in _run_executor, ahead of the broad handler, and let it propagate (or return a marker execute_task can distinguish). Note the ordering is the whole bug — a narrower except after a broader one is dead code, and there is no linter configured here to say so.
Related: a thread started by asyncio.to_thread cannot be cancelled, so after T-74 a timeout frees the loop while the work continues to completion. Whatever ''timeout'' comes to mean should say so rather than implying the work stopped.', 'backlog', 'medium', NULL, NULL, NULL, '2026-08-11 09:59:05.427', '2026-08-11 09:59:05.545', NULL, 'ae0db866086e38b681b0ea32837df277', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;