vvzvlad/gitmost
1
0
Fork 0
Code Issues 13 Pull Requests 5 Packages Projects Releases Activity

[bug][ai-chat][infra] AI-провайдер рвёт соединение pre-response (ECONNRESET) на /ai-chat/stream — retry (#175) восстанавливает, но бюджет из 2 попыток был исчерпан + латентно… #310

New Issue
Open
opened 2026-07-03 17:50:53 +03:00 by agent_vscode · 1 comment
agent_vscode commented 2026-07-03 17:50:53 +03:00
Collaborator
Copy Link
Copy Source

Симптом

В проде на POST /api/ai-chat/stream апстрим LLM-провайдера рвёт соединение до ответа (ECONNRESET, pre-response), после чего срабатывает pre-response retry (#175) и запрос восстанавливается. Из серверного лога (server@0.94.1, 2026-07-03T14:13, UA Safari 17.6):

14:13:13.910 WRN AiService:provider-http  provider HTTP: call#1 PRE-RESPONSE FAILED after=993ms code=ECONNRESET name=TypeError cause=read ECONNRESET reqBytes=48064 idleSincePrevCall=n/a
14:13:14.536 WRN AiService:provider-http  provider HTTP: call#2 PRE-RESPONSE FAILED after=475ms code=ECONNRESET               reqBytes=48064 idleSincePrevCall=1144ms
14:13:22.504 INF AiService:provider-http  provider HTTP: call#3 OK headersAfter=7663ms  status=200 reqBytes=48064 idleSincePrevCall=780ms
14:13:31.855 INF AiService:provider-http  provider HTTP: call#4 OK headersAfter=7919ms  status=200 reqBytes=50883 idleSincePrevCall=9095ms
14:13:45.437 INF AiChatService            AI chat stream DIAGNOSTIC (finish): elapsed=32956ms firstChunkLatency=10068ms heartbeatsSent=2 steps=2
14:14:00.287 INF AiService:provider-http  provider HTTP: call#5 OK headersAfter=14519ms status=200 reqBytes=918   idleSincePrevCall=21832ms

call#1 (attempt 0) и call#2 (attempt 1) первого шага упали с ECONNRESET, call#3 (attempt 2) прошёл. Ответ пользователю в итоге пришёл.

Что это на самом деле

Это ожидаемая телеметрия работающего механизма #175, а не краш:

  • ECONNRESET входит в RETRYABLE_CONNECT_CODES, isRetryableConnectError() → true.
  • withPreResponseRetry переигрывает pre-response сброс на свежем соединении (poisoned keep-alive socket destroys → retry лендится на новый коннект).
  • Инструментация (createInstrumentedFetch) намеренно логирует каждую попытку, включая восстановленные сбросы — поэтому WRN-строки видны именно тогда, когда фикс работает.

Код:

  • apps/server/src/integrations/ai/ai-streaming-fetch.ts — PRE_RESPONSE_CONNECT_RETRIES = 2 (стр. 43), RETRYABLE_CONNECT_CODES (стр. 46), withPreResponseRetry (стр. 178), дефолты DEFAULT_STREAM_KEEPALIVE_MS = 10_000 (стр. 36), DEFAULT_STREAM_TIMEOUT_MS = 900_000 (стр. 19).
  • apps/server/src/integrations/ai/ai-provider-http.ts — createInstrumentedFetch (телеметрия call# … PRE-RESPONSE FAILED … reqBytes/idleSincePrevCall).

Почему это всё-таки стоит issue (severity: medium)

  1. Бюджет ретраев был исчерпан под ноль. PRE_RESPONSE_CONNECT_RETRIES = 2 → всего 3 попытки; здесь упали 2 из 3, восстановились на последней разрешённой. Ещё один сброс — и весь turn падает с ошибкой у пользователя. Запаса нет.
  2. Латентность. firstChunkLatency=10068ms, headersAfter 7663–14519ms: из-за сбросов + повторов первый чанк приходит через ~10с, ответы ощутимо тормозят.
  3. Шум в логах уровня WRN на каждый сброс.

Гипотезы / направления диагностики

Телеметрия специально несёт reqBytes и idleSincePrevCall, чтобы это разбирать:

  • Poisoned keep-alive socket. keepAliveTimeout/keepAliveMaxTimeout = AI_STREAM_KEEPALIVE_MS (по умолчанию 10s). Если провайдер/мидлбокс убивает idle-сокеты раньше, чем undici их ресайклит, повторное использование протухшего сокета даёт pre-response reset. Стоит проверить корреляцию сбросов с idleSincePrevCall.
  • Большое тело запроса. reqBytes=48064 (~48KB накопленного контекста) на упавших попытках — проверить лимиты на теле/заголовках и поведение при больших POST у reverse-proxy перед docs.vvzvlad.xyz и у самого провайдера.
  • Reverse-proxy vs провайдер. Разделить, кто рвёт: прокси домена (Caddy/nginx: proxy_read_timeout, буферизация, HTTP/1.1 keep-alive к апстриму) или сам эндпоинт провайдера. call#1 упал сразу (первый коннект, idleSincePrevCall=n/a) — это скорее не idle-протухание, а cold-connect/большое тело/флап апстрима.

Что попробовать

  • Понизить AI_STREAM_KEEPALIVE_MS, чтобы undici ресайклил keep-alive сокеты заранее (до того, как их прибьёт апстрим/мидлбокс), и замерить, уходят ли сбросы.
  • Рассмотреть увеличение PRE_RESPONSE_CONNECT_RETRIES (напр. 3–4) и/или jittered backoff (сейчас линейный 150 * (attempt+1) ms), чтобы был запас на серию сбросов.
  • Проверить/выровнять таймауты и keep-alive на reverse-proxy перед доменом.
  • Если апстрим сам флапает — при возможности сменить/зафиксировать endpoint провайдера, снять корреляцию сбросов с нагрузкой/временем суток.

Acceptance / DoD

  • Понятно, кто именно рвёт соединение (прокси или провайдер), с доказательством из телеметрии (корреляция с idleSincePrevCall/reqBytes).
  • Сбросы либо устранены, либо стабильно поглощаются, не исчерпывая бюджет ретраев; firstChunkLatency в норме на «холодном» первом шаге.
  • Рекомендованные значения AI_STREAM_KEEPALIVE_MS / PRE_RESPONSE_CONNECT_RETRIES (и, при необходимости, таймауты прокси) задокументированы в .env.example.

Окружение

  • Версия: server@0.94.1 (docmost@0.94.1)
  • Эндпоинт: POST /api/ai-chat/stream, context=AiService:provider-http
  • Дата наблюдения: 2026-07-03 ~14:13 UTC
  • Клиент: Safari 17.6 / macOS

Примечание: механизм ретраев/таймаутов относится к #175 — этот issue про наблюдаемый в проде флап апстрима и запас прочности/тюнинг, а не про регресс самого механизма.

## Симптом В проде на `POST /api/ai-chat/stream` апстрим LLM-провайдера рвёт соединение **до ответа** (`ECONNRESET`, pre-response), после чего срабатывает pre-response retry (#175) и запрос восстанавливается. Из серверного лога (server@0.94.1, 2026-07-03T14:13, UA Safari 17.6): ``` 14:13:13.910 WRN AiService:provider-http provider HTTP: call#1 PRE-RESPONSE FAILED after=993ms code=ECONNRESET name=TypeError cause=read ECONNRESET reqBytes=48064 idleSincePrevCall=n/a 14:13:14.536 WRN AiService:provider-http provider HTTP: call#2 PRE-RESPONSE FAILED after=475ms code=ECONNRESET reqBytes=48064 idleSincePrevCall=1144ms 14:13:22.504 INF AiService:provider-http provider HTTP: call#3 OK headersAfter=7663ms status=200 reqBytes=48064 idleSincePrevCall=780ms 14:13:31.855 INF AiService:provider-http provider HTTP: call#4 OK headersAfter=7919ms status=200 reqBytes=50883 idleSincePrevCall=9095ms 14:13:45.437 INF AiChatService AI chat stream DIAGNOSTIC (finish): elapsed=32956ms firstChunkLatency=10068ms heartbeatsSent=2 steps=2 14:14:00.287 INF AiService:provider-http provider HTTP: call#5 OK headersAfter=14519ms status=200 reqBytes=918 idleSincePrevCall=21832ms ``` `call#1` (attempt 0) и `call#2` (attempt 1) первого шага упали с `ECONNRESET`, `call#3` (attempt 2) прошёл. Ответ пользователю в итоге пришёл. ## Что это на самом деле Это **ожидаемая телеметрия работающего механизма #175**, а не краш: - `ECONNRESET` входит в `RETRYABLE_CONNECT_CODES`, `isRetryableConnectError()` → `true`. - `withPreResponseRetry` переигрывает pre-response сброс на свежем соединении (poisoned keep-alive socket destroys → retry лендится на новый коннект). - Инструментация (`createInstrumentedFetch`) намеренно логирует **каждую** попытку, включая восстановленные сбросы — поэтому WRN-строки видны именно тогда, когда фикс работает. Код: - `apps/server/src/integrations/ai/ai-streaming-fetch.ts` — `PRE_RESPONSE_CONNECT_RETRIES = 2` (стр. 43), `RETRYABLE_CONNECT_CODES` (стр. 46), `withPreResponseRetry` (стр. 178), дефолты `DEFAULT_STREAM_KEEPALIVE_MS = 10_000` (стр. 36), `DEFAULT_STREAM_TIMEOUT_MS = 900_000` (стр. 19). - `apps/server/src/integrations/ai/ai-provider-http.ts` — `createInstrumentedFetch` (телеметрия `call# … PRE-RESPONSE FAILED … reqBytes/idleSincePrevCall`). ## Почему это всё-таки стоит issue (severity: medium) 1. **Бюджет ретраев был исчерпан под ноль.** `PRE_RESPONSE_CONNECT_RETRIES = 2` → всего 3 попытки; здесь упали 2 из 3, восстановились на **последней разрешённой**. Ещё один сброс — и весь turn падает с ошибкой у пользователя. Запаса нет. 2. **Латентность.** `firstChunkLatency=10068ms`, `headersAfter` 7663–14519ms: из-за сбросов + повторов первый чанк приходит через ~10с, ответы ощутимо тормозят. 3. **Шум в логах** уровня WRN на каждый сброс. ## Гипотезы / направления диагностики Телеметрия специально несёт `reqBytes` и `idleSincePrevCall`, чтобы это разбирать: - **Poisoned keep-alive socket.** `keepAliveTimeout`/`keepAliveMaxTimeout` = `AI_STREAM_KEEPALIVE_MS` (по умолчанию 10s). Если провайдер/мидлбокс убивает idle-сокеты раньше, чем undici их ресайклит, повторное использование протухшего сокета даёт pre-response reset. Стоит проверить корреляцию сбросов с `idleSincePrevCall`. - **Большое тело запроса.** `reqBytes=48064` (~48KB накопленного контекста) на упавших попытках — проверить лимиты на теле/заголовках и поведение при больших POST у reverse-proxy перед `docs.vvzvlad.xyz` и у самого провайдера. - **Reverse-proxy vs провайдер.** Разделить, кто рвёт: прокси домена (Caddy/nginx: `proxy_read_timeout`, буферизация, HTTP/1.1 keep-alive к апстриму) или сам эндпоинт провайдера. `call#1` упал сразу (первый коннект, `idleSincePrevCall=n/a`) — это скорее не idle-протухание, а cold-connect/большое тело/флап апстрима. ## Что попробовать - Понизить `AI_STREAM_KEEPALIVE_MS`, чтобы undici ресайклил keep-alive сокеты заранее (до того, как их прибьёт апстрим/мидлбокс), и замерить, уходят ли сбросы. - Рассмотреть увеличение `PRE_RESPONSE_CONNECT_RETRIES` (напр. 3–4) и/или jittered backoff (сейчас линейный `150 * (attempt+1)` ms), чтобы был запас на серию сбросов. - Проверить/выровнять таймауты и keep-alive на reverse-proxy перед доменом. - Если апстрим сам флапает — при возможности сменить/зафиксировать endpoint провайдера, снять корреляцию сбросов с нагрузкой/временем суток. ## Acceptance / DoD - Понятно, кто именно рвёт соединение (прокси или провайдер), с доказательством из телеметрии (корреляция с `idleSincePrevCall`/`reqBytes`). - Сбросы либо устранены, либо стабильно поглощаются, **не исчерпывая** бюджет ретраев; `firstChunkLatency` в норме на «холодном» первом шаге. - Рекомендованные значения `AI_STREAM_KEEPALIVE_MS` / `PRE_RESPONSE_CONNECT_RETRIES` (и, при необходимости, таймауты прокси) задокументированы в `.env.example`. ## Окружение - Версия: server@0.94.1 (docmost@0.94.1) - Эндпоинт: `POST /api/ai-chat/stream`, `context=AiService:provider-http` - Дата наблюдения: 2026-07-03 ~14:13 UTC - Клиент: Safari 17.6 / macOS --- Примечание: механизм ретраев/таймаутов относится к #175 — этот issue про наблюдаемый в проде флап апстрима и запас прочности/тюнинг, а не про регресс самого механизма.
agent_vscode commented 2026-07-03 17:54:40 +03:00
Author
Collaborator
Copy Link
Copy Source

Закрываю: issue заведён по ошибке не для того пункта. Нужный баг (500 на /ai-chat/bound-chat, slugId в UUID-колонку) вынесен в #312. Флап ECONNRESET — это штатная телеметрия механизма #175, отдельный issue сейчас не требовался. При необходимости легко переоткрыть.

Закрываю: issue заведён по ошибке не для того пункта. Нужный баг (500 на `/ai-chat/bound-chat`, slugId в UUID-колонку) вынесен в #312. Флап ECONNRESET — это штатная телеметрия механизма #175, отдельный issue сейчас не требовался. При необходимости легко переоткрыть.
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
epic
Large multi-phase effort spanning many changes
 needs-human
эскалация: нужно решение человека
 review/approved
в последнем ревью нет открытых blocking-находок
 review/changes-requested
последнее ревью оставило открытые blocking-находки
 review/needs
head не ревьюился (head != reviewed_head)
No Label
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
agent_coder agent_qa agent_reviewer agent_vscode vvzvlad
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: vvzvlad/gitmost#310
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?