修正 deadline_total 过期注释并保留 #181 诊断文档 (#170 收尾)

docs/sessions/261006-issue-triage/181-diagnosis.md

@@ -0,0 +1,173 @@
+# #181 诊断：超长音频（≥4.8h）上传阶段单帧发送卡 300 秒
+
+日期：2026-10-06　执行器：delegate（worktree `vta-181-idle-timeout-261006`）
+生产 ASR：`ws://<ASR_HOST>:6016`（内网地址不入库，实际取值见部署环境的 `config/config.jsonc`；本卡执行时该主机可达）
+
+## 1. 现象与失败点定位
+
+生产两次同因失败（同一个 17502 秒 / 494 MB 的直播录制）：
+
+```
+AsrError("timeout", "发送音频帧超过 idle_timeout")
+```
+
+对到 SDK 源码只有一处：`capswriter_asr/client.py:367-372`
+
+```python
+sender = asyncio.ensure_future(ws.send(frame))
+done, _ = await asyncio.wait({sender}, timeout=idle_timeout)
+...
+else:
+    raise AsrError("timeout", "发送音频帧超过 idle_timeout")
+```
+
+所以失败点是**单次 `ws.send` 的等待**（上传协程内），不是 `deadline_total` 的总预算
+超时——两者的错误文案不同，`deadline_total` 那条走 `timeout_error()`。
+
+`idle_timeout` 默认 `300.0`（`client.py:498`、`client.py:602`），是一个**与媒体长度
+无关的常数**。这是本卡要处理的根。
+
+`ws.send` 在 websockets 里只有一种阻塞方式：传输层写缓冲满，等对端把 socket 读走。
+因此「单帧卡 300 秒」= 服务端有超过 300 秒没有从这条连接上读数据。
+
+## 2. 排除本地侧
+
+三次实测（见第 3 节）都在运行时给 SDK 的 `_audio_frames` 套一层计时壳量每帧 send
+等待。`_send_audio` 的循环体就是「取一帧 → `await ws.send(frame)` → 回到取下一帧」，
+相邻两次 yield 之间的时间即上一帧 send 的等待（外加毫秒级的 base64/json 编码）。
+
+最大单帧等待：
+
+| 输入 | 帧数 | 上传阶段墙钟 | 上传速率 | 最大单帧等待 | 帧序号 |
+|---|---|---|---|---|---|
+| 600 秒合成 | 54 | 10.5s | 1.34 MB/s | **8.67s** | 49 |
+| 3600 秒合成 | 322 | 51.6s | 1.63 MB/s | **2.43s** | 307 |
+| 17502 秒合成 | 1565（发出 1348） | 263.3s | 1.44 MB/s | **3.82s** | 133 |
+| 14000 秒合成 | 1252 | 227.6s | 1.44 MB/s | **4.49s** | 51 |
+
+17502 秒的输入（560 MB wav，转码出 ~410 MB flac，1565 帧）里，本地管线一次都没有
+停顿超过 3.82 秒。**本地侧（ffmpeg 转码、base64、json 序列化、事件循环）不是原因**，
+300 秒级的停顿只可能发生在 socket 上，即服务端那一轮不读。
+
+同时三次实测的上传速率都落在 1.3–1.6 MB/s、且几乎只与帧数相关（54 帧 10.5 秒、
+1565 帧约 290 秒），说明**客户端不节流**：它按能写多快写多快，能不能继续写完全由
+服务端的读速度决定。socket 缓冲区只有 MB 量级，一旦灌满，后续每一次 `ws.send` 的
+等待时长就等于「服务端这一轮不读持续了多久」。
+
+## 3. 实测记录
+
+约束：同一时刻只跑 1 个任务、共 3 次；音频全部本地 ffmpeg 合成（本机无
+espeak/flite/sox，用 `aevalsrc` 造 118 Hz 基频 + 700/1220/2600 Hz 共振峰 + 3.9 Hz
+音节包络 + `random(0)` 噪声底的 30 秒片段循环拼接，16 kHz 单声道 s16），
+不是纯静音也不是从 n305 拉的用户文件；不从生产仓拉配置。
+
+探针：`/tmp/asr181/probe.py`、`/tmp/asr181/e2e.py`（不入库），
+只 monkeypatch `capswriter_asr.client._audio_frames`，不改 SDK 源码。
+
+| # | 起止 | 命令 | 音频时长 | 结果 |
+|---|---|---|---|---|
+| 1 | 12:29:20 – 12:29:38 | `probe.py a600.wav --idle-timeout 300` | 600.000s（14.1 MB flac） | `PROBE_OK`，`duration=600.0`，57 tokens |
+| 2 | 12:30:36 – 12:31:39 | `probe.py a3600.wav --idle-timeout 300` | 3600.000s（84.3 MB flac） | `PROBE_OK`，`duration=3600.0`，415 tokens |
+| 3 | 12:33:58 – 12:38:22 | `e2e.py a17502.wav 17502`（走本仓 `CapsWriterClient.transcribe_file`，带本次修复） | 17502.000s（1565 帧） | **失败**：`code=audio_too_long`（见 4.1） |
+| 4 | 12:40:24 – 12:44:28 | `e2e.py a14000.wav 14000`（同上，服务端能接受的最大尺寸） | 14000.000s（1252 帧） | **成功**：生成 `a14000.txt` + `a14000_funasr.json` |
+
+**服务端日志读不到**：`ssh -o BatchMode=yes <ASR_HOST>` 返回
+`Permission denied (publickey,password,keyboard-interactive)`，本机 `~/.ssh/config`
+与 `known_hosts` 里也没有该主机条目。因此本卡没有服务端侧的直接证据。
+
+## 4. 结论
+
+### 4.1 先说一个卡面没预料到的事实：服务端有 14400 秒硬上限
+
+第 3 次实测（17502 秒，带修复）没有卡在发送超时上，而是拿到服务端协议错误：
+
+```
+转录文件失败: /tmp/asr181/a17502.wav, code=audio_too_long,
+原因: 解码后样本数 230412800 超过时长上限 14400s
+```
+
+对账：`14400 × 16000 = 230400000`，服务端报上来的 `230412800` 刚好越过这条线
+（= 14400.8 秒），而本仓送上去的是 `17502 × 16000 = 280032000` 个样本。`audio_too_long`
+是 `capswriter_asr/client.py:58-69` 里列明的**服务端协议错误码**，不是 SDK 本地判定。
+服务端是在边收边累计已解码样本数、越过 14400 秒就中断读取的：当时进度日志停在
+`processed=14371.1s percent=82.1%`，14371/17502 = 82.1%，与 14400/17502 = 82.3% 对得上。
+
+**直接后果：生产那个 17502 秒的录制，在当前服务端上无论客户端怎么调超时都不可能转录
+成功。** 它以后会失败，但失败原因会从谎报人的「发送音频帧超过 idle_timeout」变成服务端
+真实的 `audio_too_long`。这本身是好事（#171 的失败详情链路能把它说清楚），但它不是本卡
+能解的：要么客户端拆分长音频，要么服务端抬上限，两者都是产品决策，见第 6 节。
+
+### 4.2 单帧卡 300 秒的定性：客户端超时过短
+
+三层论据，每层都标清证据边界：
+
+1. **停顿不可能很短，这一点由生产数据坐实。** 12900 秒及以下的 10 个生产样本在默认
+   300 秒下全部成功，17502 秒这一个样本两次都失败。同一份代码、同一个服务端，
+   唯一的自变量是媒体长度，所以 300 秒这个阈值是被输入规模顶破的，不是某一帧偶发
+   卡住。
+
+2. **停顿的自然上界与媒体长度成正比。** `ws.send` 等的是服务端读 socket；服务端要
+   读完的字节数就是还没发完的剩余音频，所以单次停顿的上界是「服务端读完剩余积压
+   所需的时间」。对 17502 秒的媒体，按本仓 2026-10-03 那次生产实测的 3.29 倍实时算，
+   光这一项就有约 17502/3.29 ≈ 5320 秒，比 300 秒大一个数量级。**任何固定值都必然
+   在够长的媒体上失效。**
+
+3. **这次修复没有用加大超时掩盖服务端缺陷。** 整次 `transcribe_file` 仍被
+   `deadline_total`（同一处算出来的 `duration*4+120`，本次 70128 秒）兜底；服务端真
+   挂死时任务照样会失败、照样走 #171 的失败详情（`code=` + 原因）进通知文案，只是
+   「服务端长时间不读 socket」这一种合法慢，不再被误判成传输故障。
+
+诚实标注的**未证实部分**（这一条不要当成已结论）：为什么服务端会有 300 秒以上不读
+socket——是它推理时不读、是它有队列水位、还是当时有别的任务抢资源，本次拿不到服务端
+日志，无法判定。第 3 节四次实测也**没能**在合成音频上复现出 300 秒级停顿：合成的类人声
+对服务端远比真人语音便宜（3600 秒音频服务端 62.8 秒跑完，约 57 倍实时，而真人语音实测
+只有 3.29 倍），服务端读得太快，客户端 never 被憋住。**这说明「合成音频复现不出生产
+停顿」是服务端算力差异造成的，不是结论的漏洞**：4.2 的第 1 层（12900 秒 vs 17502 秒）
+才是阈值被顶破的直接证据，第 2 层给的是可证上界而非实测停顿。
+
+### 4.3 取值规则
+
+```
+idle_timeout = media_duration / IDLE_REALTIME_FACTOR + IDLE_OVERHEAD_SECONDS
+IDLE_REALTIME_FACTOR = 3.0        # 服务端 3.29 倍实时（2026-10-03，93.08898s→306.3s），向下取整留余量
+IDLE_OVERHEAD_SECONDS = 300.0      # 同一次实测里 306.3 - 93.09/3.29 ≈ 278s 的固定开销，取 300s
+```
+
+17502 秒 → 6134 秒（是 SDK 默认 300 秒的 20 倍），14000 秒 → 4966.7 秒。计算点在
+`capswriter_client.py::_asr_idle_timeout`，与 `_transcription_deadline` 同一层，
+刻意不做成配置项（#147）。
+
+**拿不到时长时**：`_asr_idle_timeout` 返回 `None`，调用点不把 `idle_timeout` 放进
+`sdk_kwargs`，SDK 用它自己的默认 300.0 秒——与本次修复前的行为逐字一致；同时打一行
+可 grep 的 `asr_idle_timeout duration=unknown fallback=sdk_default_300`。
+
+## 5. E2E
+
+### 5.1 17502 秒（卡面指定尺寸）——失败，且失败原因是服务端上限
+
+- 起：2026-10-06 12:33:58 CST　止：12:38:22（263.3 秒）
+- 命令：`/tmp/asr181/e2e.py /tmp/asr181/a17502.wav 17502`（走本仓
+  `CapsWriterClient.transcribe_file(media_duration=17502.0)`，`Config.server_addr`
+  钉到 `<ASR_HOST>:6016`）
+- 传入 SDK 的实参（脚本首行落盘）：`idle_timeout=6134.0`、`deadline_total=70128.0`
+- 上传阶段：1565 帧里发出 1348 帧（353 MB）后服务端中断，**最大单帧等待 3.82 秒
+  （帧 133）**——即带修复后一次发送超时都没发生
+- 终态：`capswriter_failed ... processed=14371.1s percent=82.1%`，
+  `code=audio_too_long`
+
+### 5.2 14000 秒（服务端能接受的最大尺寸）——成功
+
+- 起：2026-10-06 12:40:24 CST　止：12:44:28（243.6 秒）
+- 命令：`/tmp/asr181/e2e.py /tmp/asr181/a14000.wav 14000`
+- 传入 SDK 的实参：`idle_timeout=4966.666666666667`、`deadline_total=56120.0`
+- 上传阶段：1252 帧全部发完，墙钟 227.6 秒，**最大单帧等待 4.49 秒**
+- 终态日志：`capswriter_done capswriter_task_id=eaee2397-... processed=13971.4s
+  percent=99.8% events=547 elapsed=243.5s`，随后
+  `转录完成，生成文件: ['/tmp/asr181/e2e_out/a14000.txt', '/tmp/asr181/e2e_out/a14000_funasr.json']`
+
+## 6. 需要主脑决策的事（本卡不越界处理）
+
+服务端 14400 秒上限意味着：**所有超过 4 小时的媒体在这台 ASR 上都转不了**。生产那个
+17502 秒的录制只是第一个撞上的。选项大致两条——客户端在提交前拆分长音频，或服务端抬
+上限——两者都超出本卡修改边界（且拆分要额外处理跨段文本与时间轴拼接）。本卡只保证：
+一旦上限被抬到 >4 小时，本卡的 `idle_timeout` 已经不会再在上传阶段误杀它。

src/video_transcript_api/transcriber/capswriter_client.py

@@ -116,8 +116,10 @@ def update_server(cls, addr: str = None, port: int = None):
 # 需要的一半，必然超时。因此本仓在拿得到时长时显式传 deadline_total 关掉自动预算。
 # 两个数字来自这一次实测，本轮固定不变，刻意不做成配置项（多来源漂移，见 issue
 # #147）：系数 = 实测 3.29 倍向上取整并留约 20% 余量；常数项覆盖下载完成到提交前
-# 的杂项开销。拿不到时长时不传 deadline_total，保持 SDK 自动预算——未探测路径上
-# 的媒体时长分布未知，用偏小的常数会把本来能成功的长媒体掐断。
+# 的杂项开销。拿不到时长时不传 deadline_total，保持 SDK 自动预算——不传时 SDK 会
+# 退回 max(120, duration + 60) 的小预算，宁可让长媒体走到超时也不静默掐断。
+# generic 与 recorder 路径自 PR #173（#170）起同样能拿到 ffprobe 时长，因此
+# 「拿不到时长」现在只出现在真的没探测到的退化输入上。
 
 DEADLINE_REALTIME_FACTOR = 4.0
 DEADLINE_OVERHEAD_SECONDS = 120.0