mirror of
https://github.com/bytedance/deer-flow.git
synced 2026-09-15 09:08:38 +00:00
* refactor(gateway): issue request trace ids unconditionally The request trace id was gated behind logging.enhance.enabled at every entry point, so downstream code had to keep asking whether one existed: a header-provenance flag in its own ContextVar, a precedence resolver, and three-level carrier fallbacks at each consumer. Bind one unconditionally instead. TraceMiddleware covers Gateway HTTP; ensure_trace_context covers the entry points that never touch ASGI -- scheduled occurrences, MCP task notification runs, IM channel messages, and the embedded client -- each scoped to one unit of work so a long-lived worker task cannot leak one occurrence's id into the next. The ContextVar becomes the only source; the response header, runtime context, run metadata and log records are derived outputs. Consumers now use ensure_trace_id() or resolve_trace_id(*carriers) and drop their presence guards. Removed: resolve_deerflow_trace_id, the header-provenance flag and its three helpers, set/reset_current_trace_id, is_trace_correlation_enabled and its gateway alias. BREAKING CHANGE: every Gateway HTTP response now carries X-Trace-Id and it cannot be turned off; logging.enhance.enabled controls log output only. Installations on the default enabled: false will start seeing the header. No config keys were added or removed. * fix(gateway): stop persisting a caller-supplied trace id on the run record body.metadata forks two ways: through build_run_config into the live run config, which the run worker restamps, and through create_or_reject into the run record that the runs API echoes verbatim. Only the first was covered, so a client sending metadata.deerflow_trace_id made the most durable and most visible surface of a run disagree with the X-Trace-Id and the log lines the same request produced -- a correlation id that does not match the logs is worse than none. Stamp the server-issued id once at the trust boundary so both forks receive it, preserving the caller's own metadata keys. Close the same gap on config.context, which reaches the runtime context by a separate path: _build_runtime_context no longer merges server-owned keys from the caller, and _install_runtime_context assigns rather than setdefaults. A thread's metadata is no longer seeded with the run-scoped id of whichever run created it -- one thread spans many runs and as many trace ids. Found by driving a real run through the Gateway and reading the run back from the runs API; every unit test built its metadata by hand and so could not see it. * fix(gateway): expose X-Trace-Id to split-origin browser clients X-Trace-Id is not on the CORS safelist, so a browser client served from a separate origin could not read it -- and those are exactly the clients that cannot read the Gateway's logs either, leaving them with nothing to quote in a bug report. Same-origin nginx deployments were unaffected, which is why this stayed hidden. Add it to CORS_EXPOSED_HEADERS beside Content-Location, referencing TRACE_ID_HEADER rather than repeating the literal. * fix(gateway): keep X-Trace-Id on unhandled-exception 500s Starlette's ServerErrorMiddleware sits outside every user middleware and emits unhandled-exception 500s through the raw send, so those responses never pass TraceMiddleware's header-writing wrapper. The 500 for a server bug is exactly the response a user most needs to correlate with a log line, and it was the one response that shipped without the id. TraceMiddleware now tracks whether http.response.start has been sent. On an exception with no response started it emits its own plain 500 carrying the header, then re-raises: the outer ServerErrorMiddleware sees the response already started and only re-raises too, so the server's exception logging is untouched. An exception mid-stream keeps propagating unchanged — a second response start cannot be sent, and the already-written header stands. The trace id is printable ASCII by construction (normalize_trace_id / generate_trace_id), which is what makes the raw latin-1 header encoding safe. * fix(gateway): strip the forged trace id from the persisted request echo The run-record fix stopped a forged metadata.deerflow_trace_id on the authoritative metadata surface, but the raw request echo still carried one: create_or_reject persists body.config verbatim as runs.kwargs_json, which the runs API serves back. A client posting config.context.deerflow_trace_id therefore still got its forged value stored and echoed on one API surface while the header, logs, run metadata, and checkpoint all carried the real id — the id is ignored as input there, so echoing it back only manufactures disagreement. Two changes close it. redact_config_secrets — already the shared scrub for that echo, applied at admission and again at serve time, so historical records are covered too — now also drops deerflow_trace_id from config.metadata and config.context. And build_run_config now merges run metadata onto a copy of the caller's config["metadata"] instead of updating it in place: the nested values of the request config are reference copies, so the in-place merge was writing the server-stamped key through into body.config, contaminating the "what the client sent" record before it was persisted (and incidentally masking the forged-value echo on the metadata container). The regression test posts a forged id through body.metadata, config.metadata, and config.context at once and reads the kwargs echo back off the run record, failing if either leak returns. * docs(harness): record the trace-echo scrub, 500 fallback, and accepted retry divergence The trace section of the harness AGENTS.md now covers the two fixes that close the derived-output rule (the kwargs-echo scrub in redact_config_secrets plus build_run_config's copy merge, and TraceMiddleware's own 500 for unhandled exceptions), and CHANGELOG gains their Fixed entries. It also writes down the one accepted divergence: a crash-recovered scheduled launch reuses the durable run through its idempotency key, and start_run returns early on idempotency_reused without restamping — so the run record keeps the first attempt's deerflow_trace_id while the retry's own log lines carry the freshly minted id of its ensure_trace_context binding. The divergence is confined to the crash-recovery window and is accepted rather than fixed: restamping on reuse would rewrite a persisted record for a run that already exists, which is worse than two ids that each correlate their own attempt's logs. Written down so the next reader of the scheduler recovery path does not diagnose it as a bug. * docs(config): align the logging.enhance schema note with the unconditional trace id The config-module AGENTS.md still described logging.enhance as the gate for the Gateway X-Trace-Id header and Langfuse deerflow_trace_id. That model is gone: ids are issued unconditionally and this block decides log output only. Left as-is, the stale wording invites an agent to "restore" a header gate it believes was lost. Reworded to match the sibling AGENTS.md files and config.example.yaml, with a pointer to the Request Trace Context section that owns the full model. * docs(changelog): link the trace entries to #5119 The five new entries pointed at the ([#XXXX]) placeholder with no reference definition, rendering as literal text instead of a link — and RELEASING.md step 2 relies on those references when the section becomes release notes. All five now point at #5119, with the definition appended to the reference block. * refactor(harness): rename _stream_without_trace_context to _stream_turn The name asserted the opposite of what the method now does. It was accurate while logging.enhance.enabled could route stream() around the trace scope; with the gate gone it is the only stream implementation left, and it binds the id itself via ensure_trace_id(). Private, so the rename touches only the definition and the one stream() call site. * docs(harness): fit the trace-context guidance inside the AGENTS.md chain budget The expanded Request Trace Context section pushed the effective AGENTS.md chain for agents/middlewares to 99,815 bytes, past the 98,304 hard limit scripts/check_agent_guidance.py enforces in CI (AG002). Compressed the section from 7,359 to 4592 bytes with no facts removed: the entry-point table, the derived-output rule and its enforcement points, the accepted scheduled-retry divergence, the two resolution helpers, the stream() binding rationale, the log-output-only gate, the CORS listing, the 500 fallback, and the test map all remain. Sized against the merge, not just the branch: current main grew the same chain by ~724 bytes, so the check was verified on the merged tree as well (97,772 bytes; branch tree 97,048). * fix(gateway): declare content-length on the fallback 500 The pre-response 500 declared content-type but no content-length, leaving the framing to the ASGI server: chunked on HTTP/1.1, close-delimited on HTTP/1.0 — the one wire difference from the ServerErrorMiddleware response it replaces, which sends content-length: 21. The explicit header keeps the fallback byte-identical to what clients saw before. * docs(readme): drop the trace-correlation condition from the translations The zh/ja/fr/ru Langfuse sections still said metadata.deerflow_trace_id matches X-Trace-Id "when request trace correlation is enabled". The id now always matches and that condition no longer exists, so each bullet states the unconditional match and that logging.enhance.enabled only controls whether the id is printed into logs — the one piece of the feature a user can still configure. * test(gateway): pin TraceMiddleware wiring through create_app() Every X-Trace-Id test exercised a hand-built four-route app, so the real stack's add_middleware(TraceMiddleware) line was pinned by nothing: deleting it — or short-circuiting above it — passed CI while silently dropping both the response header and the ambient id the run-record stamp and enhanced log records derive from. One case now drives /health through create_app() and asserts the inbound id round-trips; mutation-checked by removing the wiring line, which fails exactly this test. * docs(gateway): note the fallback 500 is CORS-opaque The pre-response 500 is emitted outside CORSMiddleware — the exception has already unwound past it — so it carries no Access-Control-Allow-Origin and a split-origin browser client cannot read the id on this one response, unchanged from the ServerErrorMiddleware 500 it replaces. Documented on the class and in the CHANGELOG entry rather than fixed: replicating the origin allowlist outside CORSMiddleware would let the two policies drift. * fix(harness): keep abandoned-stream cleanup inside the trace binding stream() binds the turn's id around each next(inner) and resets it before yielding, but the finally's inner.close() ran after that binding was gone. Abandoning the stream therefore drove the inner LangGraph generator's GeneratorExit/finally path with no trace id — or an unrelated ambient one from whichever context ran the close — so cancellation and finalization logs and callbacks did not correlate with the turn they belong to. inner.close() is now wrapped in a local bind/reset of the same turn id. The token is set and reset in the same frame, never across a yield, so the per-step cross-context safety is preserved even when GC closes the generator from another Context — pinned by the existing copy_context close test, which now exercises this path. The regression test records the id from the inner generator's finally and fails without the binding. * test(harness): teach the worker-trace fake about RunManager.cleanup Upstream #5112 (bound gateway memory after terminal runs) added a run_manager.cleanup(run_id) call to run_agent's finalization, so the merge-commit CI run failed all five worker-trace-binding tests with AttributeError on this PR's _FakeRunManager. The fake gains the same no-op shape as its other methods. * docs(gateway): bring the gateway AGENTS.md back under its soft budget Upstream #5092 grew backend/app/gateway/AGENTS.md to 40,966 bytes, 6 over the 40,960 soft budget that test_agent_guidance_check.py::test_repository_guidance_stays_below_soft_budgets_and_avoids_doc_indexes enforces — its Unit Tests run on main was cancelled by push concurrency, so main is currently red on that test and every PR merge-run inherits the failure. Two whitespace/wording trims in the row #5092 touched (a doubled space, and "its configured `context_window`" → "its `context_window`") bring the file to 40,953 with no content change. --------- Co-authored-by: Willem Jiang <willem.jiang@gmail.com>
637 lines
26 KiB
Python
637 lines
26 KiB
Python
from __future__ import annotations
|
|
|
|
import asyncio
|
|
import logging
|
|
import socket
|
|
import uuid
|
|
from datetime import UTC, datetime, timedelta
|
|
from typing import Any, Literal
|
|
|
|
from fastapi import HTTPException
|
|
|
|
from deerflow.persistence.scheduled_task_runs import ActiveScheduledRunConflict, ScheduledTaskAdmissionRejected
|
|
from deerflow.runtime import ConflictError, RunRecord
|
|
from deerflow.scheduler.schedules import next_run_at
|
|
from deerflow.trace_context import ensure_trace_context
|
|
from deerflow.utils.thread_id import validate_thread_id
|
|
|
|
logger = logging.getLogger(__name__)
|
|
|
|
# Shared so the active-row fast path and the atomic-admission conflict path
|
|
# return byte-identical outcomes for the same active-occurrence condition.
|
|
_ACTIVE_RUN_CONFLICT_ERROR = "task already has an active run"
|
|
_RESTART_RECOVERY_ERROR = "interrupted: gateway restarted before the run reached a terminal state"
|
|
_LEASE_RECOVERY_ERROR = "interrupted: the owning gateway stopped renewing its run lease"
|
|
_QUEUE_TIMEOUT_ERROR = "scheduled task queue wait timeout exceeded"
|
|
|
|
|
|
class ScheduledTaskService:
|
|
def __init__(
|
|
self,
|
|
*,
|
|
task_repo,
|
|
task_run_repo,
|
|
launch_run,
|
|
poll_interval_seconds: int,
|
|
lease_seconds: int,
|
|
max_concurrent_runs: int,
|
|
queue_timeout_seconds: int = 3600,
|
|
multi_instance: bool = False,
|
|
run_lease_grace_seconds: int = 10,
|
|
) -> None:
|
|
self._task_repo = task_repo
|
|
self._task_run_repo = task_run_repo
|
|
self._launch_run = launch_run
|
|
self._poll_interval_seconds = poll_interval_seconds
|
|
self._lease_seconds = lease_seconds
|
|
self._max_concurrent_runs = max_concurrent_runs
|
|
self._queue_timeout_seconds = queue_timeout_seconds
|
|
self._multi_instance = multi_instance
|
|
self._run_lease_grace_seconds = run_lease_grace_seconds
|
|
self._lease_owner = f"{socket.gethostname()}:{uuid.uuid4().hex}"
|
|
self._task: asyncio.Task | None = None
|
|
self._stop = asyncio.Event()
|
|
self._skip_next_lease_reconciliation = False
|
|
|
|
async def run_once(self, *, now: datetime) -> None:
|
|
if self._multi_instance:
|
|
if self._skip_next_lease_reconciliation:
|
|
self._skip_next_lease_reconciliation = False
|
|
else:
|
|
await self._reconcile_active_state(now=now)
|
|
else:
|
|
await self._task_run_repo.recover_expired_launch_claims(
|
|
error=_LEASE_RECOVERY_ERROR,
|
|
now=now,
|
|
)
|
|
await self._expire_waiting_runs(now=now)
|
|
await self._drain_queue(now=now)
|
|
# Admission and execution capacity are separate. Due occurrences are
|
|
# persisted even when all execution slots are busy; claim_queued_run()
|
|
# applies the global launch budget under the database lock.
|
|
claimed = await self._task_repo.claim_due_tasks(
|
|
now=now,
|
|
lease_owner=self._lease_owner,
|
|
lease_seconds=self._lease_seconds,
|
|
limit=self._max_concurrent_runs,
|
|
)
|
|
for task in claimed:
|
|
await self.dispatch_task(task, now=now, trigger="scheduled")
|
|
|
|
@staticmethod
|
|
def _is_overlap_conflict(exc: Exception) -> bool:
|
|
if isinstance(exc, ConflictError):
|
|
return True
|
|
return isinstance(exc, HTTPException) and exc.status_code == 409
|
|
|
|
@staticmethod
|
|
def _task_status_for_failure(task: dict[str, Any], *, trigger: str) -> str:
|
|
if trigger == "manual":
|
|
# A failed manual trigger must not consume the task's scheduled
|
|
# future: a `once` task with run_at still ahead would otherwise be
|
|
# flipped to "failed" and never claimed again.
|
|
return task.get("status") or "enabled"
|
|
if task["schedule_type"] == "once":
|
|
return "failed"
|
|
return "enabled"
|
|
|
|
@staticmethod
|
|
def _task_status_for_launch(task: dict[str, Any], *, trigger: str) -> str:
|
|
# The task-level status to write once _launch_run has produced a live
|
|
# run. A `once` task stays "running" until handle_run_completion
|
|
# observes the real terminal outcome; declaring "completed" at launch
|
|
# would stick if the run fails or the process dies (startup
|
|
# reconciliation is cancel_stuck_once_tasks).
|
|
if task["schedule_type"] == "once":
|
|
return "running"
|
|
if trigger == "manual" and task.get("status") == "paused":
|
|
return "paused"
|
|
return "enabled"
|
|
|
|
async def dispatch_task(
|
|
self,
|
|
task: dict[str, Any],
|
|
*,
|
|
now: datetime,
|
|
trigger: str,
|
|
) -> dict[str, Any]:
|
|
expected_lease_owner = self._lease_owner if trigger == "scheduled" else None
|
|
execution_thread_id = task.get("thread_id")
|
|
if task.get("context_mode") == "fresh_thread_per_run" or execution_thread_id is None:
|
|
execution_thread_id = str(uuid.uuid4())
|
|
try:
|
|
validate_thread_id(execution_thread_id)
|
|
except ValueError as exc:
|
|
# Rows persisted before the thread-id contract was centralized may
|
|
# hold IDs that were valid then (dots, unlimited length) but fail
|
|
# the canonical pattern now. Route through the normal failure
|
|
# bookkeeping instead of raising: an uncaught ValueError here would
|
|
# surface as HTTP 500 on manual trigger and, in the poller, abort
|
|
# the rest of the claimed batch every cycle while the task itself
|
|
# is never marked with last_error.
|
|
task_status = self._task_status_for_failure(task, trigger=trigger)
|
|
await self._task_repo.update_after_launch(
|
|
task["id"],
|
|
status=task_status,
|
|
next_run_at=next_run_at(
|
|
task["schedule_type"],
|
|
task["schedule_spec"],
|
|
task["timezone"],
|
|
now=now,
|
|
),
|
|
last_run_at=now,
|
|
last_run_id=None,
|
|
last_thread_id=execution_thread_id,
|
|
last_error=str(exc),
|
|
increment_run_count=False,
|
|
expected_lease_owner=expected_lease_owner,
|
|
)
|
|
return {
|
|
"outcome": "failed",
|
|
"task_run_id": None,
|
|
"run_id": None,
|
|
"thread_id": execution_thread_id,
|
|
"error": str(exc),
|
|
}
|
|
active = await self._task_run_repo.get_active_run(task["id"])
|
|
if active is not None:
|
|
if trigger == "scheduled":
|
|
await self._release_admission_lease(task, trigger=trigger)
|
|
return self._existing_active_result(active, execution_thread_id, trigger=trigger)
|
|
|
|
task_run_id = f"task-run-{uuid.uuid4().hex}"
|
|
try:
|
|
await self._task_run_repo.create(
|
|
run_record_id=task_run_id,
|
|
task_id=task["id"],
|
|
thread_id=execution_thread_id,
|
|
scheduled_for=now,
|
|
trigger=trigger,
|
|
status="queued",
|
|
coordinate_with_task=True,
|
|
expected_task_user_id=task.get("user_id"),
|
|
expected_task_status=task.get("status") if trigger == "manual" else None,
|
|
expected_task_updated_at=task.get("updated_at") if trigger == "manual" else None,
|
|
expected_task_lease_owner=self._lease_owner if trigger == "scheduled" else None,
|
|
release_task_lease_status="enabled" if trigger == "scheduled" else None,
|
|
)
|
|
except ActiveScheduledRunConflict:
|
|
active = await self._task_run_repo.get_active_run(task["id"])
|
|
if trigger == "scheduled":
|
|
await self._release_admission_lease(task, trigger=trigger)
|
|
if active is None:
|
|
return self._active_run_conflict_result(execution_thread_id)
|
|
return self._existing_active_result(active, execution_thread_id, trigger=trigger)
|
|
except ScheduledTaskAdmissionRejected as exc:
|
|
if exc.reason == "not_found":
|
|
return {
|
|
"outcome": "not_found",
|
|
"task_run_id": None,
|
|
"run_id": None,
|
|
"thread_id": execution_thread_id,
|
|
"error": "scheduled task no longer exists",
|
|
}
|
|
return {
|
|
"outcome": "conflict",
|
|
"task_run_id": None,
|
|
"run_id": None,
|
|
"thread_id": execution_thread_id,
|
|
"error": "scheduled task changed before trigger admission",
|
|
}
|
|
|
|
# Scheduled admission inserted the queue row and released its parent
|
|
# lease in one transaction. Manual admission verified that this task
|
|
# snapshot was still current under the same parent lock.
|
|
queued = {
|
|
"id": task_run_id,
|
|
"task_id": task["id"],
|
|
"thread_id": execution_thread_id,
|
|
"trigger": trigger,
|
|
}
|
|
return await self._attempt_queued_run(task, queued, now=now)
|
|
|
|
async def _release_admission_lease(self, task: dict[str, Any], *, trigger: str) -> None:
|
|
status = "enabled" if trigger == "scheduled" else (task.get("status") or "enabled")
|
|
await self._task_repo.release_dispatch_lease(
|
|
task["id"],
|
|
expected_lease_owner=self._lease_owner if trigger == "scheduled" else None,
|
|
status=status,
|
|
)
|
|
|
|
async def _attempt_queued_run(
|
|
self,
|
|
task: dict[str, Any],
|
|
queued: dict[str, Any],
|
|
*,
|
|
now: datetime,
|
|
) -> dict[str, Any]:
|
|
"""Turn one queued occurrence into a live run under its own trace scope.
|
|
|
|
The poller is a non-HTTP entry point, so no ``TraceMiddleware`` has
|
|
bound anything: each occurrence opens its own scope rather than
|
|
sharing one id across a whole poll cycle. A manual trigger arrives
|
|
inside a Gateway request and keeps that request's trace instead, so
|
|
the launched run stays correlated with the call that asked for it.
|
|
"""
|
|
with ensure_trace_context():
|
|
return await self._launch_queued_occurrence(task, queued, now=now)
|
|
|
|
async def _launch_queued_occurrence(
|
|
self,
|
|
task: dict[str, Any],
|
|
queued: dict[str, Any],
|
|
*,
|
|
now: datetime,
|
|
) -> dict[str, Any]:
|
|
task_run_id = queued["id"]
|
|
execution_thread_id = queued["thread_id"]
|
|
trigger = queued["trigger"]
|
|
claimed = await self._task_run_repo.claim_queued_run(
|
|
task_run_id,
|
|
lease_owner=self._lease_owner,
|
|
now=now,
|
|
lease_seconds=self._lease_seconds,
|
|
global_max_concurrent_runs=self._max_concurrent_runs,
|
|
)
|
|
if claimed is None:
|
|
return self._queued_result(task_run_id, execution_thread_id)
|
|
|
|
# Track whether _launch_run has produced a live run. A bookkeeping
|
|
# failure after launch must retain the non-terminal slot so a later
|
|
# poll cannot start the same occurrence twice.
|
|
launched_run_id: str | None = None
|
|
launched_thread_id: str | None = None
|
|
launch_succeeded = False
|
|
try:
|
|
result = await self._launch_run(
|
|
thread_id=execution_thread_id,
|
|
assistant_id=task.get("assistant_id"),
|
|
prompt=task["prompt"],
|
|
owner_user_id=task.get("user_id"),
|
|
metadata={
|
|
"scheduled_task_id": task["id"],
|
|
"scheduled_task_run_id": task_run_id,
|
|
"scheduled_trigger": trigger,
|
|
},
|
|
)
|
|
launch_succeeded = True
|
|
launched_run_id = result["run_id"]
|
|
launched_thread_id = result["thread_id"]
|
|
next_at = next_run_at(
|
|
task["schedule_type"],
|
|
task["schedule_spec"],
|
|
task["timezone"],
|
|
now=now,
|
|
)
|
|
task_status = self._task_status_for_launch(task, trigger=trigger)
|
|
await self._record_launched_run(
|
|
task_run_id=task_run_id,
|
|
task_id=task["id"],
|
|
run_id=launched_run_id,
|
|
started_at=now,
|
|
)
|
|
await self._task_repo.update_after_launch(
|
|
task["id"],
|
|
status=task_status,
|
|
next_run_at=next_at,
|
|
last_run_at=now,
|
|
last_run_id=launched_run_id,
|
|
last_thread_id=launched_thread_id,
|
|
last_error=None,
|
|
increment_run_count=True,
|
|
# Same race as the run-row write above: a fast-failing run's
|
|
# completion hook may have already finalized a `once` task.
|
|
protect_terminal=True,
|
|
)
|
|
return {
|
|
"outcome": "launched",
|
|
"task_run_id": task_run_id,
|
|
"run_id": launched_run_id,
|
|
"thread_id": launched_thread_id,
|
|
"error": None,
|
|
}
|
|
except Exception as exc:
|
|
if not launch_succeeded and self._is_overlap_conflict(exc):
|
|
await self._task_run_repo.requeue_claimed_run(
|
|
task_run_id,
|
|
lease_owner=self._lease_owner,
|
|
error=str(exc),
|
|
)
|
|
return self._queued_result(task_run_id, execution_thread_id, error=str(exc))
|
|
|
|
next_at = next_run_at(
|
|
task["schedule_type"],
|
|
task["schedule_spec"],
|
|
task["timezone"],
|
|
now=now,
|
|
)
|
|
|
|
if launch_succeeded:
|
|
# _launch_run succeeded, so a run is live even though
|
|
# post-launch bookkeeping raised. Keep the task-run row
|
|
# "running" so it keeps holding the task's single active slot
|
|
# (preventing a duplicate launch on the next dispatch) and
|
|
# persist the run_id on the parent task for recovery /
|
|
# reconciliation / cancellation. These writes are best-effort:
|
|
# if the DB is still down the row stays "queued" -- still
|
|
# active, still holding the slot -- so we log and still report
|
|
# the run as launched so callers know a run is in flight.
|
|
task_status = self._task_status_for_launch(task, trigger=trigger)
|
|
try:
|
|
await self._record_launched_run(
|
|
task_run_id=task_run_id,
|
|
task_id=task["id"],
|
|
run_id=launched_run_id,
|
|
started_at=now,
|
|
)
|
|
except Exception:
|
|
logger.exception(
|
|
"Scheduled task-run %s: post-launch bookkeeping failed; run %s is still live (task %s)",
|
|
task_run_id,
|
|
launched_run_id,
|
|
task["id"],
|
|
)
|
|
try:
|
|
await self._task_repo.update_after_launch(
|
|
task["id"],
|
|
status=task_status,
|
|
next_run_at=next_at,
|
|
last_run_at=now,
|
|
last_run_id=launched_run_id,
|
|
last_thread_id=launched_thread_id,
|
|
# The bookkeeping exception is an infrastructure-level
|
|
# transient, not a run-level failure: the run launched
|
|
# and is still in flight. Clear last_error like the
|
|
# success path so the task list does not show an error
|
|
# on a task whose run is actively running; the real
|
|
# terminal outcome is written by handle_run_completion.
|
|
# The transient itself is logged above.
|
|
last_error=None,
|
|
increment_run_count=True,
|
|
protect_terminal=True,
|
|
)
|
|
except Exception:
|
|
logger.exception(
|
|
"Scheduled task %s: post-launch update failed; run %s is still live",
|
|
task["id"],
|
|
launched_run_id,
|
|
)
|
|
return {
|
|
"outcome": "launched",
|
|
"task_run_id": task_run_id,
|
|
"run_id": launched_run_id,
|
|
"thread_id": launched_thread_id,
|
|
"error": str(exc),
|
|
}
|
|
|
|
# _launch_run itself failed (or a step before it did): no live run
|
|
# was created, so it is safe to release the active slot.
|
|
finalized = await self._task_run_repo.fail_launching_run(
|
|
task_run_id,
|
|
task_id=task["id"],
|
|
lease_owner=self._lease_owner,
|
|
error=str(exc),
|
|
now=now,
|
|
)
|
|
if not finalized:
|
|
logger.warning(
|
|
"Scheduled task-run %s lost its launch claim before failure bookkeeping; leaving recovery-owned state unchanged",
|
|
task_run_id,
|
|
)
|
|
return self._queued_result(task_run_id, execution_thread_id, error=str(exc))
|
|
return {
|
|
"outcome": "failed",
|
|
"task_run_id": task_run_id,
|
|
"run_id": None,
|
|
"thread_id": execution_thread_id,
|
|
"error": str(exc),
|
|
}
|
|
|
|
async def _record_launched_run(
|
|
self,
|
|
*,
|
|
task_run_id: str,
|
|
task_id: str,
|
|
run_id: str,
|
|
started_at: datetime,
|
|
) -> None:
|
|
updated = await self._task_run_repo.update_status(
|
|
task_run_id,
|
|
status="running",
|
|
run_id=run_id,
|
|
started_at=started_at,
|
|
protect_terminal=True,
|
|
expected_lease_owner=self._lease_owner,
|
|
)
|
|
if updated:
|
|
return
|
|
reconciled = await self._task_run_repo.reconcile_launched_run(
|
|
task_run_id,
|
|
task_id=task_id,
|
|
run_id=run_id,
|
|
started_at=started_at,
|
|
)
|
|
if not reconciled:
|
|
logger.error(
|
|
"Scheduled task-run %s launched durable run %s but could not restore its occurrence association",
|
|
task_run_id,
|
|
run_id,
|
|
)
|
|
|
|
def _active_run_conflict_result(self, thread_id: str) -> dict[str, Any]:
|
|
"""Manual-trigger response when the task already has an active run.
|
|
|
|
Nothing was scheduled to happen, so no run-history row is recorded; the
|
|
router maps this to a 409.
|
|
"""
|
|
return {
|
|
"outcome": "conflict",
|
|
"task_run_id": None,
|
|
"run_id": None,
|
|
"thread_id": thread_id,
|
|
"error": _ACTIVE_RUN_CONFLICT_ERROR,
|
|
}
|
|
|
|
def _existing_active_result(
|
|
self,
|
|
active: dict[str, Any],
|
|
thread_id: str,
|
|
*,
|
|
trigger: str,
|
|
) -> dict[str, Any]:
|
|
if active["status"] == "queued":
|
|
return self._queued_result(active["id"], active["thread_id"])
|
|
return self._active_run_conflict_result(thread_id)
|
|
|
|
@staticmethod
|
|
def _queued_result(
|
|
task_run_id: str,
|
|
thread_id: str,
|
|
*,
|
|
error: str | None = None,
|
|
) -> dict[str, Any]:
|
|
return {
|
|
"outcome": "queued",
|
|
"task_run_id": task_run_id,
|
|
"run_id": None,
|
|
"thread_id": thread_id,
|
|
"error": error,
|
|
}
|
|
|
|
async def _drain_queue(self, *, now: datetime) -> None:
|
|
queued_rows = await self._task_run_repo.list_queued_runs(limit=max(16, self._max_concurrent_runs * 4))
|
|
for queued in queued_rows:
|
|
await self._task_repo.release_queued_admission_lease(queued["task_id"])
|
|
task = await self._task_repo.get_internal(queued["task_id"])
|
|
if task is None:
|
|
await self._task_run_repo.update_status(
|
|
queued["id"],
|
|
status="interrupted",
|
|
error="scheduled task was deleted while queued",
|
|
finished_at=now,
|
|
)
|
|
continue
|
|
# Pausing suppresses automatic occurrences, but a manual trigger is
|
|
# an explicit request and has always been allowed to run without
|
|
# resuming the schedule. A later pause still cancels an already
|
|
# queued manual row atomically in pause_with_queue_cancellation().
|
|
if task.get("status") == "paused" and queued["trigger"] != "manual":
|
|
await self._task_run_repo.update_status(
|
|
queued["id"],
|
|
status="interrupted",
|
|
error="scheduled task was paused while queued",
|
|
finished_at=now,
|
|
)
|
|
continue
|
|
await self._attempt_queued_run(task, queued, now=now)
|
|
|
|
async def _expire_waiting_runs(self, *, now: datetime) -> None:
|
|
await self._task_run_repo.expire_queued_runs(
|
|
created_before=now - timedelta(seconds=self._queue_timeout_seconds),
|
|
error=_QUEUE_TIMEOUT_ERROR,
|
|
now=now,
|
|
)
|
|
|
|
async def handle_run_completion(self, record: RunRecord) -> None:
|
|
metadata = record.metadata or {}
|
|
task_id = metadata.get("scheduled_task_id")
|
|
task_run_id = metadata.get("scheduled_task_run_id")
|
|
user_id = record.user_id
|
|
if not isinstance(task_id, str) or not isinstance(task_run_id, str) or not user_id:
|
|
return
|
|
|
|
terminal_status: Literal["success", "failed", "interrupted"] | None
|
|
if record.status.value == "success":
|
|
terminal_status = "success"
|
|
error = None
|
|
elif record.status.value == "interrupted":
|
|
# Distinct from "failed": an interrupt (user cancel, same-thread
|
|
# takeover) carries no error and is not an execution failure.
|
|
terminal_status = "interrupted"
|
|
error = record.error or "run was interrupted before completion"
|
|
elif record.status.value in {"error", "timeout"}:
|
|
terminal_status = "failed"
|
|
error = record.error
|
|
else:
|
|
terminal_status = None
|
|
error = record.error
|
|
if terminal_status is None:
|
|
return
|
|
|
|
await self._task_run_repo.update_status(
|
|
task_run_id,
|
|
status=terminal_status,
|
|
run_id=record.run_id,
|
|
error=error,
|
|
finished_at=datetime.now(UTC),
|
|
)
|
|
|
|
task = await self._task_repo.get(task_id, user_id=user_id)
|
|
if task is None:
|
|
return
|
|
|
|
updates: dict[str, Any] = {"last_error": error}
|
|
if task["schedule_type"] == "once":
|
|
# The single occurrence is consumed either way (the run did launch,
|
|
# so re-arming risks duplicate side effects), but an interrupt ends
|
|
# as "cancelled", not "failed".
|
|
if terminal_status == "success":
|
|
updates["status"] = "completed"
|
|
elif terminal_status == "interrupted":
|
|
updates["status"] = "cancelled"
|
|
else:
|
|
updates["status"] = "failed"
|
|
await self._task_repo.update(task_id, user_id=user_id, updates=updates)
|
|
|
|
async def start(self) -> None:
|
|
if self._task is not None:
|
|
return
|
|
restart_error = _RESTART_RECOVERY_ERROR
|
|
if self._multi_instance:
|
|
await self._reconcile_active_state(now=datetime.now(UTC))
|
|
self._skip_next_lease_reconciliation = True
|
|
else:
|
|
try:
|
|
stale = await self._task_run_repo.mark_stale_active_runs(error=restart_error)
|
|
if stale:
|
|
logger.warning("Marked %d stale scheduled task run(s) as interrupted after restart", stale)
|
|
except Exception:
|
|
logger.exception("Failed to sweep stale scheduled task runs at startup")
|
|
try:
|
|
# The run rows above are only half the story: a launched `once`
|
|
# task is parked in "running" until the (now dead) completion hook
|
|
# would have finalized it, so reconcile the parent rows too.
|
|
stuck = await self._task_repo.cancel_stuck_once_tasks(error=restart_error)
|
|
if stuck:
|
|
logger.warning("Cancelled %d stuck once task(s) after restart", stuck)
|
|
except Exception:
|
|
logger.exception("Failed to reconcile stuck once tasks at startup")
|
|
self._stop.clear()
|
|
self._task = asyncio.create_task(self._run_loop())
|
|
|
|
async def _reconcile_active_state(self, *, now: datetime) -> None:
|
|
error = _LEASE_RECOVERY_ERROR
|
|
try:
|
|
stale = await self._task_run_repo.reconcile_active_runs(
|
|
error=error,
|
|
now=now,
|
|
lease_grace_seconds=self._run_lease_grace_seconds,
|
|
)
|
|
if stale:
|
|
logger.warning("Marked %d stale scheduled task run(s) as interrupted after lease reconciliation", stale)
|
|
except Exception:
|
|
logger.exception("Failed to reconcile scheduled task runs with leases")
|
|
try:
|
|
stuck = await self._task_repo.reconcile_stuck_once_tasks(
|
|
error=error,
|
|
now=now,
|
|
lease_grace_seconds=self._run_lease_grace_seconds,
|
|
)
|
|
if stuck:
|
|
logger.warning("Cancelled %d stuck once task(s) after lease reconciliation", stuck)
|
|
except Exception:
|
|
logger.exception("Failed to reconcile once tasks with leases")
|
|
|
|
async def stop(self) -> None:
|
|
if self._task is None:
|
|
return
|
|
self._stop.set()
|
|
await self._task
|
|
self._task = None
|
|
|
|
async def _run_loop(self) -> None:
|
|
while not self._stop.is_set():
|
|
try:
|
|
await self.run_once(now=datetime.now(UTC))
|
|
except Exception:
|
|
# A transient DB error (e.g. SQLite "database is locked") must
|
|
# not kill the poller task for the rest of the process life.
|
|
logger.exception("Scheduled task poll failed; retrying next interval")
|
|
try:
|
|
await asyncio.wait_for(
|
|
self._stop.wait(),
|
|
timeout=self._poll_interval_seconds,
|
|
)
|
|
except TimeoutError:
|
|
continue
|