deer-flow/backend/tests/test_trace_entry_points.py
Nan Gao 6c4c74a504
fix(channels): share chat-to-thread bindings through the database (#6558)
* fix(channels): share chat-to-thread bindings through the database

ChannelManager kept its IM chat-to-thread bindings
(channel_name:chat_id[:topic_id] -> thread_id) in a per-process JSON file,
channels/store.json, loaded once and rewritten whole on every change. With
several Gateway processes a binding created on one replica was invisible to
the others (the next message for the same chat opened a second thread) and
concurrent writers clobbered each other's file.

- New channel_thread_bindings table (migration 0036_channel_thread_bindings)
  and harness package deerflow.persistence.channel_thread_bindings: key PK
  (the legacy composite string), channel_name, chat_id, nullable topic_id,
  thread_id, user_id, epoch created_at/updated_at; index (channel_name,
  chat_id). Dialect upsert keeps created_at; prefix remove and batched
  ON CONFLICT DO NOTHING import.
- app.channels.store.ChannelStore is an async protocol: SqlChannelStore for
  sqlite/postgres, JsonChannelStore (file I/O via asyncio.to_thread) for
  database.backend: memory. resolve_channel_store picks at ChannelService
  construction; ChannelService.start() imports an existing store.json once
  into an empty table and renames it store.json.migrated (a concurrently
  importing peer neither duplicates nor clobbers; a populated table leaves
  the file alone).
- Callers updated: manager, connection_identity.lookup_thread_id, Feishu
  (send() awaits the mapping writer; the synchronous lark callback bridges
  its two store calls to the Gateway loop with a bounded wait), Discord
  (channels_dir).
- Head pins in the 0027_0028/0029/0032/0034/0035 migration tests point at
  the new head; docs (channels and migrations AGENTS.md, CONFIGURATION.md,
  README) and CHANGELOG updated.

* docs(changelog): link the channel thread bindings entry to #6558

* fix(channels): reject only the Gateway loop in the Feishu store bridge

lark-oapi 1.5.5 invokes the message callback synchronously from its async
frame handler, on the private event loop that FeishuChannel._run_ws starts
for the SDK thread. The bridge's guard treated any running loop as unsafe,
so every real inbound message skipped the stored-topic lookup and the
pending-mapping restore: a reply whose parent card was mapped but whose
root was not fell back to the unknown root, and could consume an
unrelated pending clarification.

Only a wait issued from the Gateway loop itself (the loop that executes
the submitted coroutine) is refused now; the SDK's own loop may block for
the bounded wait, as that thread blocked on the JSON rewrite before.
Tests drive _on_message from a worker thread running its own loop, the
production shape, for both the lookup and the write path, and pin the
Gateway-loop refusal.

* fix(channels): defer unresolved Feishu lookups and harden the store.json import

Review follow-ups on the chat-to-thread binding store (#6558):

- Import: a legacy entry whose key, channel_name, chat_id, topic_id,
  thread_id or user_id exceeds its column width is skipped and counted
  with the malformed ones instead of failing the whole batch on
  PostgreSQL (SQLite silently accepted the same row, so the backends
  diverged on one file). The corrupt-file warning now says what each
  caller does: the JSON store starts fresh, the import is skipped and
  the file kept.
- Feishu bridge: store calls run on the Gateway loop under a 3s
  asyncio.wait_for (the SDK loop also services ws keepalives; the old
  10s bound could stall it per message), and the lark-thread wait is
  that budget plus 1s. A deadline or store error is StoreLookupUnresolved,
  never a miss: _on_message no longer routes such a reply onto its
  unknown root (which created a second thread and later overwrote the
  parent alias). The message joins a per-chat FIFO drained on the
  Gateway loop with backoff for up to 30s, then is dropped with a
  warning. _on_message is split into parse / resolve / dispatch so the
  deferred path dispatches the same way; later messages for the chat
  queue behind the deferred one.

* fix(tests): expect follow_redirects in the Jina client kwargs after #5808

#5808 made JinaClient pass follow_redirects=True to httpx.AsyncClient and
updated test_jina_client.py, but test_jina_response_limit.py and
test_jina_retry_after.py still pin the exact client kwargs to proxy and
trust_env, so every backend-unit-tests shard that lands on them fails on
main (the backend unit-test workflow only runs on pull requests, which is
why the push to main did not surface it). Update the two expectations to
include the new keyword.

(cherry picked from commit d5aa23156ce19ce36d95df03953442f83ae6d050)

* Revert "fix(tests): expect follow_redirects in the Jina client kwargs after #5808"

This reverts commit 5bee00bfb09c65a30f77fb4df47a1f82c47ecef7.

* fix(channels): bound deferred Feishu routing by the inbound queue capacity

Review follow-up on #6558: a store outage let every subsequent message for
a chat join the deferred queue with no capacity check (the bus reservation
was only taken after routing succeeded), and each queued message started a
fresh 30s retry budget when it reached the head, so a burst could be
retained for N x 30s and grow without bound.

- Intake is reserved BEFORE routing for every store-backed message
  (bus.reserve_inbound is thread-safe and already used from SDK threads),
  so deferred and live messages share the one configured bound,
  channels.inbound_queue_maxsize; a message that cannot be admitted is
  dropped at once with a warning, never queued or routed as a miss.
- The reservation travels with the message into dispatch (committed by
  _prepare_inbound), is released on the batch path (the flush reserves at
  publish time), on drop after the budget, on a failed deferral, on
  dispatch failure and for every leftover when the drain task is cancelled
  by stop().
- The retry budget runs from the message's arrival: a queued message whose
  budget is spent when it reaches the head is dropped without a lookup.
- The bounded resolver returns the unresolved outcome instead of raising
  it through the tracked task, which logged an ERROR for an expected,
  handled store timeout.
- Upstream's new blocking-io test constructs the store by its old class
  name; it now uses JsonChannelStore.

---------

Co-authored-by: Willem Jiang <willem.jiang@gmail.com>
2026-10-10 14:00:00 +08:00

308 lines
10 KiB
Python

"""Trace binding at the entry points that no ASGI middleware can reach.
``TraceMiddleware`` covers Gateway HTTP traffic (``test_trace_middleware.py``)
and ``DeerFlowClient.stream`` covers embedded callers
(``test_client_langfuse_metadata.py``). The remaining ways work enters DeerFlow
hold no HTTP request at all: the scheduled-task poller, MCP task notification
runs, and IM channels, which keep long-lived provider connections. Each must
bind a trace id of its own, scoped to one unit of work, or everything
downstream falls back to an unattributed id.
"""
from __future__ import annotations
import asyncio
from datetime import UTC, datetime, timedelta
from pathlib import Path
from types import SimpleNamespace
import pytest
from app.channels.manager import ChannelManager
from app.channels.message_bus import InboundMessage, MessageBus
from app.channels.store import JsonChannelStore
from app.scheduler.service import ScheduledTaskService
from deerflow.config.app_config import AppConfig, reset_app_config, set_app_config
from deerflow.trace_context import get_current_trace_id, request_trace_context
# --------------------------------------------------------------------------
# Scheduled tasks
# --------------------------------------------------------------------------
class _StubTaskRepo:
def __init__(self, rows):
self.rows = rows
self.claimed = False
async def claim_due_tasks(self, **_kwargs):
if self.claimed:
return []
self.claimed = True
return self.rows
async def claim_dispatch_lease(self, task_id, **_kwargs):
return next((dict(row) for row in self.rows if row["id"] == task_id), None)
async def release_queued_admission_lease(self, task_id):
return False
async def release_dispatch_lease(self, task_id, **_kwargs):
return True
async def get_internal(self, task_id):
row = next((item for item in self.rows if item["id"] == task_id), None)
return dict(row) if row is not None else None
async def update_after_launch(self, *_args, **_kwargs):
return None
class _StubRunRepo:
async def list_queued_runs(self, *, limit, **_kwargs):
return []
async def expire_queued_runs(self, **_kwargs):
return []
async def recover_expired_launch_claims(self, **_kwargs):
return 0
async def get_active_run(self, task_id):
return None
async def claim_queued_run(self, run_record_id, **_kwargs):
return {"id": run_record_id, "status": "launching"}
async def create(self, **kwargs):
return {"id": kwargs["run_record_id"]}
async def reconcile_launched_run(self, run_record_id, **_kwargs):
return True
async def update_status(self, run_record_id, **_kwargs):
return True
def _scheduled_task(task_id: str) -> dict:
return {
"id": task_id,
"user_id": "user-1",
"thread_id": f"thread-{task_id}",
"context_mode": "reuse_thread",
"assistant_id": "lead_agent",
"prompt": "Summarize thread",
"schedule_type": "once",
"schedule_spec": {"run_at": "2026-07-02T01:00:00+00:00"},
"timezone": "UTC",
}
def _make_service(rows, launch_run) -> ScheduledTaskService:
return ScheduledTaskService(
task_repo=_StubTaskRepo(rows),
task_run_repo=_StubRunRepo(),
launch_run=launch_run,
poll_interval_seconds=5,
lease_seconds=120,
max_concurrent_runs=3,
)
@pytest.mark.asyncio
async def test_scheduled_launch_runs_under_a_bound_trace_id():
launched: list[str | None] = []
async def fake_launch(**kwargs):
launched.append(get_current_trace_id())
return {"run_id": "run-1", "thread_id": kwargs["thread_id"]}
service = _make_service([_scheduled_task("task-1")], fake_launch)
await service.run_once(now=datetime.now(UTC) + timedelta(days=1))
assert launched == [launched[0]]
assert launched[0], "a scheduled occurrence must not launch without a trace id"
@pytest.mark.asyncio
async def test_each_scheduled_occurrence_gets_its_own_trace_id():
"""One id per poll cycle would merge unrelated tasks into a single trace."""
launched: list[str | None] = []
async def fake_launch(**kwargs):
launched.append(get_current_trace_id())
return {"run_id": "run-1", "thread_id": kwargs["thread_id"]}
service = _make_service([_scheduled_task("task-1"), _scheduled_task("task-2")], fake_launch)
await service.run_once(now=datetime.now(UTC) + timedelta(days=1))
assert len(launched) == 2
assert all(launched)
assert launched[0] != launched[1]
@pytest.mark.asyncio
async def test_scheduled_trace_scope_closes_after_the_occurrence():
"""The poller task is long-lived, so a leaked binding would attribute every
later cycle to the first occurrence it ever ran."""
async def fake_launch(**kwargs):
return {"run_id": "run-1", "thread_id": kwargs["thread_id"]}
service = _make_service([_scheduled_task("task-1")], fake_launch)
await service.run_once(now=datetime.now(UTC) + timedelta(days=1))
assert get_current_trace_id() is None
@pytest.mark.asyncio
async def test_manual_trigger_keeps_the_requesting_trace():
"""A manual trigger arrives inside a Gateway request, so the launched run
stays correlated with the call that asked for it."""
launched: list[str | None] = []
async def fake_launch(**kwargs):
launched.append(get_current_trace_id())
return {"run_id": "run-1", "thread_id": kwargs["thread_id"]}
task = _scheduled_task("task-1")
service = _make_service([task], fake_launch)
with request_trace_context("gateway-request-1"):
await service.dispatch_task(task, now=datetime.now(UTC), trigger="manual")
assert launched == ["gateway-request-1"]
# --------------------------------------------------------------------------
# IM channels
# --------------------------------------------------------------------------
def _inbound(index: int) -> InboundMessage:
return InboundMessage(
channel_name="slack",
chat_id="C1",
user_id="U1",
text=f"message-{index}",
metadata={},
)
@pytest.mark.asyncio
async def test_inbound_messages_are_handled_under_distinct_trace_scopes(tmp_path: Path):
"""Channels hold long-lived provider connections, so no ASGI middleware
ever runs for them, and one worker task serves many messages in sequence."""
bus = MessageBus(inbound_queue_maxsize=4)
manager = ChannelManager(
bus=bus,
store=JsonChannelStore(path=tmp_path / "store.json"),
max_concurrency=1,
)
seen: list[str | None] = []
async def capture_handler(msg: InboundMessage) -> None:
seen.append(get_current_trace_id())
manager._handle_message = capture_handler # type: ignore[method-assign]
await manager.start()
try:
await bus.publish_inbound(_inbound(0))
await bus.publish_inbound(_inbound(1))
async with asyncio.timeout(2):
while len(seen) < 2:
await asyncio.sleep(0)
finally:
await manager.stop()
assert all(seen), "an inbound message must not be handled without a trace id"
assert seen[0] != seen[1], "each message is its own unit of work"
assert get_current_trace_id() is None
# --------------------------------------------------------------------------
# Gateway run launchers
# --------------------------------------------------------------------------
@pytest.fixture
def _stub_app_config():
"""Keep the launchers independent from a developer-local config.yaml."""
set_app_config(AppConfig.model_validate({"sandbox": {"use": "deerflow.sandbox.local:LocalSandboxProvider"}}))
yield
reset_app_config()
@pytest.fixture
def launcher_traces(monkeypatch):
"""Capture the trace id bound around each ``start_run`` the launchers make."""
seen: list[str | None] = []
async def fake_start_run(_body, thread_id, _request, **_kwargs):
seen.append(get_current_trace_id())
return SimpleNamespace(run_id="run-1", thread_id=thread_id)
monkeypatch.setattr("app.gateway.services.start_run", fake_start_run)
return seen
@pytest.mark.asyncio
async def test_scheduled_launcher_binds_a_trace_context(_stub_app_config, launcher_traces):
from app.gateway.services import launch_scheduled_thread_run
await launch_scheduled_thread_run(
app=SimpleNamespace(),
thread_id="thread-sched",
assistant_id="lead_agent",
prompt="Summarize thread",
owner_user_id="user-1",
metadata={"scheduled_task_run_id": "run-row-1"},
)
assert launcher_traces[0], "a scheduled launch must not reach start_run untraced"
assert get_current_trace_id() is None
@pytest.mark.asyncio
async def test_mcp_notification_launcher_binds_a_trace_context(_stub_app_config, launcher_traces):
"""Driven from the MCP task service's own background loop, so one scope per
notification keeps every delivery attempt separately correlatable."""
from app.gateway.services import launch_mcp_task_notification_run
for attempt in (1, 2):
await launch_mcp_task_notification_run(
app=SimpleNamespace(),
thread_id="thread-mcp",
assistant_id="lead_agent",
owner_user_id="user-1",
task_id="task-1",
dispatch_version=1,
dispatch_attempt=attempt,
event={"status": "completed"},
)
assert all(launcher_traces)
assert launcher_traces[0] != launcher_traces[1]
assert get_current_trace_id() is None
@pytest.mark.asyncio
async def test_launcher_keeps_the_requesting_trace(_stub_app_config, launcher_traces):
"""Reached from inside a Gateway request -- a manual scheduled trigger --
the launched run stays correlated with the call that asked for it."""
from app.gateway.services import launch_scheduled_thread_run
with request_trace_context("gateway-request-1"):
await launch_scheduled_thread_run(
app=SimpleNamespace(),
thread_id="thread-sched",
assistant_id="lead_agent",
prompt="Summarize thread",
owner_user_id="user-1",
)
assert launcher_traces == ["gateway-request-1"]