Compare commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
4911c94e48 | ||
|
|
538bfe5944 |
@@ -45,3 +45,89 @@ So every timeout since 2025-12-07 has been recorded as a generic failure carryin
|
||||
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;
|
||||
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', '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.', '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.
|
||||
|
||||
FIXED in v1.6.0 (e45de4f). TaskExecutor.reconcile_orphaned_executions() runs in the lifespan before the scheduler starts.
|
||||
|
||||
Proven on the real system rather than in a test. The row that had been ''running'' since 2025-12-07 22:44 was released at startup:
|
||||
|
||||
WARNING - Orphaned execution recovered: test_example_task was left ''running''
|
||||
since 2025-12-07 22:44:00.046695. That task had been excluded from
|
||||
scheduling until now.
|
||||
|
||||
Rows still ''running'' afterwards: 0. Status is ''orphaned'', error names the restart.
|
||||
|
||||
''orphaned'' rather than ''failed'' because the outcome is genuinely unknown — a task that completed and never got to update its row looks exactly like one that died halfway, and ''failed'' would assert something nobody observed.
|
||||
|
||||
Ordering is part of the fix and is mutation-checked: reconciliation must complete before the first minute is processed, or the first tick still sees the stale rows. Removing the startup call fails the test.
|
||||
|
||||
Not extended to a duration-based sweep, deliberately. While the process lives, execute_task''s finally always closes the row out, so a stale row implies a dead owner; a time-based rule would have to distinguish a slow task from a dead one and would eventually close the record of a task that is still working.', NULL, '2026-08-11 10:11:39', '2026-08-11 10:11:39.058', '2026-08-11 10:11:39.058', NULL, '0cec030639664cf075a113be75218e8d', 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', 'status', 'backlog', 'done', NULL, '2026-08-11 10:11:39', '2026-08-11 10:11:39.178', '2026-08-11 10:11:39.178', NULL, 'cd26a078365d91d44e6d284e80da39f5', 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', '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.', '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.
|
||||
|
||||
FIXED in v1.6.0 (e45de4f). _run_executor now catches asyncio.TimeoutError ahead of the broad handler and re-raises, so execute_task''s timeout branch is reachable for the first time.
|
||||
|
||||
A trap surfaced while fixing it, and it is the interesting part. While the branch was unreachable, a timeout travelled the NORMAL path — which does update scheduled_tasks. Making the branch reachable without adding that write would have swapped a wrong status (''failed'') for a stale one (last_status showing the previous run''s outcome indefinitely). _update_task_outcome now mirrors terminal outcomes onto the parent row. A fix that repairs the reported symptom while breaking something adjacent is worse than the bug.
|
||||
|
||||
The timeout message also records 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 to completion. Saying "timed out" without that would imply the work stopped.
|
||||
|
||||
Mutation-checked: removing the narrow except clause fails the propagation test. A third test pins that ordinary exceptions are still returned rather than raised, so the narrow clause cannot start swallowing anything else.', NULL, '2026-08-11 10:11:39', '2026-08-11 10:11:39.291', '2026-08-11 10:11:39.291', NULL, '8bdb93fdcfbc234e18f3d034ddf25277', 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', 'status', 'backlog', 'done', NULL, '2026-08-11 10:11:39', '2026-08-11 10:11:39.421', '2026-08-11 10:11:39.421', NULL, '7bc24ec03ed40ccacd71d7c7269d05af', 2) ON CONFLICT(hash) DO NOTHING;
|
||||
|
||||
@@ -48,3 +48,113 @@ So every timeout since 2025-12-07 has been recorded as a generic failure carryin
|
||||
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;
|
||||
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.
|
||||
|
||||
FIXED in v1.6.0 (e45de4f). TaskExecutor.reconcile_orphaned_executions() runs in the lifespan before the scheduler starts.
|
||||
|
||||
Proven on the real system rather than in a test. The row that had been ''running'' since 2025-12-07 22:44 was released at startup:
|
||||
|
||||
WARNING - Orphaned execution recovered: test_example_task was left ''running''
|
||||
since 2025-12-07 22:44:00.046695. That task had been excluded from
|
||||
scheduling until now.
|
||||
|
||||
Rows still ''running'' afterwards: 0. Status is ''orphaned'', error names the restart.
|
||||
|
||||
''orphaned'' rather than ''failed'' because the outcome is genuinely unknown — a task that completed and never got to update its row looks exactly like one that died halfway, and ''failed'' would assert something nobody observed.
|
||||
|
||||
Ordering is part of the fix and is mutation-checked: reconciliation must complete before the first minute is processed, or the first tick still sees the stale rows. Removing the startup call fails the test.
|
||||
|
||||
Not extended to a duration-based sweep, deliberately. While the process lives, execute_task''s finally always closes the row out, so a stale row implies a dead owner; a time-based rule would have to distinguish a slow task from a dead one and would eventually close the record of a task that is still working.', 'backlog', 'high', NULL, NULL, NULL, '2026-08-11 09:59:05.153', '2026-08-11 10:11:39.058', NULL, '8d88d4684f803319131765d97772e64d', 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.
|
||||
|
||||
FIXED in v1.6.0 (e45de4f). TaskExecutor.reconcile_orphaned_executions() runs in the lifespan before the scheduler starts.
|
||||
|
||||
Proven on the real system rather than in a test. The row that had been ''running'' since 2025-12-07 22:44 was released at startup:
|
||||
|
||||
WARNING - Orphaned execution recovered: test_example_task was left ''running''
|
||||
since 2025-12-07 22:44:00.046695. That task had been excluded from
|
||||
scheduling until now.
|
||||
|
||||
Rows still ''running'' afterwards: 0. Status is ''orphaned'', error names the restart.
|
||||
|
||||
''orphaned'' rather than ''failed'' because the outcome is genuinely unknown — a task that completed and never got to update its row looks exactly like one that died halfway, and ''failed'' would assert something nobody observed.
|
||||
|
||||
Ordering is part of the fix and is mutation-checked: reconciliation must complete before the first minute is processed, or the first tick still sees the stale rows. Removing the startup call fails the test.
|
||||
|
||||
Not extended to a duration-based sweep, deliberately. While the process lives, execute_task''s finally always closes the row out, so a stale row implies a dead owner; a time-based rule would have to distinguish a slow task from a dead one and would eventually close the record of a task that is still working.', 'done', 'high', NULL, NULL, NULL, '2026-08-11 09:59:05.153', '2026-08-11 10:11:39.177', NULL, '99284d5f4a53a35637ee10c7b6b66c6e', 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.
|
||||
|
||||
FIXED in v1.6.0 (e45de4f). _run_executor now catches asyncio.TimeoutError ahead of the broad handler and re-raises, so execute_task''s timeout branch is reachable for the first time.
|
||||
|
||||
A trap surfaced while fixing it, and it is the interesting part. While the branch was unreachable, a timeout travelled the NORMAL path — which does update scheduled_tasks. Making the branch reachable without adding that write would have swapped a wrong status (''failed'') for a stale one (last_status showing the previous run''s outcome indefinitely). _update_task_outcome now mirrors terminal outcomes onto the parent row. A fix that repairs the reported symptom while breaking something adjacent is worse than the bug.
|
||||
|
||||
The timeout message also records 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 to completion. Saying "timed out" without that would imply the work stopped.
|
||||
|
||||
Mutation-checked: removing the narrow except clause fails the propagation test. A third test pins that ordinary exceptions are still returned rather than raised, so the narrow clause cannot start swallowing anything else.', 'backlog', 'medium', NULL, NULL, NULL, '2026-08-11 09:59:05.427', '2026-08-11 10:11:39.291', NULL, 'b7379fa662b40c6996f17c36b64010c0', 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.
|
||||
|
||||
FIXED in v1.6.0 (e45de4f). _run_executor now catches asyncio.TimeoutError ahead of the broad handler and re-raises, so execute_task''s timeout branch is reachable for the first time.
|
||||
|
||||
A trap surfaced while fixing it, and it is the interesting part. While the branch was unreachable, a timeout travelled the NORMAL path — which does update scheduled_tasks. Making the branch reachable without adding that write would have swapped a wrong status (''failed'') for a stale one (last_status showing the previous run''s outcome indefinitely). _update_task_outcome now mirrors terminal outcomes onto the parent row. A fix that repairs the reported symptom while breaking something adjacent is worse than the bug.
|
||||
|
||||
The timeout message also records 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 to completion. Saying "timed out" without that would imply the work stopped.
|
||||
|
||||
Mutation-checked: removing the narrow except clause fails the propagation test. A third test pins that ordinary exceptions are still returned rather than raised, so the narrow clause cannot start swallowing anything else.', 'done', 'medium', NULL, NULL, NULL, '2026-08-11 09:59:05.427', '2026-08-11 10:11:39.420', NULL, '333edb040cfa995cf26f45b6fa2cd2f9', 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;
|
||||
|
||||
@@ -6,6 +6,13 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
|
||||
|
||||
## [Unreleased]
|
||||
|
||||
## [1.7.0] - 2026-08-11
|
||||
|
||||
### Added
|
||||
- `check_history` rows name the scheduled task that produced them. `source` names the code,
|
||||
which cannot distinguish two tasks sharing one executor — so a failure could not be
|
||||
attributed to the job that caused it. Omitted when there is no task.
|
||||
|
||||
## [1.6.0] - 2026-08-11
|
||||
|
||||
### Fixed
|
||||
|
||||
@@ -9,7 +9,7 @@ It is the homelab's cron. Recurring work belongs here rather than in a systemd t
|
||||
|
||||
## Live contract
|
||||
|
||||
`http://localhost:8090/openapi.json` — 10 paths, `version: 1.6.0` (verified 2026-08-11). Human
|
||||
`http://localhost:8090/openapi.json` — 10 paths, `version: 1.7.0` (verified 2026-08-11). Human
|
||||
docs at `/docs`. Generated from running code, so read it instead of inferring routes.
|
||||
|
||||
**Every route except `/health` requires `Authorization: Bearer $SCHEDULER_API_KEY`.** An
|
||||
|
||||
+1
-1
@@ -1,6 +1,6 @@
|
||||
[project]
|
||||
name = "the-scheduler"
|
||||
version = "1.6.0"
|
||||
version = "1.7.0"
|
||||
description = "System-wide maintenance orchestration - backups, doc mirroring, cleanup, task automation"
|
||||
readme = "README.md"
|
||||
requires-python = ">=3.12"
|
||||
|
||||
@@ -20,6 +20,11 @@ Three consequences that are load-bearing here:
|
||||
|
||||
- `source` names the producer, because the table now has several writers and a
|
||||
row must say which one wrote it.
|
||||
- `task` names the schedule that invoked it, which `source` cannot: two tasks
|
||||
may share one executor. On 2026-08-11 two did, and their rows were identical
|
||||
apart from their contents — a failure could not be attributed to either. It
|
||||
comes from a ContextVar the engine sets (`src/task_context.py`), so executors
|
||||
need no signature change and dormant ones stay valid.
|
||||
- `domain` is a shared namespace. Two producers claiming one name would
|
||||
interleave silently.
|
||||
- **A reporting failure must never fail the task.** Backing up successfully and
|
||||
@@ -36,6 +41,8 @@ from typing import Any, Dict, Optional
|
||||
|
||||
import psycopg2
|
||||
|
||||
from src.task_context import current_task_name
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
# The database holding check_history. Not the scheduler's own database — this is
|
||||
@@ -61,6 +68,7 @@ def report(
|
||||
"""
|
||||
metrics = metrics or {}
|
||||
now = datetime.now(timezone.utc)
|
||||
task = current_task_name()
|
||||
result = {
|
||||
# The envelope the table has carried since the shell era. A reader of a
|
||||
# year of history should not have to know which producer wrote a row in
|
||||
@@ -71,6 +79,14 @@ def report(
|
||||
"status": status,
|
||||
"metrics": metrics,
|
||||
}
|
||||
# Which scheduled task produced this. `source` names the code; two tasks can
|
||||
# share one executor, and on 2026-08-11 two did — a 425 MB probe and the 5 GB
|
||||
# nightly backup wrote rows that were identical apart from their contents, so
|
||||
# a failure could not be attributed to either. Omitted rather than nulled
|
||||
# when absent, per the convention that a missing field means "not
|
||||
# applicable": report() is also callable from a script with no task around it.
|
||||
if task:
|
||||
result["task"] = task
|
||||
|
||||
try:
|
||||
conn = psycopg2.connect(
|
||||
|
||||
@@ -0,0 +1,59 @@
|
||||
"""Which scheduled task is currently executing.
|
||||
|
||||
Executors are invoked as `execute(config, settings)` and are never told which
|
||||
task they are. That is fine until one of them writes to a shared record: on
|
||||
2026-08-11 a probe task and the nightly backup both used
|
||||
config_backup_executor, and the rows they wrote into `check_history` were
|
||||
indistinguishable — same `source`, same `domain`. A failure from a 425 MB test
|
||||
archive was impossible to tell from a failure of the 5 GB nightly job, so the
|
||||
health record could not answer "which one broke?".
|
||||
|
||||
A ContextVar rather than a parameter, because the alternatives are worse here:
|
||||
|
||||
- Threading a `task` argument through `execute(config, settings, task)` is a
|
||||
signature change across every executor, including the dormant ones that
|
||||
exist only as a string in a database row and would break the moment
|
||||
somebody enabled them.
|
||||
- Injecting the name into `config` corrupts the thing executors validate.
|
||||
`config` is what a human wrote in the task definition, and an executor is
|
||||
entitled to reject keys it does not recognise.
|
||||
|
||||
Two properties make this safe, both verified in the deployed runtime rather
|
||||
than assumed:
|
||||
|
||||
- `asyncio.to_thread` propagates the context, so a reporter still sees the
|
||||
task after T-74 moved executor bodies into worker threads.
|
||||
- Each asyncio Task gets its own copy, so the five concurrent executions
|
||||
allowed by MAX_CONCURRENT_TASKS cannot read each other's value.
|
||||
|
||||
A plain `await` of a coroutine does NOT get its own copy and would leak the
|
||||
value back to the caller, so `task_scope` resets it rather than relying on the
|
||||
call always arriving via create_task.
|
||||
"""
|
||||
from contextlib import contextmanager
|
||||
from contextvars import ContextVar
|
||||
from typing import Optional
|
||||
|
||||
_current_task_name: ContextVar[Optional[str]] = ContextVar(
|
||||
"current_task_name", default=None
|
||||
)
|
||||
|
||||
|
||||
@contextmanager
|
||||
def task_scope(task_name: str):
|
||||
"""Name the executing task for the duration of the block."""
|
||||
token = _current_task_name.set(task_name)
|
||||
try:
|
||||
yield
|
||||
finally:
|
||||
_current_task_name.reset(token)
|
||||
|
||||
|
||||
def current_task_name() -> Optional[str]:
|
||||
"""The executing task's name, or None outside an execution.
|
||||
|
||||
None is a real answer, not an error: a reporter may be called from a script
|
||||
or a test with no task around it. Callers omit the field rather than
|
||||
inventing one.
|
||||
"""
|
||||
return _current_task_name.get()
|
||||
@@ -11,6 +11,7 @@ from psycopg2.extras import RealDictCursor
|
||||
import traceback
|
||||
|
||||
from src.config import Settings
|
||||
from src.task_context import task_scope
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
@@ -209,8 +210,11 @@ class TaskExecutor:
|
||||
execution_id = cur.fetchone()[0]
|
||||
conn.commit()
|
||||
|
||||
# Load and execute the task
|
||||
output, error = await self._run_executor(executor_name, task, timeout)
|
||||
# Load and execute the task. The scope names it for anything the
|
||||
# executor writes to a shared record — without it, two tasks sharing
|
||||
# one executor produce rows nobody can tell apart.
|
||||
with task_scope(task_name):
|
||||
output, error = await self._run_executor(executor_name, task, timeout)
|
||||
|
||||
completed_at = datetime.now(timezone.utc)
|
||||
duration = int((completed_at - started_at).total_seconds())
|
||||
|
||||
@@ -0,0 +1,154 @@
|
||||
"""A check_history row must say which task produced it.
|
||||
|
||||
On 2026-08-11 a 425 MB probe task and the 5 GB nightly backup both ran through
|
||||
config_backup_executor. The probe failed, and the row it wrote was
|
||||
indistinguishable from a nightly-backup failure — same `source`, same `domain`,
|
||||
nothing naming the task. The health record could not answer which job broke,
|
||||
which is most of what a health record is for.
|
||||
|
||||
Executors are called as `execute(config, settings)` and are never told which
|
||||
task they are, so the name travels in a ContextVar. These tests pin the three
|
||||
properties that makes safe: it reaches the reporter, it survives the worker
|
||||
thread T-74 introduced, and concurrent executions cannot read each other's.
|
||||
"""
|
||||
import asyncio
|
||||
import json
|
||||
|
||||
import pytest
|
||||
from unittest.mock import AsyncMock, MagicMock, patch
|
||||
|
||||
from src.config import Settings
|
||||
from src.executors import health_report
|
||||
from src.task_context import current_task_name, task_scope
|
||||
from src.tasks.executor import TaskExecutor
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def captured_row(monkeypatch):
|
||||
"""Capture the JSON payload report() would insert, without a database."""
|
||||
box = {}
|
||||
conn, cur = MagicMock(), MagicMock()
|
||||
|
||||
def execute(sql, params):
|
||||
box['result'] = json.loads(params[4])
|
||||
|
||||
cur.execute.side_effect = execute
|
||||
conn.cursor.return_value.__enter__ = MagicMock(return_value=cur)
|
||||
conn.cursor.return_value.__exit__ = MagicMock(return_value=None)
|
||||
conn.__enter__ = MagicMock(return_value=conn)
|
||||
conn.__exit__ = MagicMock(return_value=None)
|
||||
monkeypatch.setattr(health_report.psycopg2, 'connect', lambda **kw: conn)
|
||||
return box
|
||||
|
||||
|
||||
def _report(settings, **kw):
|
||||
health_report.report(
|
||||
settings, domain="backup", status=health_report.OK,
|
||||
source="scheduler/config_backup_executor", metrics={}, **kw
|
||||
)
|
||||
|
||||
|
||||
@pytest.mark.unit
|
||||
class TestAttribution:
|
||||
|
||||
def test_the_row_names_the_task(self, test_settings: Settings, captured_row):
|
||||
with task_scope("backup_docker_configs_daily"):
|
||||
_report(test_settings)
|
||||
assert captured_row['result']['task'] == "backup_docker_configs_daily"
|
||||
|
||||
def test_source_still_names_the_code(self, test_settings: Settings, captured_row):
|
||||
"""Task and source answer different questions; both are needed.
|
||||
|
||||
`source` says which code wrote the row, `task` says which schedule
|
||||
invoked it. Replacing one with the other loses a distinction.
|
||||
"""
|
||||
with task_scope("t74_loop_probe"):
|
||||
_report(test_settings)
|
||||
r = captured_row['result']
|
||||
assert r['source'] == "scheduler/config_backup_executor"
|
||||
assert r['task'] == "t74_loop_probe"
|
||||
|
||||
def test_the_field_is_omitted_rather_than_nulled(self, test_settings: Settings, captured_row):
|
||||
"""report() is callable from a script with no task around it.
|
||||
|
||||
A null would claim there was a task and it had no name. Absence says the
|
||||
question does not apply.
|
||||
"""
|
||||
_report(test_settings)
|
||||
assert 'task' not in captured_row['result']
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_attribution_survives_the_worker_thread(
|
||||
self, test_settings: Settings, captured_row
|
||||
):
|
||||
"""T-74 moved reporting into asyncio.to_thread. Attribution has to follow.
|
||||
|
||||
If the context did not propagate, every row written by a real executor
|
||||
would silently lose its task while the tests above still passed.
|
||||
"""
|
||||
with task_scope("backup_portainer_daily"):
|
||||
await health_report.report_async(
|
||||
test_settings, domain="backup", status=health_report.OK,
|
||||
source="scheduler/portainer_backup_executor", metrics={},
|
||||
)
|
||||
assert captured_row['result']['task'] == "backup_portainer_daily"
|
||||
|
||||
|
||||
@pytest.mark.unit
|
||||
class TestAttributionIsolation:
|
||||
"""MAX_CONCURRENT_TASKS is 5, so mixing values between them is a live risk."""
|
||||
|
||||
def _executor_with_db(self, test_settings):
|
||||
executor = TaskExecutor(test_settings)
|
||||
conn, cur = MagicMock(), MagicMock()
|
||||
cur.fetchone.return_value = [1]
|
||||
conn.cursor.return_value.__enter__ = MagicMock(return_value=cur)
|
||||
conn.cursor.return_value.__exit__ = MagicMock(return_value=None)
|
||||
conn.__enter__ = MagicMock(return_value=conn)
|
||||
conn.__exit__ = MagicMock(return_value=None)
|
||||
return executor, patch.object(executor, 'get_db_connection', return_value=conn)
|
||||
|
||||
def _task(self, name):
|
||||
return {'id': hash(name) % 1000, 'task_name': name, 'executor': 'x',
|
||||
'service': 'scheduler', 'priority': 5, 'timeout_seconds': 60}
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_the_engine_names_the_task_and_clears_it_after(
|
||||
self, test_settings: Settings
|
||||
):
|
||||
executor, db = self._executor_with_db(test_settings)
|
||||
seen = {}
|
||||
|
||||
async def fake_run(name, task, timeout):
|
||||
seen['during'] = current_task_name()
|
||||
return "done", None
|
||||
|
||||
with db, patch.object(executor, '_run_executor', new=fake_run):
|
||||
await executor.execute_task(self._task("nightly_backup"))
|
||||
|
||||
assert seen['during'] == "nightly_backup", "executor ran unattributed"
|
||||
assert current_task_name() is None, "attribution leaked past the execution"
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_concurrent_executions_do_not_see_each_other(
|
||||
self, test_settings: Settings
|
||||
):
|
||||
executor, db = self._executor_with_db(test_settings)
|
||||
seen = {}
|
||||
|
||||
async def fake_run(name, task, timeout):
|
||||
who = task['task_name']
|
||||
# Yield mid-flight so the executions genuinely interleave; without
|
||||
# this they would run to completion one at a time and the test would
|
||||
# pass even with a shared global.
|
||||
await asyncio.sleep(0.01 if who == "slow_one" else 0)
|
||||
seen[who] = current_task_name()
|
||||
return "done", None
|
||||
|
||||
with db, patch.object(executor, '_run_executor', new=fake_run):
|
||||
await asyncio.gather(
|
||||
executor.execute_task(self._task("slow_one")),
|
||||
executor.execute_task(self._task("fast_one")),
|
||||
)
|
||||
|
||||
assert seen == {"slow_one": "slow_one", "fast_one": "fast_one"}
|
||||
Reference in New Issue
Block a user