wip: first-chunk debug logging — paused waiting for platform-agent logs

2026-04-24 15:17:08 +03:00 · 2026-04-24 15:17:08 +03:00 · c34db0e6c0
commit c34db0e6c0
parent 2a23b30f83
5 changed files with 61 additions and 111 deletions
--- a/.planning/HANDOFF.json
+++ b/.planning/HANDOFF.json
@ -1,90 +1,38 @@
 {
  "version": "1.0",
-  "timestamp": "2026-04-23T11:46:45.938Z",
+  "timestamp": "2026-04-24T12:16:09.301Z",
  "phase": "04",
-  "phase_name": "Matrix MVP: shared agent context and context management commands",
-  "phase_dir": ".planning/phases/04-matrix-mvp-shared-agent-context-and-context-management-comma",
-  "plan": 3,
-  "task": 3,
-  "total_tasks": 3,
+  "phase_name": "matrix-mvp-shared-agent-context-and-context-management",
+  "phase_dir": "04-matrix-mvp-shared-agent-context-and-context-management-comma",
+  "plan": null,
+  "task": null,
+  "total_tasks": null,
  "status": "paused",
  "completed_tasks": [
-    {
-      "id": 1,
-      "name": "Стабилизировать Matrix MVP runtime: numeric platform_chat_id mapping, staged attachments, clean vendored platform repos",
-      "status": "done",
-      "commit": "4524a6a"
-    },
-    {
-      "id": 2,
-      "name": "Локализовать missing-first-chunk bug, оформить финальный bug report и очистить runtime до thin upstream integration boundary",
-      "status": "done",
-      "commit": "0c2884c"
-    },
-    {
-      "id": 3,
-      "name": "Перейти на direct upstream AgentApi per request, убрать local wrapper из prod path и зафиксировать AGENT_BASE_URL как основной runtime contract",
-      "status": "done",
-      "commit": "7d58dd1"
-    }
+    {"id": 1, "name": "docker-compose config mount + MATRIX_AGENT_REGISTRY_PATH", "status": "done"},
+    {"id": 2, "name": "debug logging in sdk/real.py (_stream_agent_events)", "status": "done"},
+    {"id": 3, "name": "debug logging in platform-agent service.py", "status": "done"}
  ],
  "remaining_tasks": [
-    {
-      "id": 4,
-      "name": "Решить, закрываем ли Phase 04 окончательно или продолжаем Matrix через live smoke в реальном окружении",
-      "status": "not_started"
-    },
-    {
-      "id": 5,
-      "name": "Если двигаемся дальше по Matrix, прогнать text/tool/file smoke на direct AgentApi per-request path и проверить отсутствие regressions",
-      "status": "not_started"
-    },
-    {
-      "id": 6,
-      "name": "Если начинаем новую surface, открыть follow-up phase для prod messenger architecture без собственного transport layer",
-      "status": "not_started"
-    }
-  ],
-  "blockers": [
-    {
-      "description": "В worktree остаётся посторонний локальный diff в core/handlers/message.py, не связанный с direct AgentApi fix",
-      "type": "technical",
-      "workaround": "Не смешивать с runtime/surface работой без отдельной задачи; handoff commit этот файл не включает"
-    }
+    {"id": 4, "name": "run docker compose up --build and get platform-agent logs with stream_event lines", "status": "not_started"},
+    {"id": 5, "name": "analyze logs: content_type and langgraph_node to find where first chunk is lost", "status": "not_started"},
+    {"id": 6, "name": "fix in service.py based on findings (filter by node, handle list content, or capture subagent output)", "status": "not_started"}
  ],
+  "blockers": [],
  "human_actions_pending": [
-    {
-      "action": "Выбрать следующий трек: Matrix live validation или планирование новой prod surface вроде Telegram/Max",
-      "context": "Кодовый фикс уже сделан и запушен; дальше работа зависит от продуктового направления, а не от transport-debug",
-      "blocking": false
-    },
-    {
-      "action": "При следующем отдельном planning/cleanup коммите привести STATE/roadmap в полное соответствие с direct upstream per-request решением",
-      "context": "Локальный STATE уже обновлён как checkpoint, но handoff WIP commit включает только HANDOFF и .continue-here",
-      "blocking": false
-    }
+    {"action": "run docker compose up --build and reproduce the alphabet/image truncation bug", "context": "Need platform-agent logs with DEBUG level to see stream_event lines", "blocking": true}
  ],
  "decisions": [
-    {
-      "decision": "Для prod path Matrix surface больше не держит собственный transport layer; используется прямой upstream AgentApi с fresh connection per request",
-      "rationale": "Это убрало reuse-sensitive загрязнение между запросами, после чего missing-first-chunk симптом перестал воспроизводиться локально",
-      "phase": "04"
-    },
-    {
-      "decision": "AGENT_BASE_URL принят как основной runtime contract; AGENT_WS_URL оставлен только как backward-compat fallback в env wiring",
-      "rationale": "Так surface говорит с платформой по их реальному API contract, а не через локальный ws shim",
-      "phase": "04"
-    },
-    {
-      "decision": "Для следующих surfaces не строить custom transport wrapper поверх платформы",
-      "rationale": "Surface должна владеть integration/session boundary, а не альтернативной stream semantics",
-      "phase": "04"
-    }
+    {"decision": "Bug is in platform-agent service.py __astream, not in surfaces bot", "rationale": "Logs show first text chunk already truncated at index=0 level", "phase": "04"},
+    {"decision": "deepagents uses dispatcher+subagent architecture", "rationale": "create_deep_agent wraps SubAgentMiddleware with general-purpose subagent", "phase": "04"},
+    {"decision": "astream_events v2 processes on_chat_model_stream from ALL nodes without filtering", "rationale": "service.py has no namespace/node filtering", "phase": "04"}
  ],
  "uncommitted_files": [
-    ".planning/STATE.md",
-    "core/handlers/message.py"
+    "sdk/real.py (debug logging added)",
+    "docker-compose.yml (config volume mount added)",
+    "config/matrix-agents.example.yaml (label names updated)",
+    "external/platform-agent/src/agent/service.py (debug logging added, in submodule)"
  ],
-  "next_action": "При возобновлении сначала прочитать обновлённый handoff, затем выбрать один из двух треков: либо Matrix live smoke на direct AgentApi per-request path, либо новая phase/spec для prod surface без собственного transport layer",
-  "context_notes": "Старый checkpoint про platform triage устарел. После диалога с платформой runtime переведён на прямой upstream AgentApi с fresh connection per request, локальный wrapper убран из prod path, tests прошли, commit 7d58dd1 запушен в origin/feat/matrix-direct-agent-prototype. Важный вывод для будущей архитектуры surfaces: upstream transport считать authoritative, а локально держать только lifecycle, serialization, attachment forwarding, error mapping и reconciliation."
+  "next_action": "Run: docker compose up --build. Send a message that triggers the bug (e.g. 'Напомни алфавит' after sending an image). Look for stream_event lines in platform-agent-1 logs. Check content_type and langgraph_node values for truncated responses.",
+  "context_notes": "Investigating first-chunk truncation bug in Matrix bot responses. The bug appears when agent uses tools (image analysis) OR when images are in context. Platform-agent uses deepagents framework (dispatcher+subagent pattern). The hypothesis is that on_chat_model_stream events from multiple graph nodes are all forwarded as MsgEventTextChunk without filtering, OR that chunk.content is sometimes a list instead of str causing validation issues. Added logging to confirm. The fix will likely be in service.py: either filter by langgraph_node or handle list content type."
 }
--- a/.planning/phases/04-matrix-mvp-shared-agent-context-and-context-management-comma/.continue-here.md
+++ b/.planning/phases/04-matrix-mvp-shared-agent-context-and-context-management-comma/.continue-here.md
@ -1,62 +1,53 @@
 ---
+context: phase
 phase: 04-matrix-mvp-shared-agent-context-and-context-management-comma
-task: 3
-total_tasks: 3
-status: paused
-last_updated: 2026-04-23T11:46:45.938Z
+task: 4
+total_tasks: 6
+status: in_progress
+last_updated: 2026-04-24T12:16:09.301Z
 ---

 <current_state>
-Phase 04 кодово стабилизирована вокруг direct upstream `AgentApi` per request. Коммит `7d58dd1` уже запушен в `origin/feat/matrix-direct-agent-prototype`. Старый checkpoint в этом файле устарел: после обратной связи от платформы мы убрали extra wrapper из prod path, перестали переиспользовать один websocket между запросами и после этого missing-first-chunk симптом перестал воспроизводиться локально.
+Debugging first-chunk truncation bug in Matrix bot. Logging added to both sdk/real.py and external/platform-agent/src/agent/service.py. Waiting for user to run docker compose up --build and share platform-agent logs with stream_event lines.
 </current_state>

 <completed_work>

- Весь ранее собранный Matrix MVP контекст остаётся валидным: numeric `platform_chat_id`, staged attachments, shared workspace, context commands и Docker packaging уже на месте.
- Продовый runtime path переведён на direct upstream client через `sdk/upstream_agent_api.py`; локальный `sdk/agent_api_wrapper.py` удалён из runtime path.
- `sdk/real.py` теперь на каждый `send_message` и `stream_message` создаёт новый `AgentApi`, делает `connect()`, читает stream и сразу `close()`.
- `AGENT_BASE_URL` зафиксирован как основной runtime contract; `AGENT_WS_URL` оставлен только как backward-compat fallback в env wiring.
- Добавлена регрессия на reuse-sensitive missing-first-chunk сценарий и обновлены runtime/integration tests; `uv run pytest tests -q` прошёл (`196 passed`), `ruff` на затронутых файлах clean.
- Кодовый фикс закоммичен и запушен: `7d58dd1` (`fix: use direct agent api per request`).
- В сессионных выводах зафиксирован новый архитектурный принцип для следующих surfaces: не строить свой transport layer, держать только thin integration/session boundary над upstream transport.
+- docker-compose.yml: added `./config:/app/config:ro` volume mount so MATRIX_AGENT_REGISTRY_PATH works
+- config/matrix-agents.example.yaml: updated labels to Platform/Media
+- sdk/real.py: added structlog debug logging in _stream_agent_events (logs each chunk index + text[:40])
+- external/platform-agent/src/agent/service.py: added logging of langgraph_node, content_type, content[:60] for every on_chat_model_stream event
+
+Bot is running and user confirmed it starts correctly with MATRIX_PLATFORM_BACKEND=real.
 </completed_work>

 <remaining_work>

- Перед следующим кодом выбрать направление:
-  - если продолжаем Matrix, прогнать live smoke в реальном окружении на text/tool/file flow и проверить отсутствие regressions на direct per-request path;
-  - если переходим к Telegram/Max-подобной работе, открыть новую phase/spec под prod surface architecture.
- Привести `.planning/STATE.md` и roadmap в полностью каноничное состояние отдельным planning/cleanup шагом, если хотим закрепить этот checkpoint не только через handoff.
- Не смешивать дальнейшую surface/runtime работу с отдельным локальным diff в `core/handlers/message.py`, пока это не станет явной задачей.
+- Task 4: Get platform-agent debug logs (docker compose up --build, reproduce truncation, share stream_event lines)
+- Task 5: Analyze: check content_type (str vs list), check langgraph_node (which graph node produces the first chunk)
+- Task 6: Fix service.py based on findings
 </remaining_work>

 <decisions_made>

- Matrix prod path должен использовать прямой upstream `AgentApi`, а не surface-owned wrapper с кастомной stream semantics.
- Fresh connection per request принят как дефолтный lifecycle для этой surface, потому что именно reuse websocket оказался чувствительной точкой для missing-first-chunk симптома.
- `AGENT_BASE_URL` это честный runtime contract; ws URL normalization допустим только как backward-compat env fallback.
- Для следующих surfaces надо думать терминами `integration boundary` и `runtime contract`, а не терминами "написать свой transport layer".
+- Bug confirmed to be in platform-agent, NOT in surfaces bot: our sdk/real.py logs show chunk index=0 already has truncated text (e.g. ' Д Е Ё...' instead of 'А Б В Г Д...')
+- deepagents framework uses SubAgentMiddleware: main dispatcher agent + general-purpose subagent
+- service.py processes ALL on_chat_model_stream events from astream_events v2 with no node filtering
+- Two leading hypotheses: (A) chunk.content is a list for some events (multimodal), causing silent skip/error; (B) events from wrong graph node are being captured/not captured
 </decisions_made>

 <blockers>
- Подтверждённого локального Matrix blocker после `7d58dd1` больше нет; дальше это вопрос product direction и live validation, а не active transport-firefight.
- В worktree остаётся посторонний локальный diff в `core/handlers/message.py`; не смешивать его с будущими surface/runtime изменениями без отдельной задачи.
+- Need user to run docker compose up --build and share platform-agent logs with DEBUG output
 </blockers>

 <context>
-Важная ментальная модель теперь такая:
+The deepagents architecture: create_deep_agent creates a main orchestrator with SubAgentMiddleware wrapping a general-purpose subagent. When astream_events v2 runs, it may emit on_chat_model_stream from both the main agent's LLM call AND the subagent's LLM call. service.py captures ALL of them. The first chunk of the actual response might be from the subagent (not forwarded to client properly), while the main agent's response starts mid-sentence because it "sees" the subagent's output in its tool result context.

- upstream transport authoritative; `surfaces` владеет только lifecycle, serialization, attachment forwarding, error mapping и reconciliation.
- Старый narrative "ждём platform triage перед любыми transport changes" больше не актуален; transport change уже сделан и дал положительный эффект.
- Предыдущий handoff и текущий `STATE.md` были написаны до этого решения, поэтому их надо читать как исторический контекст, а не как последнюю истину.
- Проверка на false completion ничего критичного не показала: grep задел только фразу "compatibility placeholder" в `04-01-SUMMARY.md`, а не реальный незаполненный summary.
- Текущие локальные non-handoff diff: `.planning/STATE.md` и `core/handlers/message.py`.
+Two key things to look for in logs:
+1. content_type=list → fix is `chunk.content[0].get("text", "")` or similar
+2. langgraph_node varies between chunks → fix is to filter to the correct node (e.g. only "agent" node)
 </context>

 <next_action>
-Start with:
-
-1. Открыть этот обновлённый handoff, а не опираться на старый checkpoint про platform triage.
-2. Выбрать трек: Matrix live smoke или новая prod-surface phase.
-3. Если снова полезем в runtime, не возвращать custom transport wrapper и persistent shared websocket без очень сильной причины и регрессионных тестов.
+Start with: docker compose up --build. Then send a message with image context (e.g. send an image first, then ask 'Напомни алфавит'). Share platform-agent-1 logs — specifically the stream_event lines showing ns= and content_type= values.
 </next_action>
--- a/config/matrix-agents.example.yaml
+++ b/config/matrix-agents.example.yaml
@ -1,5 +1,5 @@
 agents:
  - id: agent-1
-    label: Analyst
+    label: Platform
  - id: agent-2
-    label: Research
+    label: Media
--- a/docker-compose.yml
+++ b/docker-compose.yml
@ -32,6 +32,7 @@ services:
      - platform-agent
    volumes:
      - workspace:/workspace
+      - ./config:/app/config:ro
    restart: unless-stopped

 volumes:
--- a/sdk/real.py
+++ b/sdk/real.py
@ -4,6 +4,8 @@ import asyncio
 from collections.abc import AsyncIterator
 from pathlib import Path

+import structlog
+
 from sdk.interface import (
    Attachment,
    MessageChunk,
@ -16,6 +18,8 @@ from sdk.interface import (
 from sdk.prototype_state import PrototypeStateStore
 from sdk.upstream_agent_api import AgentApi, MsgEventSendFile, MsgEventTextChunk

+logger = structlog.get_logger(__name__)
+

 class RealPlatformClient(PlatformClient):
    def __init__(
@ -157,7 +161,13 @@ class RealPlatformClient(PlatformClient):
    ) -> AsyncIterator[object]:
        attachment_paths = self._attachment_paths(attachments)
        event_stream = chat_api.send_message(text, attachments=attachment_paths or None)
+        chunk_index = 0
        async for event in event_stream:
+            if isinstance(event, MsgEventTextChunk):
+                logger.debug("agent_chunk", index=chunk_index, text=repr(event.text[:40]))
+                chunk_index += 1
+            else:
+                logger.debug("agent_event", index=chunk_index, type=type(event).__name__)
            yield event

    def _build_chat_api(self, chat_id: str):