fix(stream): 流式请求被误记为 499/client_cancelled 且 token 用量恒为 0 - #62
Conversation
流式请求的成功日志原先写在 `stream_response_body` 这个 `async_stream::stream!`
生成器最后一次 `yield` 之后,只有消费者再轮询一次才会执行到。Agent 类客户端
(Codex / Claude Code / Node undici)拿到终止帧 `[DONE]` 就立刻关闭连接,hyper
检测到对端关闭后不再轮询、直接 drop 掉 body,于是 `StreamLogFinalizer::drop`
的兜底路径接管落库,而那条路径是硬编码的:
f.write(true, false, Some("client_cancelled"), 0, 0, 0, 0, None)
结果一条完整成功、下游已经拿到全部内容的流被记成
`499 / client_cancelled / 0 token / 空响应`,配额与用量看板全部偏低。
实测差分(同一份 DB 副本、同一 key、同一模型,唯一变量是客户端何时关连接):
读满 [DONE] 即断开 → 499 / 0 tokens;读到 EOF → 200 / 113 tokens。
本机 873 条 499 里 870 条来自同一个 Agent 类 key,其余 key 走同一模型同一渠道
拿到的是 200,可见与上游无关。
改动:
1. `downstream_terminal_frame()` 按下游协议逐行精确识别终止帧
(chat `data: [DONE]` / anthropic `event: message_stop` /
responses `event: response.completed`)。逐行匹配而非子串搜索:SSE 的 JSON
载荷里换行一定是 `\n` 转义,正文伪造不出行首终止帧。
2. 在 start / push / finish 三个产出点于 `yield` **之前**检测终止帧,命中即先把
200 + 真实 usage + 响应内容落库,`finalized` 标记防止尾部重复写。
3. 流错误帧同理先落 502 再 yield —— 原来 502 也会被随后的客户端断开覆盖成 499。
4. 把原先内联在生成器尾部的落库逻辑抽成 `StreamLogSnapshot` + `write_stream_log()`。
快照必须在 await 之前同步取好:把 `&mut pump` 带过 await 会让生成器自引用,
跨 await 存活的只有 `&finalizer` / `&completed`,与改动前的收尾代码同形。
5. 真·中途取消(终止帧之前断开)仍然记 499 + client_cancelled=1,语义不变,
但通过 `StreamCancelProgress` 共享进度槽补记断开前已观测到的用量:上游 usage
优先,否则用已下发正文本地估算;一个字节都没发出去时保持全 0。
回归测试两条:
- `stream_client_close_after_terminal_frame_is_logged_as_success`
(回退本补丁后确实失败,报 `完整送达的流不能记成 499`)
- `stream_client_cancel_backfills_token_usage`
上一条提交只修了前向行为,已经落库的历史行仍是 `499 / 0 token / 空响应`。 本提交提供一个显式的一次性修复入口,把欠账补回来。 恢复依据不是启发式打分,而是内容级证据:Agent 的对话历史是累积的,若第 N 轮 真的产出了被下游采用的回复,则同会话第 N+1 轮请求的 `messages` 里必然多出第 N 轮 那条 assistant 消息。据此既能判定"本轮其实成功了",又能顺带把本轮的响应正文和 completion tokens 一起恢复出来。参照行的 messages 必须与目标行**前缀逐条相等**才 采信(否则说明换了会话或历史被压缩),判定偏保守:拿不到证据的行保持 499。 prompt tokens 分两层恢复,按可信度择优: 1. 同会话邻近真实行按 request_body 字节比插值; 2. 窗口外退到 `estimate_usage` 本地 BPE。 实测本机 873 条 499 行:98.2% 有内容证据证明其实成功交付,0 条疑似真取消。 安全边界: - 默认 dry-run,只报告不写库;`--apply` 才落库。 - dry-run 只扫一批就退出(不写库时 remaining 不会收敛,避免死循环)。 - 只处理 `usage_source IS NULL` 的行,天然幂等且可中断续跑:任何时刻 Ctrl+C 都安全,已处理的行不会被重扫,未处理的仍是候选。 - **不动 `api_keys.quota_used`**:配额语义是否同步是独立决策,留给使用者。 - 回填出的数字一律标 `usage_source='repaired'`,与上游实测值可区分,避免历史 估算永久冒充实测数据。 状态改判与用量回填拆成两个独立开关(`--status-only` / `--usage-only`):前者只做 消息前缀比对,秒级完成;后者要对 request_body 跑 BPE,GB 级库上分钟级。两者成本 与精度来源完全不同,必须能分开选。(注意两个 scope 不能先后各跑一次:候选条件是 `usage_source IS NULL`,先跑 reclassify 会打上标记,第二次就扫不到了。要么一次跑完, 要么只跑其中一种。) 载体选择:刻意不做成 migration。migration 会在每个用户启动时自动跑、静默改写他们 的历史数据,而且 SQL 里跑不了 tiktoken。做成两个显式入口: - `waliapi-web repair-stream-logs [--data-dir <目录>] [--apply] [--limit <行>] [--status-only|--usage-only]`,离线执行、不需要管理员会话,桌面端与 Docker 通用; - Tauri command `repair_stream_cancel_logs` + `/admin/api/invoke` 同名 cmd。 ⚠ 帮助文本里明确要求先停实例再跑:WaLiAPI 的 SQLite 以默认 journal_mode=delete (回滚日志)打开,写事务提交需要 EXCLUSIVE 锁,本命令会连续发起数百个写事务, 与仍在服务的网关(每请求至少一次读 + 一次写)争锁,两侧都会遇到 SQLITE_BUSY 停顿。 实测吞吐约 1.5 秒/行(BPE 跑在 ~1MB 的 agent 请求体上),873 行约 23 分钟。 已知局限(已写进代码注释,避免后人误信):插值层在本机实际只命中 0.8%(7/873), 因为 499 行连续成串(回溯链中位 44 行),后继本身通常也是 prompt_tokens=0 的 499 行, 没有可锚的真实值;99.2% 落到 BPE,这正是 23 分钟的来源。改用前驱为锚点可把命中 提到 91.9%(434 对真实相邻样本留一验证:中位误差 0.01%、P90 0.41%),但链式插值会 telescoping 成远锚点直算,严格窗口下覆盖率只回升到 17.3% —— 精度受益、耗时不受益。 真正能同时改善两者的是增量法(只对每轮新增的几 KB 跑 BPE 再累加),属后续优化。 新增 migration 028 给 `request_logs` 加可空列 `usage_source`,纯增量、不改既有列。 `estimate_usage::count_tokens` 提升为 `pub(crate)` 供恢复出的回复文本计数复用。 测试:12 个单测/集成测试,含内存库 + 真实迁移跑通"扫描 → 证据判定 → 落库 → 幂等" 全链路、dry-run 不得改动任何行的断言,以及两个 scope 开关各自只改自己那部分的断言。
|
历史用量恢复(操作步骤): A. 其他 Windows 桌面用户(合并发版后的标准路径) :: 1) 停应用(避免与网关争 SQLite 写锁) :: 2) 先看报告,不写库 :: 3) 确认数字合理后执行 :: 4) 重启 waliapi-web repair-stream-logs --status-only --apply B. Linux / Docker / systemd 用户 systemctl stop waliapi # 或 docker compose stop C. 完全不能停机的用户 两条可选,都不需要任何额外脚本: 进程内入口:POST /admin/api/invoke,body {"cmd":"repair_stream_cancel_logs","args":{"input":{"apply":true,"limit":50}}},带管理员会话。它跑在应用进程内,不存在跨进程锁竞争;分批调用直到返回 remaining: 0。 D. 关于"不停机直接跑"的风险,准确说法 |
版本最高最全分支为 upstream/v0.2.9(main 之上另有 PR fuzhengwei#62/63/64/66/67/68)。 冲突融合决策: - core/proxy.rs 响应侧扫描:保留 FIX-16 的 scan_response_into 收敛实现, 新增 custom_rules 参数贯通上游 PR fuzhengwei#64;security/mod.rs 同步扩签名, driver.rs / handlers.rs 各调用点传 &[](这些路径 AuditedRequest 不携带规则快照,与上游一致) - endpoint_executor/driver.rs:保留 issue fuzhengwei#57 的 snapshot 链路(含本地估算 兜底 + FIX-26 runtime 守卫),移除上游 PR fuzhengwei#62 等价的 progress/publish_progress 链路;update_stream_snapshot 改为首个非空内容立即快照(修复短流取消时 completion 漏算,上游新测试 stream_client_cancel_backfills_token_usage 覆盖), 长流仍按 ≥16KB 分段防 O(n²) - server/handlers.rs:保留 FIX-12 的 finish(&mut self)(解析器 Mutex 内共享) 验证:cargo test --lib --tests 全量 797 通过,仅余 2 个已知基线失败 (codex_login Windows rename 语义、security_gate_block_zero_upstream), 与合并前基线一致。
问题
桌面端审计日志里大量
499+client_cancelled,响应内容为空、token 用量为 0,但流式输出对下游 Agent 完全正常 —— 思维链和正文都能拿到。
本机实测:873 条 499 里 870 条来自同一个 Agent 类 API key;同一模型、同一渠道在
另外两个 key 下拿到的是 200。可见与上游供应商无关,也与下游无关。
根因
stream_response_body的成功日志写在async_stream::stream!生成器最后一次yield之后,只有消费者再轮询一次才会执行到。Agent 类客户端(Codex / Claude Code /Node undici 等)拿到终止帧
[DONE]就立刻关闭连接,hyper 检测到对端关闭后不再轮询、直接 drop 掉 body,于是
StreamLogFinalizer::drop的兜底路径接管落库,而那条路径是硬编码的:
三个症状(499 / token=0 / 响应空)全部由此解释。全仓库
499只有这一处写入点。差分实测(同一份 DB 副本、同一 key、同一模型,唯一变量 = 客户端何时关连接):
[DONE]立刻 close提交一:前向修复(
endpoint_executor/driver.rs)downstream_terminal_frame()按下游协议逐行精确识别终止帧(chat
data: [DONE]/ anthropicevent: message_stop/ responsesevent: response.completed)。逐行匹配而非子串搜索:SSE 的 JSON 载荷里换行一定是\n转义,正文伪造不出行首终止帧。start/push/finish三个产出点于yield之前检测终止帧,命中即先把200 + 真实 usage + 响应内容落库,
finalized标记防止尾部重复写。yield—— 原来 502 也会被随后的客户端断开覆盖成 499。StreamLogSnapshot+write_stream_log()。快照必须在await之前同步取好:把
&mut pump带过await会让async_stream生成器自引用;跨 await存活的只有
&finalizer/&completed,与改动前的收尾代码同形。499 + client_cancelled=1(语义不变),但通过StreamCancelProgress共享进度槽补记断开前已观测到的用量:上游 usage 优先,否则用已下发正文本地估算;
一个字节都没 yield 过则保持全 0(那次请求上游可能尚未开始生成)。
回归测试两条:
stream_client_close_after_terminal_frame_is_logged_as_success—— 回退本补丁后确实失败,报
完整送达的流不能记成 499(error=Some("client_cancelled"))stream_client_cancel_backfills_token_usage提交二:历史数据修复命令
前一条只修未来,已落库的行需要单独恢复。
判定不用启发式打分,用内容级证据:Agent 的对话历史是累积的,若第 N 轮真的产出了
被下游采用的回复,同会话第 N+1 轮请求的
messages里必然多出第 N 轮那条 assistant消息。据此既能证明"本轮其实成功了",又能顺带把本轮的响应正文和 completion tokens
一起恢复出来。参照行的
messages必须与目标行前缀逐条相等才采信(否则说明换了会话或客户端压缩过历史),判定偏保守:拿不到证据的行保持 499。
prompt tokens 分两层恢复:邻近真实行按
request_body字节比插值,窗口外退到estimate_usage本地 BPE。入口与可达性
以及 Tauri command
repair_stream_cancel_logs(/admin/api/invoke同名 cmd)。两点已核实,说明桌面用户真的能自助使用:
waliapi-web.exe随 Windows 安装包发布(Tauri 生成的wix/x64/main.wxs与nsis/x64/installer.nsi均包含该二进制),无需额外下载;--data-dir时命中桌面端同一个库:resolve_data_dir的 Windows 分支返回%APPDATA%\<APP_IDENTIFIER>,与app.path().app_data_dir()一致。刻意不做成 migration:migration 会在每个用户启动时自动跑、静默改写他们的历史数据,
而且 SQL 里跑不了 tiktoken。
状态改判与用量回填是两个独立开关
两者成本与精度来源完全不同:
--status-only--usage-only开关是真正跳过计算、不是只跳过写入(
plan_repair收到with_usage=false时完全不调用 tokenizer)。两个开关同时关闭会显式报错。
安全边界
--apply才写入。dry-run 只扫一批即退出(不写库时
remaining不会收敛,否则会死循环)。usage_source IS NULL的行 → 天然幂等,且任何时刻 Ctrl+C 都安全:已处理的行带标记不会被重扫,未处理的仍是候选,重跑即续。
api_keys.quota_used:配额语义是否同步是独立决策,留给使用者。usage_source='repaired',与上游实测值可区分,避免历史估算永久冒充实测数据。
journal_mode=delete(回滚日志)打开,写事务提交需要 EXCLUSIVE 锁,而网关每请求至少一次读 + 一次写。风险性质是可恢复而非危险
—— 最坏情况是个别日志行写入失败或回填中途退出,重跑即续,不会损坏库。
已知局限(已写进代码注释,避免后人误信)
插值层在本机实际只命中 0.8%(7/873):499 行往往连续成串(回溯链中位 44 行、
P90 123 行),后继本身通常也是
prompt_tokens=0的 499 行,没有可锚的真实值。剩下 99.2% 落到 BPE —— 这正是 23 分钟的来源。
改用前驱行为锚点可把命中提到 91.9%,且精度更高(434 对"两行都有上游真实
prompt_tokens"的相邻样本留一验证:中位误差 0.01%、P90 0.41%、94.5% 误差 ≤1%)。
但链式插值会 telescoping 成
prompt(锚点) × chars(N)/chars(锚点),等价于直接用远锚点,严格窗口下覆盖率只回升到 17.3% —— 精度受益、耗时不受益。真正能同时改善
两者的是增量法(只对每轮新增的几 KB 跑 BPE 再累加),属后续优化,本 PR 未做。
验证
单元/集成测试
cargo test --no-fail-fast:765 passed / 2 failed(
security_gate_block_zero_upstream、codex_login::export_is_nested_private_...—— 已确认
git diff main v0.2.8 -- src/security/ src/auth_provider/为空,这两个测试的代码与 main 逐字一致,属 v0.2.8 继承失败,与本 PR 无关)
(含内存库 + 真实迁移跑通"扫描 → 证据判定 → 落库 → 幂等"全链路、dry-run 不得改动
任何行的断言、两个 scope 各自只改自己那部分的断言、双关开关显式报错)
cargo fmt --check:仓库基线 114 处 pre-existing 差异,本分支仍是 114 处,净增 0cargo clippy --all-targets:log_repair.rs/waliapi-web.rs零命中,lib 告警数 211 与基线持平
真实生产库端到端(1.73 GB、873 条历史 499)
--apply全量:15 批 / 873 行 /remaining=0,改判 857 条为 200、16 条无证据保持 499、0 条疑似真取消,补记 prompt 147,027,054 + completion 587,507 tokens,
857 行恢复
response_choices499计数 873 → 16,quota_used三个 key 全部未被改动200+ 真实 token +client_cancelled=0在 873 行 × 8 个字段上逐字节一致(差异 0),说明命令输出稳定可复现
已知取舍
[DONE]到客户端会晚这么多。取舍是"宁可少报一条取消,也不把成功流误报成失败"。
v0.2.8(3aff3e1),与上游对stream_response_body的重写(
UpstreamItem/next_upstream_item/idle_timeout)合并,v0.2.8 新增的buffer_first_record诊断与 idle timeout 测试全部保留。tests/request_log.rs的reasoning_effort字段 v0.2.8 已自行修好,本 PR 不再涉及。本 PR 有意未做(可作后续)
src/与web/src/里对repair_stream_cancel_logs的引用为 0 处。命令行已覆盖绝大多数场景;若希望完全不停机的用户能自助,值得在日志页
加一个按钮调用进程内 command(约 40 行前端,复用现有后端)。
estimate_usage只统计delta.content,不含reasoning_content;非流式路径的extract_response_text()同样不取 Anthropic 的thinking块。但上游真实回传的completion_tokens本身是包含 reasoning tokens 的(OpenAI 把completion_tokens_details.reasoning_tokens作为其子集,Anthropic 的 thinking 也计入
output_tokens)—— 这是估算路径与实测路径口径不一致、估算路径少算,属 bug而非口径变更。未一并修是因为它会同时改变既有 200 行的数字,需要维护者定夺。
[INFO] stream token usage estimated用的是eprintln!,桌面端无控制台,这行日志在桌面版里根本看不到(本机日志目录搜索 0 命中),是可观测性缺口。
usage_source(目前只有回填命令会写repaired)。列已预留upstream/estimated/interpolated语义,补上需要把来源信息透到落库处。版本号 / CHANGELOG
未改
package.json/Cargo.toml/tauri.conf.json/Cargo.lock版本号,也未改CHANGELOG.md,按仓库惯例留给维护者在发版时统一处理。