mirror of
https://github.com/tiennm99/DocsGPT.git
synced 2026-10-14 08:17:34 +00:00
fix: more stability for durable tasks, retry strategy, refactor dead
code
This commit is contained in:
1 parent
114585cd7d
commit
e96ff8658c
27 files changed
+1060
-162
No files matched your search
@@ -1,4 +1,3 @@
|
||||
import json
|
||||
import logging
|
||||
import re
|
||||
import uuid
|
||||
@@ -398,7 +397,7 @@ class ToolExecutor:
|
||||
self.attachments: List[Dict] = []
|
||||
self.client_tools: Optional[List[Dict]] = None
|
||||
self._name_to_tool: Dict[str, Tuple[str, str]] = {}
|
||||
# Per-signature failure counts for invented tool names this turn. After
|
||||
# Per-NAME failure counts for invented tool names this turn. After
|
||||
# ``UNRESOLVABLE_CALL_LIMIT`` the model is handed a directive message
|
||||
# instead of the generic error; this is a prompt-level nudge, not a hard
|
||||
# bound — the loop bound remains ``MAX_TOOL_ITERATIONS``.
|
||||
@@ -895,27 +894,38 @@ class ToolExecutor:
|
||||
a tool call. Fall back to tool names when the mapping has not been built
|
||||
(headless paths, tests). Never the internal tool ids: quoting those
|
||||
tells the model nothing about what to call instead.
|
||||
|
||||
Narrowed to ``tools_dict`` so a call made with a restricted toolset is
|
||||
never told to call something out of scope, and capped: this string is
|
||||
returned as a tool RESULT, so it joins the message history and is
|
||||
re-sent on every later round. Uncapped, a large MCP fleet turns one
|
||||
failed call into kilobytes of prose duplicating the tool schema the
|
||||
provider already received.
|
||||
"""
|
||||
names = sorted(self._tool_to_name.values())
|
||||
scope = set(tools_dict or {})
|
||||
names = sorted(
|
||||
name
|
||||
for (tool_id, _action), name in self._tool_to_name.items()
|
||||
if not scope or tool_id in scope
|
||||
)
|
||||
if not names:
|
||||
names = sorted(
|
||||
{(tool or {}).get("name") or tool_id for tool_id, tool in (tools_dict or {}).items()}
|
||||
)
|
||||
names = [str(name) for name in names if name != exclude]
|
||||
if len(names) > self.MAX_ADVERTISED_TOOL_NAMES:
|
||||
hidden = len(names) - self.MAX_ADVERTISED_TOOL_NAMES
|
||||
names = names[: self.MAX_ADVERTISED_TOOL_NAMES] + [f"and {hidden} more"]
|
||||
return ", ".join(names) if names else "(none available)"
|
||||
|
||||
@staticmethod
|
||||
def _call_signature(llm_name: str, call_args: Any) -> str:
|
||||
"""Stable key for "the model just made this exact call again"."""
|
||||
try:
|
||||
rendered = json.dumps(call_args, sort_keys=True, default=str)
|
||||
except (TypeError, ValueError):
|
||||
rendered = str(call_args)
|
||||
return f"{llm_name}::{rendered}"
|
||||
|
||||
# After this many identical unresolvable calls, refuse rather than re-run.
|
||||
# After this many unresolvable calls to the same name, refuse rather than
|
||||
# re-run.
|
||||
UNRESOLVABLE_CALL_LIMIT = 2
|
||||
|
||||
# Cap on names rendered into a failed-call result; see
|
||||
# :meth:`_available_tool_names`.
|
||||
MAX_ADVERTISED_TOOL_NAMES = 30
|
||||
|
||||
def execute(self, tools_dict: Dict, call, llm_class_name: str):
|
||||
"""Execute a tool call. Yields status events, returns (result, call_id)."""
|
||||
parser = ToolActionParser(llm_class_name, name_mapping=self._name_to_tool)
|
||||
@@ -930,18 +940,26 @@ class ToolExecutor:
|
||||
# third attempt on, hand back a directive message instead of the generic
|
||||
# error. Scoped to an unknown *name*: a registered tool whose arguments
|
||||
# merely failed to decode is recoverable, and refusing it would strand a
|
||||
# working tool for the rest of the turn. Keyed on the raw payload, so two
|
||||
# different malformed bodies stay two different signatures.
|
||||
# working tool for the rest of the turn.
|
||||
#
|
||||
# Keyed on the NAME ALONE. Keying on the payload too made the guard a
|
||||
# no-op in the case it exists for: told a call failed, a model varies
|
||||
# its arguments on the next attempt, minting a fresh counter every
|
||||
# round and never reaching the limit. Arguments cannot rescue an
|
||||
# unknown name anyway — ``ToolActionParser`` resolves from ``call.name``
|
||||
# only — and the "two different malformed bodies" case this used to
|
||||
# protect belongs to REGISTERED tools, which the
|
||||
# ``llm_name not in self._name_to_tool`` gate already excludes.
|
||||
if unresolvable and llm_name not in self._name_to_tool:
|
||||
signature = self._call_signature(llm_name, getattr(call, "arguments", None))
|
||||
failures = self._unresolvable_calls.get(signature, 0)
|
||||
failures = self._unresolvable_calls.get(llm_name, 0)
|
||||
# Count before refusing, so the message and the log escalate rather
|
||||
# than freezing at the limit for the rest of the turn.
|
||||
self._unresolvable_calls[signature] = failures + 1
|
||||
self._unresolvable_calls[llm_name] = failures + 1
|
||||
if failures >= self.UNRESOLVABLE_CALL_LIMIT:
|
||||
repeated = (
|
||||
f"'{llm_name}' has already failed {failures} times with these arguments and "
|
||||
f"will keep failing. Stop calling it and either use a different tool "
|
||||
f"'{llm_name}' has already failed {failures} times and will keep "
|
||||
f"failing — it is not a tool that exists. Stop calling it and "
|
||||
f"either use a different tool "
|
||||
f"({self._available_tool_names(tools_dict, exclude=llm_name)}) or answer without one."
|
||||
)
|
||||
logger.warning(
|
||||
@@ -987,7 +1005,6 @@ class ToolExecutor:
|
||||
if name_is_known
|
||||
else "the tool name could not be resolved and its arguments were not a JSON object"
|
||||
)
|
||||
error_message = f"Error: Failed to parse LLM tool call. Tool name: {llm_name}"
|
||||
logger.error(
|
||||
"tool_call_parse_failed",
|
||||
extra={
|
||||
@@ -1029,7 +1046,6 @@ class ToolExecutor:
|
||||
return tool_call_data["result"], call_id
|
||||
|
||||
if tool_id not in tools_dict:
|
||||
error_message = f"Error: Tool ID '{tool_id}' extracted from LLM call not found in available tools_dict. Available IDs: {list(tools_dict.keys())}"
|
||||
logger.error(
|
||||
"tool_id_not_found",
|
||||
extra={
|
||||
|
||||
@@ -15,7 +15,7 @@ import copy
|
||||
import json
|
||||
import logging
|
||||
import uuid
|
||||
from typing import Any, Dict, List, Optional
|
||||
from typing import Any, Dict, List, Optional, Tuple
|
||||
|
||||
from application.agents.tools.artifact_ref import resolve_artifact_id
|
||||
from application.agents.tools.base import Tool
|
||||
@@ -597,11 +597,10 @@ class ArtifactGeneratorTool(Tool):
|
||||
def _create(self, **kwargs: Any) -> Dict[str, Any]:
|
||||
"""Validate, render, and persist a new artifact at version 1."""
|
||||
kind = kwargs.get("kind")
|
||||
spec = self._coerce_spec(kwargs.get("spec"))
|
||||
title = kwargs.get("title")
|
||||
if kind not in _KIND_INFO:
|
||||
return {"status": "error", "error": f"unsupported kind: {kind!r}; expected one of {sorted(_KIND_INFO)}."}
|
||||
valid = self._validate(kind, spec)
|
||||
spec, valid = self._validate(kind, kwargs.get("spec"))
|
||||
if valid is not None:
|
||||
return valid
|
||||
|
||||
@@ -674,8 +673,7 @@ class ArtifactGeneratorTool(Tool):
|
||||
self, artifact_id: str, kind: str, spec: Any, action: str, title: Optional[str] = None
|
||||
) -> Dict[str, Any]:
|
||||
"""Validate the new spec, re-render, and append the next version of an existing artifact."""
|
||||
spec = self._coerce_spec(spec)
|
||||
valid = self._validate(kind, spec)
|
||||
spec, valid = self._validate(kind, spec)
|
||||
if valid is not None:
|
||||
return valid
|
||||
rendered = self._render(kind, spec)
|
||||
@@ -736,16 +734,30 @@ class ArtifactGeneratorTool(Tool):
|
||||
return spec
|
||||
return parsed if isinstance(parsed, dict) else spec
|
||||
|
||||
def _validate(self, kind: str, spec: Any) -> Optional[Dict[str, Any]]:
|
||||
"""Return an error payload when ``spec`` is invalid for ``kind``, else None."""
|
||||
def _validate(self, kind: str, spec: Any) -> Tuple[Any, Optional[Dict[str, Any]]]:
|
||||
"""Validate ``spec`` for ``kind``, returning ``(spec, error_payload)``.
|
||||
|
||||
The coerced spec comes back with the verdict so a caller cannot
|
||||
validate one value and then render another: returning only the error
|
||||
left the caller holding the original, and a stringified spec that
|
||||
passed validation here would be written to spec.json as a JSON
|
||||
*string*, which the renderer cannot read.
|
||||
|
||||
Args:
|
||||
kind: Artifact kind, a key of ``_SCHEMAS``.
|
||||
spec: The spec as received, possibly JSON-encoded.
|
||||
|
||||
Returns:
|
||||
``(coerced_spec, None)`` when valid, else ``(coerced_spec, error)``.
|
||||
"""
|
||||
spec = self._coerce_spec(spec)
|
||||
if not isinstance(spec, dict):
|
||||
return {"status": "error", "error": "spec must be a JSON object."}
|
||||
return spec, {"status": "error", "error": "spec must be a JSON object."}
|
||||
try:
|
||||
jsonschema.validate(spec, _SCHEMAS[kind])
|
||||
except jsonschema.ValidationError as exc:
|
||||
return {"status": "error", "error": f"invalid {kind} spec: {exc.message}"}
|
||||
return None
|
||||
return spec, {"status": "error", "error": f"invalid {kind} spec: {exc.message}"}
|
||||
return spec, None
|
||||
|
||||
def _load_current(self, raw_id: Any) -> Dict[str, Any]:
|
||||
"""Resolve a short ref/uuid to its parent-scoped artifact and current-version spec for edit/rewrite."""
|
||||
@@ -804,10 +816,9 @@ class ArtifactGeneratorTool(Tool):
|
||||
|
||||
def _render(self, kind: str, spec: Any) -> Dict[str, Any]:
|
||||
"""Run the fixed renderer in the sandbox and return the produced file bytes."""
|
||||
# ``_validate`` coerces a stringified spec internally but returns only an
|
||||
# error payload, so validating and rendering the same value is the
|
||||
# caller's job. Coerce here too: a caller that skipped it would otherwise
|
||||
# pass validation and then write a JSON *string* to spec.json.
|
||||
# Callers reach here with the spec ``_validate`` handed back, which is
|
||||
# already coerced. Kept as a cheap guard for direct callers: it is an
|
||||
# ``isinstance`` check, not a re-parse, once the value is a dict.
|
||||
spec = self._coerce_spec(spec)
|
||||
session_id = self._resolve_session_id()
|
||||
if session_id is None:
|
||||
|
||||
@@ -0,0 +1,55 @@
|
||||
"""0030 superseded_messages — distinguish a replaced turn from a lost answer.
|
||||
|
||||
``truncate_after`` deletes the tail of a conversation on retry/edit, but a
|
||||
stream can still own one of those rows: the SSE keepalive pump drains the
|
||||
generator after a client disconnect, so the old stream runs to completion and
|
||||
then finalizes into a row that no longer exists. That produced an ERROR-level
|
||||
``answer_persist_failed`` — indistinguishable from a genuinely orphaned answer,
|
||||
at the rate users hit retry mid-answer.
|
||||
|
||||
The supersede and the late finalize usually happen in DIFFERENT worker
|
||||
processes, so the signal has to be durable. This table is that signal: one row
|
||||
per superseded message, written in the same transaction as the delete. There is
|
||||
deliberately NO foreign key to ``conversation_messages`` — the row it describes
|
||||
is being deleted microseconds later, and a CASCADE would take the tombstone
|
||||
with it.
|
||||
|
||||
Rows are swept by the existing retention beat; ``superseded_at`` is indexed for
|
||||
that. Idempotent both ways.
|
||||
|
||||
Revision ID: 0030_superseded_messages
|
||||
Revises: 0029_agent_guardrails
|
||||
"""
|
||||
|
||||
from typing import Sequence, Union
|
||||
|
||||
from alembic import op
|
||||
|
||||
|
||||
revision: str = "0030_superseded_messages"
|
||||
down_revision: Union[str, None] = "0029_agent_guardrails"
|
||||
branch_labels: Union[str, Sequence[str], None] = None
|
||||
depends_on: Union[str, Sequence[str], None] = None
|
||||
|
||||
|
||||
def upgrade() -> None:
|
||||
op.execute(
|
||||
"""
|
||||
CREATE TABLE IF NOT EXISTS superseded_messages (
|
||||
message_id uuid PRIMARY KEY,
|
||||
conversation_id uuid NOT NULL,
|
||||
superseded_at timestamptz NOT NULL DEFAULT clock_timestamp()
|
||||
);
|
||||
"""
|
||||
)
|
||||
op.execute(
|
||||
"""
|
||||
CREATE INDEX IF NOT EXISTS ix_superseded_messages_superseded_at
|
||||
ON superseded_messages (superseded_at);
|
||||
"""
|
||||
)
|
||||
|
||||
|
||||
def downgrade() -> None:
|
||||
op.execute("DROP INDEX IF EXISTS ix_superseded_messages_superseded_at;")
|
||||
op.execute("DROP TABLE IF EXISTS superseded_messages;")
|
||||
@@ -1047,22 +1047,50 @@ class BaseAnswerResource:
|
||||
# `ok`, because activity logging never observes the DB.
|
||||
# Emit a distinct, countable signal instead.
|
||||
if finalize_outcome is MessageUpdateOutcome.NOT_FOUND:
|
||||
logger.error(
|
||||
"answer_persist_failed: message row %s no longer "
|
||||
"exists; %d chars of answer were produced and "
|
||||
"could not be saved (conversation=%s)",
|
||||
reserved_message_id,
|
||||
len(response_full or ""),
|
||||
conversation_id,
|
||||
extra={
|
||||
"alert": "answer_persist_failed",
|
||||
"message_id": reserved_message_id,
|
||||
"conversation_id": (
|
||||
str(conversation_id) if conversation_id else None
|
||||
),
|
||||
"answer_length": len(response_full or ""),
|
||||
},
|
||||
# The row can be gone for two very different reasons.
|
||||
# A retry/edit deliberately replaced this turn — the
|
||||
# user asked for the answer to be discarded, and the
|
||||
# cancel flag could not reach us because the ticker
|
||||
# that sets it lives in the superseding request's own
|
||||
# process. That is routine and must not page anyone.
|
||||
# Anything else is a genuinely orphaned answer.
|
||||
superseded = self.conversation_service.was_superseded(
|
||||
reserved_message_id
|
||||
)
|
||||
if superseded:
|
||||
logger.info(
|
||||
"stream superseded: message row %s was replaced "
|
||||
"by a newer turn after %d chars; discarding "
|
||||
"(conversation=%s)",
|
||||
reserved_message_id,
|
||||
len(response_full or ""),
|
||||
conversation_id,
|
||||
extra={
|
||||
"alert": "stream_superseded",
|
||||
"message_id": reserved_message_id,
|
||||
"conversation_id": (
|
||||
str(conversation_id) if conversation_id else None
|
||||
),
|
||||
"answer_length": len(response_full or ""),
|
||||
},
|
||||
)
|
||||
else:
|
||||
logger.error(
|
||||
"answer_persist_failed: message row %s no longer "
|
||||
"exists; %d chars of answer were produced and "
|
||||
"could not be saved (conversation=%s)",
|
||||
reserved_message_id,
|
||||
len(response_full or ""),
|
||||
conversation_id,
|
||||
extra={
|
||||
"alert": "answer_persist_failed",
|
||||
"message_id": reserved_message_id,
|
||||
"conversation_id": (
|
||||
str(conversation_id) if conversation_id else None
|
||||
),
|
||||
"answer_length": len(response_full or ""),
|
||||
},
|
||||
)
|
||||
else:
|
||||
conversation_id = self.conversation_service.save_conversation(
|
||||
conversation_id,
|
||||
@@ -1379,6 +1407,26 @@ class BaseAnswerResource:
|
||||
return
|
||||
except Exception as e:
|
||||
logger.error(f"Error in stream: {str(e)}", exc_info=True)
|
||||
# This process took the resume claim, so it owns releasing it. The
|
||||
# only other way back is ``revert_stale_resuming``'s 600 s grace,
|
||||
# which leaves the user locked out of their own conversation for
|
||||
# ten minutes after a resume that errored: ``load_state`` sees
|
||||
# only ``pending`` rows, so the paused turn is still resumable but
|
||||
# invisible, and every retry inside the window gets another 409.
|
||||
# Not on the ``StreamSuperseded`` path above — there the turn was
|
||||
# deliberately replaced and the row is legitimately gone.
|
||||
if _continuation and conversation_id:
|
||||
try:
|
||||
ContinuationService().release_claim(
|
||||
str(conversation_id),
|
||||
decoded_token.get("sub", "local"),
|
||||
)
|
||||
except Exception as release_err:
|
||||
logger.error(
|
||||
f"Failed to release resume claim after a failed "
|
||||
f"resume: {release_err}",
|
||||
exc_info=True,
|
||||
)
|
||||
if reserved_message_id is not None:
|
||||
try:
|
||||
self.conversation_service.finalize_message(
|
||||
|
||||
@@ -174,6 +174,27 @@ class ContinuationService:
|
||||
)
|
||||
return deleted
|
||||
|
||||
def release_claim(self, conversation_id: str, user: str) -> bool:
|
||||
"""Return a claimed row to ``pending`` after a resume failed.
|
||||
|
||||
Returns:
|
||||
True if a claim was released.
|
||||
"""
|
||||
with db_session() as conn:
|
||||
conv = ConversationsRepository(conn).get_by_legacy_id(conversation_id)
|
||||
if conv is not None:
|
||||
pg_conv_id = conv["id"]
|
||||
elif looks_like_uuid(conversation_id):
|
||||
pg_conv_id = conversation_id
|
||||
else:
|
||||
return False
|
||||
released = PendingToolStateRepository(conn).release_claim(pg_conv_id, user)
|
||||
if released:
|
||||
logger.info(
|
||||
f"Released resume claim for conversation {conversation_id}"
|
||||
)
|
||||
return released
|
||||
|
||||
def mark_resuming(self, conversation_id: str, user: str) -> bool:
|
||||
"""Flip the pending row to ``resuming`` so a crashed resume can be retried."""
|
||||
with db_session() as conn:
|
||||
|
||||
@@ -340,6 +340,20 @@ class ConversationService:
|
||||
message_id, status,
|
||||
)
|
||||
|
||||
def was_superseded(self, message_id: str) -> bool:
|
||||
"""True when a retry/edit truncation deleted this message's row.
|
||||
|
||||
Args:
|
||||
message_id: The reserved message id the stream was writing to.
|
||||
|
||||
Returns:
|
||||
True if the row was deliberately superseded rather than lost.
|
||||
"""
|
||||
if not message_id:
|
||||
return False
|
||||
with db_readonly() as conn:
|
||||
return ConversationsRepository(conn).was_superseded(message_id)
|
||||
|
||||
def heartbeat_message(self, message_id: str) -> bool:
|
||||
"""Bump ``message_metadata.last_heartbeat_at`` so the reconciler's
|
||||
staleness sweep counts the row as alive. No-ops on terminal rows.
|
||||
|
||||
@@ -4,10 +4,11 @@ from __future__ import annotations
|
||||
|
||||
import logging
|
||||
import uuid
|
||||
from contextlib import contextmanager
|
||||
from datetime import datetime, timezone
|
||||
from typing import Any, Dict, Optional, TYPE_CHECKING
|
||||
from typing import Any, Dict, Iterator, Optional, TYPE_CHECKING
|
||||
|
||||
from sqlalchemy import Connection
|
||||
from sqlalchemy import Connection, Engine
|
||||
|
||||
from application.api.user.idempotency import MAX_TASK_ATTEMPTS
|
||||
from application.core.settings import settings
|
||||
@@ -60,29 +61,54 @@ def run_reconciliation() -> Dict[str, Any]:
|
||||
# ``(user_id, event_type, payload, scope)``.
|
||||
events: list[tuple] = []
|
||||
|
||||
# Each sweep below commits in its own transaction, but the queued
|
||||
# user-facing events are fanned out once, at the end. Without the
|
||||
# ``finally``, a transient DB error in a later sweep discards events whose
|
||||
# writes already landed — and the loss is permanent, because every sweep
|
||||
# filters out the rows it just made terminal (``find_and_lock_stalled_
|
||||
# ingests`` looks only at ``status='active'``, ``find_and_lock_stuck_
|
||||
# messages`` only at pending/streaming), so no later tick re-finds them to
|
||||
# re-emit. The user is left with an upload toast spinning on "Training..."
|
||||
# forever. Seen live on 2026-08-21 when an Azure DNS blip took Postgres
|
||||
# unreachable mid-tick.
|
||||
# Each sweep below commits in its own transaction, and the queued
|
||||
# user-facing events are fanned out once, at the end. The ``finally`` is
|
||||
# what makes a LATER sweep's failure non-destructive: without it, a
|
||||
# transient DB error discards events whose writes already landed — and the
|
||||
# loss is permanent, because every sweep filters out the rows it just made
|
||||
# terminal (``find_and_lock_stalled_ingests`` looks only at
|
||||
# ``status='active'``, ``find_and_lock_stuck_messages`` only at
|
||||
# pending/streaming), so no later tick re-finds them to re-emit. The user
|
||||
# is left with an upload toast spinning on "Training..." forever. Seen
|
||||
# live on 2026-08-21 when an Azure DNS blip took Postgres unreachable
|
||||
# mid-tick.
|
||||
#
|
||||
# Publish-after-commit is preserved by ``_sweep``: each sweep stages its
|
||||
# own events and they only reach ``events`` once that sweep's transaction
|
||||
# has committed. A sweep that raises PARTWAY THROUGH takes its staged
|
||||
# events down with its rolled-back writes, which is the point — otherwise
|
||||
# the ``finally`` would fan out terminal events for rows that are still
|
||||
# active, and the next tick would re-find those rows and emit a duplicate.
|
||||
try:
|
||||
return _run_sweeps(engine, summary, events)
|
||||
finally:
|
||||
_publish_events(events)
|
||||
|
||||
|
||||
def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[str, Any]:
|
||||
@contextmanager
|
||||
def _sweep(engine: Engine, events: list[tuple]) -> Iterator[tuple[Connection, list[tuple]]]:
|
||||
"""Open one sweep transaction, staging its events until it commits.
|
||||
|
||||
Yields ``(conn, staged)``. Append user-facing events to ``staged``, never
|
||||
to ``events`` directly: ``staged`` is merged into ``events`` only after the
|
||||
``engine.begin()`` block exits cleanly, so a sweep that raises mid-loop
|
||||
publishes nothing for the writes Postgres just rolled back.
|
||||
"""
|
||||
staged: list[tuple] = []
|
||||
with engine.begin() as conn:
|
||||
yield conn, staged
|
||||
events.extend(staged)
|
||||
|
||||
|
||||
def _run_sweeps(engine: Engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[str, Any]:
|
||||
"""Run every reconciler sweep, appending user-facing events to ``events``.
|
||||
|
||||
Split out of :func:`run_reconciliation` so the caller can guarantee the
|
||||
queued events are published even when a sweep raises partway through.
|
||||
Split out of :func:`run_reconciliation` so the caller can guarantee that
|
||||
events from sweeps that already COMMITTED are published even when a later
|
||||
sweep raises. Each sweep stages into its own list via :func:`_sweep`; see
|
||||
the comment in :func:`run_reconciliation` for why staging matters.
|
||||
"""
|
||||
with engine.begin() as conn:
|
||||
with _sweep(engine, events) as (conn, staged):
|
||||
repo = ReconciliationRepository(conn)
|
||||
pt_repo = PendingToolStateRepository(conn)
|
||||
for msg in repo.find_and_lock_stuck_messages():
|
||||
@@ -115,7 +141,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
# been told the approval was cleared, so landing an answer
|
||||
# here would contradict what the user was shown.
|
||||
repo.mark_message_approval_cleared(msg["id"])
|
||||
events.append(
|
||||
staged.append(
|
||||
(
|
||||
str(user_id),
|
||||
"tool.approval.cleared",
|
||||
@@ -137,7 +163,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
},
|
||||
)
|
||||
|
||||
with engine.begin() as conn:
|
||||
with _sweep(engine, events) as (conn, staged):
|
||||
repo = ReconciliationRepository(conn)
|
||||
for row in repo.find_and_lock_proposed_tool_calls():
|
||||
repo.mark_tool_call_failed(
|
||||
@@ -161,7 +187,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
},
|
||||
)
|
||||
|
||||
with engine.begin() as conn:
|
||||
with _sweep(engine, events) as (conn, staged):
|
||||
repo = ReconciliationRepository(conn)
|
||||
for row in repo.find_and_lock_executed_tool_calls():
|
||||
repo.mark_tool_call_failed(
|
||||
@@ -192,7 +218,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
# worker kill, no rollback of the partial embed. The 'stalled' flag
|
||||
# ends the re-alert loop and drives the "indexing failed" badge the
|
||||
# sources list derives from this row.
|
||||
with engine.begin() as conn:
|
||||
with _sweep(engine, events) as (conn, staged):
|
||||
repo = ReconciliationRepository(conn)
|
||||
for row in repo.find_and_lock_stalled_ingests():
|
||||
summary["ingests_stalled"] += 1
|
||||
@@ -214,7 +240,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
user_id = row.get("user_id")
|
||||
source_id = row.get("source_id")
|
||||
if user_id and source_id:
|
||||
events.append(
|
||||
staged.append(
|
||||
(
|
||||
str(user_id),
|
||||
"source.ingest.failed",
|
||||
@@ -235,7 +261,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
# via ``_lookup_completed`` returning None for the whole 24 h TTL.
|
||||
# Promote to ``failed`` so a retry can re-claim and either resume
|
||||
# or fail loudly.
|
||||
with engine.begin() as conn:
|
||||
with _sweep(engine, events) as (conn, staged):
|
||||
repo = ReconciliationRepository(conn)
|
||||
for row in repo.find_stuck_idempotency_pending(
|
||||
max_attempts=MAX_TASK_ATTEMPTS,
|
||||
@@ -271,7 +297,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
stuck_age = max(
|
||||
15, int(_settings.SCHEDULE_RUN_TIMEOUT // 60) + 5,
|
||||
)
|
||||
with engine.begin() as conn:
|
||||
with _sweep(engine, events) as (conn, staged):
|
||||
runs_repo = ScheduleRunsRepository(conn)
|
||||
schedules_repo = SchedulesRepository(conn)
|
||||
for run in runs_repo.list_stuck_running(age_minutes=stuck_age):
|
||||
@@ -292,7 +318,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
schedules_repo, str(run["schedule_id"]),
|
||||
)
|
||||
summary["schedule_runs_failed"] += 1
|
||||
events.extend(
|
||||
staged.extend(
|
||||
_schedule_terminal_events(
|
||||
run,
|
||||
error_type="timeout",
|
||||
@@ -315,7 +341,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
|
||||
# Q7: scheduler runs orphaned in 'pending' — dispatcher committed but
|
||||
# apply_async failed (broker outage / crash mid-dispatch).
|
||||
with engine.begin() as conn:
|
||||
with _sweep(engine, events) as (conn, staged):
|
||||
runs_repo = ScheduleRunsRepository(conn)
|
||||
schedules_repo = SchedulesRepository(conn)
|
||||
for run in runs_repo.list_stuck_pending(age_minutes=stuck_age):
|
||||
@@ -336,7 +362,7 @@ def _run_sweeps(engine, summary: Dict[str, Any], events: list[tuple]) -> Dict[st
|
||||
schedules_repo, str(run["schedule_id"]),
|
||||
)
|
||||
summary["schedule_runs_failed"] += 1
|
||||
events.extend(
|
||||
staged.extend(
|
||||
_schedule_terminal_events(
|
||||
run,
|
||||
error_type="internal",
|
||||
|
||||
@@ -28,24 +28,44 @@ logger = logging.getLogger(__name__)
|
||||
# durability story is grep-able next to the body. Combined with
|
||||
# ``autoretry_for=(Exception,)`` and a bounded ``max_retries`` so a poison
|
||||
# message can't loop forever.
|
||||
#
|
||||
# ``retry_backoff`` is the factor, NOT a boolean toggle: celery's
|
||||
# ``add_autoretry_behaviour`` OVERWRITES ``retry_kwargs["countdown"]`` whenever
|
||||
# it is truthy (celery/app/autoretry.py). With the old ``retry_backoff=True``
|
||||
# the factor was ``int(max(1.0, True)) == 1``, so the declared 60 s countdown
|
||||
# never reached ``task.retry`` and the three waits were jittered 0-1 s, 0-2 s
|
||||
# and 0-4 s — a whole retry envelope of at most 7 seconds. A 3.5-minute network
|
||||
# blip (2026-08-21) therefore exhausted every attempt and published a terminal
|
||||
# ``source.ingest.failed`` / ``attachment.failed`` to the user.
|
||||
# Factor 30 gives 30 s / 60 s / 120 s (full-jittered, capped by celery's
|
||||
# ``retry_backoff_max`` default of 600 s), which actually spans an outage of
|
||||
# that length. ``countdown`` is deliberately absent: leaving it in only
|
||||
# documents a value the library discards.
|
||||
# the factor was ``int(max(1.0, True)) == 1``, so the three waits were jittered
|
||||
# 0-1 s, 0-2 s and 0-4 s — a whole retry envelope of at most 7 seconds. A
|
||||
# 3.5-minute network blip (2026-08-21) therefore exhausted every attempt and
|
||||
# published a terminal ``source.ingest.failed`` / ``attachment.failed``.
|
||||
#
|
||||
# celery applies FULL JITTER (``retry_jitter`` defaults to True), so each wait
|
||||
# is drawn uniformly from ``[0, factor * 2**retries]`` — the ceilings are NOT
|
||||
# the waits, and the envelope is a distribution, not a guarantee. Factor 60
|
||||
# gives ceilings 60/120/240 s: a median envelope of ~210 s, which covers a
|
||||
# 60 s blip ~98% of the time and a 120 s blip ~85%. Factor 30 would have
|
||||
# covered the 210 s incident 0% of the time, because its 210 s nominal
|
||||
# maximum was reachable only by drawing all three waits at their ceiling.
|
||||
# Raising ``max_retries`` would buy more headroom but is deliberately not
|
||||
# done here: attempt 6 would newly reach the ``MAX_TASK_ATTEMPTS=5``
|
||||
# poison-loop guard in ``idempotency.py``, which is a separate behaviour
|
||||
# change from widening the waits.
|
||||
#
|
||||
# Jitter is deliberately left ON. These nine task types share their
|
||||
# dependencies (Postgres, object storage, the embedding provider), so an
|
||||
# outage fails them all at once; ``retry_jitter=False`` would wake every
|
||||
# in-flight task at the same instant and stampede the service that just
|
||||
# recovered.
|
||||
#
|
||||
# ``max_retries`` is passed at the top level rather than inside
|
||||
# ``retry_kwargs``: celery captures that dict BY REFERENCE and writes
|
||||
# ``retry_kwargs["countdown"]`` into it on every retry, so one shared dict
|
||||
# spread across all the decorators below would let concurrent retries race
|
||||
# and would permanently mutate this module constant.
|
||||
DURABLE_TASK = dict(
|
||||
bind=True,
|
||||
acks_late=True,
|
||||
autoretry_for=(Exception,),
|
||||
retry_kwargs={"max_retries": 3},
|
||||
retry_backoff=30,
|
||||
max_retries=3,
|
||||
retry_backoff=60,
|
||||
)
|
||||
|
||||
|
||||
@@ -706,11 +726,21 @@ def reconciliation_task(self):
|
||||
|
||||
try:
|
||||
return run_reconciliation()
|
||||
except Exception as exc: # noqa: BLE001 - housekeeping must never crash the beat loop
|
||||
logging.getLogger(__name__).warning(
|
||||
"reconciliation_task failed; the next beat retries: %s", exc,
|
||||
)
|
||||
return {"messages_failed": 0, "tool_calls_failed": 0, "error": True}
|
||||
except Exception: # noqa: BLE001 - housekeeping must never crash the beat loop
|
||||
# ``exception`` not ``warning``: without the traceback a programming
|
||||
# error in a sweep logs one context-free line every 30 s forever and
|
||||
# there is no way to locate it. Celery still records the tick as
|
||||
# SUCCESS because the exception is swallowed here, so this log is the
|
||||
# only channel that carries the stack.
|
||||
logger.exception("reconciliation_task failed; the next beat retries")
|
||||
return {
|
||||
"messages_failed": 0,
|
||||
"tool_calls_failed": 0,
|
||||
"ingests_stalled": 0,
|
||||
"attachments_stalled": 0,
|
||||
"schedule_runs_failed": 0,
|
||||
"error": True,
|
||||
}
|
||||
|
||||
|
||||
@celery.task(bind=True, acks_late=False)
|
||||
@@ -732,11 +762,20 @@ def cleanup_message_events(self):
|
||||
MessageEventsRepository,
|
||||
)
|
||||
|
||||
from application.storage.db.repositories.conversations import (
|
||||
ConversationsRepository,
|
||||
)
|
||||
|
||||
ttl_days = settings.MESSAGE_EVENTS_RETENTION_DAYS
|
||||
engine = get_engine()
|
||||
with engine.begin() as conn:
|
||||
deleted = MessageEventsRepository(conn).cleanup_older_than(ttl_days)
|
||||
return {"deleted": deleted, "ttl_days": ttl_days}
|
||||
# Supersede tombstones ride the same beat: both are per-stream
|
||||
# bookkeeping with the same retention story.
|
||||
tombstones = ConversationsRepository(conn).cleanup_superseded_older_than(
|
||||
ttl_days
|
||||
)
|
||||
return {"deleted": deleted, "superseded_deleted": tombstones, "ttl_days": ttl_days}
|
||||
|
||||
|
||||
@celery.task(bind=True, acks_late=False)
|
||||
|
||||
@@ -97,6 +97,31 @@ class LLMResponse:
|
||||
return bool(self.tool_calls) and self.finish_reason == "tool_calls"
|
||||
|
||||
|
||||
def _is_restated_payload(existing: str, incoming: str) -> bool:
|
||||
"""True when ``incoming`` restates an already-complete ``existing`` payload.
|
||||
|
||||
Genuine argument deltas are fragments: a strict prefix of a single
|
||||
top-level JSON object can never parse, because the outer brace balances
|
||||
only at the final character. So "``existing`` parses on its own" is a
|
||||
reliable signal that it is finished and ``incoming`` is a restatement
|
||||
rather than a continuation.
|
||||
|
||||
The character check runs first and is what keeps this O(1) per frame —
|
||||
parsing the accumulator on every delta would be quadratic in the number
|
||||
of frames, which is 100 ms+ of CPU for a large artifact spec streamed a
|
||||
few characters at a time.
|
||||
"""
|
||||
if not existing or not incoming:
|
||||
return False
|
||||
if existing.rstrip()[-1:] not in ("}", "]") or incoming.lstrip()[:1] not in ("{", "["):
|
||||
return False
|
||||
try:
|
||||
json.loads(existing)
|
||||
except ValueError:
|
||||
return False
|
||||
return True
|
||||
|
||||
|
||||
class LLMHandler(ABC):
|
||||
"""Abstract base class for LLM handlers."""
|
||||
|
||||
@@ -1422,7 +1447,20 @@ class LLMHandler(ABC):
|
||||
elif isinstance(existing.arguments, str) and isinstance(
|
||||
call.arguments, str
|
||||
):
|
||||
existing.arguments += call.arguments
|
||||
if _is_restated_payload(
|
||||
existing.arguments, call.arguments
|
||||
):
|
||||
# Some OpenAI-compatible gateways restate
|
||||
# the WHOLE argument payload on the finish
|
||||
# frame for an index instead of streaming
|
||||
# deltas. Appending produced '{...}{...}',
|
||||
# which never parses, so the tool call
|
||||
# failed on every one of the turn's
|
||||
# MAX_TOOL_ITERATIONS rounds while the turn
|
||||
# still reported status='complete'.
|
||||
existing.arguments = call.arguments
|
||||
else:
|
||||
existing.arguments += call.arguments
|
||||
else:
|
||||
# Complete (non-delta) payloads: latest wins.
|
||||
existing.arguments = call.arguments
|
||||
|
||||
@@ -655,6 +655,28 @@ message_events_table = Table(
|
||||
)
|
||||
|
||||
|
||||
|
||||
# One row per message deleted by ``truncate_after``. A stream that outlives its
|
||||
# own row — the SSE pump drains a disconnected generator to completion — reads
|
||||
# this to tell "the user replaced this turn" (expected) from "an answer was
|
||||
# genuinely orphaned" (an incident). Deliberately no FK to
|
||||
# ``conversation_messages``: the row it describes is deleted in the same
|
||||
# transaction, and a CASCADE would take the tombstone with it.
|
||||
superseded_messages_table = Table(
|
||||
"superseded_messages",
|
||||
metadata,
|
||||
Column("message_id", UUID(as_uuid=True), primary_key=True, nullable=False),
|
||||
Column("conversation_id", UUID(as_uuid=True), nullable=False),
|
||||
Column(
|
||||
"superseded_at",
|
||||
DateTime(timezone=True),
|
||||
nullable=False,
|
||||
server_default=func.clock_timestamp(),
|
||||
index=True,
|
||||
),
|
||||
)
|
||||
|
||||
|
||||
shared_conversations_table = Table(
|
||||
"shared_conversations",
|
||||
metadata,
|
||||
|
||||
@@ -1167,16 +1167,23 @@ class ConversationsRepository:
|
||||
turns — so the rows go, but any non-terminal one is first stamped
|
||||
terminal, which leaves an audit trail of what was superseded.
|
||||
|
||||
That stamp does NOT survive: the UPDATE and the DELETE below run the
|
||||
same ``position > :pos`` predicate in one transaction, so every stamped
|
||||
row is removed microseconds later and the owning stream's late
|
||||
``finalize_message`` correctly reports ``NOT_FOUND``, not
|
||||
``ALREADY_FAILED``. Do not rely on the stamp for anything but the
|
||||
``RETURNING id`` log line. A stream superseded less than
|
||||
``STREAM_HEARTBEAT_INTERVAL`` before it finishes is never cancelled
|
||||
(the ticker in ``api/answer/routes/base.py`` is the only thing that
|
||||
sets the cancel flag), so it runs to completion and raises
|
||||
``answer_persist_failed`` with an answer nothing can save.
|
||||
That stamp does NOT survive: the UPDATE's predicate is a subset of the
|
||||
DELETE's (it also filters ``status NOT IN ('complete','failed')``), and
|
||||
both run in one transaction, so every stamped row is removed
|
||||
microseconds later and the owning stream's late ``finalize_message``
|
||||
correctly reports ``NOT_FOUND``, not ``ALREADY_FAILED``. Do not rely on
|
||||
the stamp for anything but the ``RETURNING id`` log line.
|
||||
|
||||
What DOES survive is the ``superseded_messages`` tombstone written
|
||||
below. A stream superseded less than ``STREAM_HEARTBEAT_INTERVAL``
|
||||
before it finishes is never cancelled — the ticker in
|
||||
``api/answer/routes/base.py`` is the only thing that sets the cancel
|
||||
flag, and it cannot be set from here because it is a ``threading.Event``
|
||||
in another worker process — so the stream runs to completion and
|
||||
finalizes into a row that is gone. Without the tombstone that logged an
|
||||
ERROR ``answer_persist_failed``, identical to a genuinely orphaned
|
||||
answer, every time a user hit retry on an answer shorter than the
|
||||
heartbeat interval.
|
||||
|
||||
Args:
|
||||
conversation_id: Conversation whose tail is being trimmed.
|
||||
@@ -1218,6 +1225,22 @@ class ConversationsRepository:
|
||||
conversation_id,
|
||||
", ".join(str(r[0]) for r in superseded),
|
||||
)
|
||||
# Tombstone before the delete, in the same transaction: the late
|
||||
# finalize usually runs in a different worker process, so the signal
|
||||
# has to be durable. No FK, or the CASCADE below would remove it.
|
||||
self._conn.execute(
|
||||
text(
|
||||
"""
|
||||
INSERT INTO superseded_messages (message_id, conversation_id)
|
||||
SELECT id, conversation_id
|
||||
FROM conversation_messages
|
||||
WHERE conversation_id = CAST(:conv_id AS uuid)
|
||||
AND position > :pos
|
||||
ON CONFLICT (message_id) DO NOTHING
|
||||
"""
|
||||
),
|
||||
{"conv_id": conversation_id, "pos": keep_up_to},
|
||||
)
|
||||
result = self._conn.execute(
|
||||
text(
|
||||
"DELETE FROM conversation_messages "
|
||||
@@ -1228,6 +1251,52 @@ class ConversationsRepository:
|
||||
)
|
||||
return result.rowcount
|
||||
|
||||
def was_superseded(self, message_id: str) -> bool:
|
||||
"""True when ``message_id`` was deleted by a retry/edit truncation.
|
||||
|
||||
Lets a stream that outlived its own row tell an expected supersede from
|
||||
a genuinely orphaned answer. See :meth:`truncate_after`.
|
||||
|
||||
Args:
|
||||
message_id: The reserved message id the stream was writing to.
|
||||
|
||||
Returns:
|
||||
True if a tombstone exists for that message.
|
||||
"""
|
||||
if not looks_like_uuid(message_id):
|
||||
return False
|
||||
row = self._conn.execute(
|
||||
text(
|
||||
"SELECT 1 FROM superseded_messages "
|
||||
"WHERE message_id = CAST(:mid AS uuid)"
|
||||
),
|
||||
{"mid": message_id},
|
||||
).fetchone()
|
||||
return row is not None
|
||||
|
||||
def cleanup_superseded_older_than(self, days: int) -> int:
|
||||
"""Delete ``superseded_messages`` tombstones older than ``days``.
|
||||
|
||||
The tombstone only has to outlive the stream that was superseded, which
|
||||
is bounded by the request timeout — days of retention is already
|
||||
generous, and the table has no other reader.
|
||||
|
||||
Args:
|
||||
days: Retention window in days.
|
||||
|
||||
Returns:
|
||||
Number of rows deleted.
|
||||
"""
|
||||
result = self._conn.execute(
|
||||
text(
|
||||
"DELETE FROM superseded_messages "
|
||||
"WHERE superseded_at < clock_timestamp() "
|
||||
"- make_interval(days => :days)"
|
||||
),
|
||||
{"days": days},
|
||||
)
|
||||
return result.rowcount or 0
|
||||
|
||||
def set_feedback(
|
||||
self, conversation_id: str, position: int, feedback: dict | None,
|
||||
) -> bool:
|
||||
|
||||
@@ -176,6 +176,37 @@ class PendingToolStateRepository:
|
||||
)
|
||||
return result.rowcount > 0
|
||||
|
||||
def release_claim(self, conversation_id: str, user_id: str) -> bool:
|
||||
"""Flip a ``resuming`` row back to ``pending`` so a retry can claim it.
|
||||
|
||||
The inverse of :meth:`mark_resuming`, for the process that TOOK the
|
||||
claim to call when its resume fails. Without it the only way back is
|
||||
:meth:`revert_stale_resuming`, whose 600 s grace leaves the user
|
||||
locked out of their own conversation for ten minutes after a resume
|
||||
that errored — the paused turn stays resumable but invisible, because
|
||||
:meth:`load_state` only sees ``pending`` rows.
|
||||
|
||||
Deliberately narrow: it matches on ``status = 'resuming'`` only, so it
|
||||
can never resurrect a row another request has since deleted, and it
|
||||
does not touch ``expires_at`` (the TTL is unrelated to the claim).
|
||||
|
||||
Returns:
|
||||
True when a claim was released.
|
||||
"""
|
||||
result = self._conn.execute(
|
||||
text(
|
||||
"""
|
||||
UPDATE pending_tool_state
|
||||
SET status = 'pending', resumed_at = NULL
|
||||
WHERE conversation_id = CAST(:conv_id AS uuid)
|
||||
AND user_id = :user_id
|
||||
AND status = 'resuming'
|
||||
"""
|
||||
),
|
||||
{"conv_id": conversation_id, "user_id": user_id},
|
||||
)
|
||||
return result.rowcount > 0
|
||||
|
||||
def revert_stale_resuming(
|
||||
self,
|
||||
grace_seconds: int = 600,
|
||||
|
||||
Reference in new issue
Block a user