bili drops an OpenAI-compatible stream's usage when it arrives on a non-empty choices frame with an empty delta #4488

TL;DR — On a relay that does return usage on every single request, billion-context 0.1.205/0.1.206 still recorded no usage for 4 hours, so nudge never saw growth and never folded. The reason is not the relay, and not only the statusInputBaseline fallback tracked in #4383: the OpenAI SSE parser only harvests usage from two frame shapes (no choices at all, or a frame carrying finish_reason). A usage-only frame that still carries choices:[{delta:{}}] with no finish_reason falls through both branches and the usage is silently discarded. I verified this against the upstream with curl and with a one-line patch to dist/index.js that fixed the frozen session.

Related: #4383 (the reported freeze), #4413 / #4443 (read-side fixes for it), #593 (an earlier, different frame shape with the same symptom).

Environment

• billion-context 0.1.204 → 0.1.205 → 0.1.206 (all three exhibit the bug; 0.1.206's parser is byte-identical to 0.1.205's in this area)
• Windows Server 2022, Git Bash
• Client: ZCode via an OpenAI-compatible endpoint served by bili on 127.0.0.1:8787
• Upstream: a local relay (wild-work gateway) on 127.0.0.1:7863, which fronts several channels
• Model that froze: raccoon/sn-deepseek-v4-1-flash-1017, declared context_length: 1000000, max_output_tokens: 100000; bili resolves an effective window of 750000 after output headroom
• Model that recovered it: workbuddy/deepseek-v4.1-flash, same declared window

Symptom

Session a5ea1121-b895-4ee3-bfdc-e0a967642270 sat frozen for 4h07m (00:31:59Z → 04:39:20Z). During that window every nudge verdict was idle with growth=0, while pendingT1 climbed to 284030 tokens:

02:xx nudge idle: usage=1% (4733/750000), growth=0/22500 (ref=4733, interval=50000), pendingT1=170128/50000 model=raccoon/sn-deepseek-v4-1-flash-1017
...
04:37 nudge idle: usage=1% (4733/750000), growth=0/22500 (ref=4733, interval=50000), pendingT1=284030/50000 model=raccoon/sn-deepseek-v4-1-flash-1017

The same requests were carrying ~300k tokens of input — bili's own budget line proves it knows:

04:37:31 output budget clamped 384000 -> 100000 (input~303092.92940082756, window=1000000); prevents input+output overflow (#453)

So one code path measures 303093 tokens and another reports 4733, with no new usage sample arriving to correct it. Switching the model (no restart, no config change) fixed it instantly:

04:39:21 [acp-usage] round 1 input=252154 cached=22400 (cache hit 9%)
04:39:25 nudge INJECT T1: ... growth=247421/22500 (ref=4733, interval=50000), pendingT1=285786/50000
04:39:49 [acp-compress-obs] shrink 84% (~245156/293216 tok) foldPoints=m00391 blocks=5 ... postCtx≈48060

This is the freeze already filed as #4383.

What #4383 does not capture: the upstream is reporting usage

The premise in #4383's triage — and in maintainer comment 2 and 4 — is that this relay "从不回传 usage" (never returns usage), so the anchor can only go stale. That is not what happens here. I queried the relay directly and it returns usage on every request, streaming or not:

Non-streaming (POST http://127.0.0.1:7863/v1/chat/completions, model: raccoon/sn-deepseek-v4-1-flash-1017):

"usage": {"completion_tokens": 12, "prompt_tokens": 33, "total_tokens": 45}

Streaming, tail of the SSE body — this is the shape that matters:

data: {"choices":[{"delta":{},"finish_reason":"stop","index":0}],...,"model":"raccoon/sn-deepseek-v4-1-flash-1017",...}

data: {"choices":[{"delta":{},"index":0}],...,"model":"raccoon/sn-deepseek-v4-1-flash-1017","usage":{"completion_tokens":11,"prompt_tokens":33,"total_tokens":44}}

data: [DONE]

The usage rides on a separate trailing frame that keeps choices non-empty ([{"delta":{},"index":0}]) and carries no finish_reason.

For contrast, workbuddy/deepseek-v4.1-flash on the same relay puts usage on the frame that does carry finish_reason:

data: {"choices":[{"delta":{"role":"assistant"},"finish_reason":"stop","index":0}],...,"usage":{"cache_read_input_tokens":0,...,"prompt_tokens":7,...}}

Same relay, same request shape, two different placements. One is readable by bili, the other is not.

The parser

In the shipped 0.1.205 bundle (dist/index.js, line 6102, OpenAI SSE parseStream), usage is harvested in exactly two places:

1. When the frame has no choices at all — this is the choices: [] shape fixed by fix #589: forward trailing usage-only frame on raw tool-call rounds #593:

const choices=parsed.choices;
const choice=choices?.[0];
if(!choice){
  if(parsed.usage){
    const u2=parsed.usage;
    yield{kind:"usage",inputTokens:...,outputTokens:...,cachedTokens:openaiCachedTokens(u2)};
    if(sawRealToolCall){yield{kind:"meta",chunk:rawBuf}}
  }
  continue
}

2. When the frame carries finish_reason:

const delta=choice.delta;
const finishReason=typeof choice.finish_reason==="string"?choice.finish_reason:void 0;
...
if(finishReason){
  ...
  const u2=parsed.usage;
  yield{kind:"usage",inputTokens:typeof u2?.prompt_tokens==="number"?u2.prompt_tokens:void 0,...}

A frame with choices:[{"delta":{},"index":0}] plus usage satisfies neither: choice exists (so branch 1 is skipped) and finish_reason is undefined (so branch 2 is skipped). delta is {}, truthy, so execution walks all the way to the bottom and the usage field is never read. No warning, no diagnostic — the same silence that made #4383 hard to attribute.

#593 fixed the choices: [] variant of this in 0.1.x. This is the non-empty-choices variant, and it is still open in 0.1.206.

Empirical confirmation from the same session

The freeze and the recovery happened without a restart, so the parser and the session state were constant across both. What changed was which channel produced the tail frame.

• Frozen window (00:31:59Z → 04:39:20Z, 153 main requests on raccoon): exactly one [acp-usage] line in the entire window. Not one per request.
• After the model switch to workbuddy: [acp-usage] appears on essentially every request (224 lines total, 220 of them after 04:39:20).
• Later, back on raccoon in a fresh session: [acp-usage] stopped again — 06:00Z → 06:19Z had zero [acp-usage] lines despite successful turns, and tokenCount froze at 182983 while nudge kept reading that stale value.

So the relay reports usage on every request, and bili records it only when the channel happens to use the finish_reason placement. That is a parser defect, not a relay defect.

Fix (minimal, verified locally)

Read usage from any frame that carries it, not only the two legacy shapes. A conservative placement that cannot disturb the other channels: only fire when the frame has usage, no finish_reason, and an empty delta object (i.e. the frame carries no content of its own):

if(parsed.usage&&typeof choice.finish_reason!=="string"&&choice.delta&&typeof choice.delta==="object"&&Object.keys(choice.delta).length===0){
  const biliUsageFix=parsed.usage;
  yield{kind:"usage",
    inputTokens:typeof biliUsageFix.prompt_tokens==="number"?biliUsageFix.prompt_tokens:void 0,
    outputTokens:typeof biliUsageFix.completion_tokens==="number"?biliUsageFix.completion_tokens:void 0,
    cachedTokens:openaiCachedTokens(biliUsageFix)}
}

inserted immediately before const delta=choice.delta;const finishReason=... in dist/index.js (line 6102 in the 0.1.205 bundle). Frames that carry content, and frames that carry finish_reason (the workbuddy shape), never enter the branch, so existing behavior is untouched.

Verification after patch + restart, same session, same raccoon model, no other change:

06:21:34 [acp-usage] round 1 input=91392 cached=90624 (cache hit 99%)
06:22:28 nudge idle: usage=12% (92313/750000), growth=3325/22500 (ref=88988, interval=50000), pendingT1=40875/50000
06:22:43 [acp-usage] round 1 input=94748 cached=92288 (cache hit 97%)
06:23:17 [acp-usage] round 1 input=96483 cached=94720 (cache hit 98%)

Usage now lands on every request, growth accumulates normally, and the nudge gate returns to its designed behavior (idle because max compressible 45239 < threshold 50000, which is the intended reason — not the growth 0 < floor 22500 deadlock).

Why this should be fixed in addition to #4413 / #4443

The read-side fallback in #4413/#4443 degrades a stale anchor to the calibrated local estimate. That is the right safety net, and it would have broken this freeze. But with the parser defect left in place:

• every request from this relay still loses its real usage, so nudge, pressure band, preflight, panel figures and cache accounting all ride an estimate permanently, instead of the number the upstream actually billed;
• the estimate is explicitly less trustworthy: in [Bug] statusInputBaseline falls back to lastUsageGradeTokens instead of the calibrated local estimate — so one 4.7k side-request sample blocks folding for 4 hours | #1595 承诺的"改用本地估算"兜底在 statusInputBaseline 里没有实现，一次 4.7k 侧请求样本即可挡住折叠 4 小时 #4383's own measurements the calibrated estimate ran ~0.7355 of true usage, and localInputEstimate exceeded usage by 4.2×;
• it makes the failure look like "this relay never reports usage", which sends the fix to the wrong layer and leaves every other client of the same relay permanently mis-metered.

Two independent defects, one symptom. The parser one is cheaper to fix and has no blast radius.

Reproduction

1. Point bili at a relay whose streaming tail frame is {"choices":[{"delta":{},"index":0}],...,"usage":{...}} (no finish_reason on that frame). OpenAI's own stream_options.include_usage produces exactly this shape, so it is not exotic — it is the reference implementation.
2. Send a small request first (title generation, /models probe) so a small usage sample becomes the anchor.
3. Chat past ~200k tokens.
4. Observe [acp-usage] missing for most/all turns, nudge printing usage=<small>/<window>, growth=0, while the same log's output budget clamped ... (input~<large>) shows the real size and pendingT1 grows without bound.
5. Switch to a channel that puts usage on the finish_reason frame; the freeze clears on the first response.

No special configuration needed, compress left at defaults.

Suggested fix location

parseStream in the OpenAI-compatible SSE lane. Either harvest parsed.usage from every frame after the two existing branches (guarding against duplicate applyUsageSample calls), or add the empty-delta trailing-frame branch as above. A one-line #593-style regression test with a choices:[{delta:{}}] usage frame would cover it.

中文摘要

上游 relay 每次请求都回传了 usage，但 bili 的 OpenAI SSE 解析器只在两种帧里读取它：choices 为空数组的帧，以及带 finish_reason 的帧。而该渠道把 usage 放在一个独立尾帧里——choices 非空（[{"delta":{},"index":0}]）、delta 为空对象、没有 finish_reason。这种帧两个分支都进不去，usage 被静默丢弃，#593 当年只修了 choices: [] 那一种。

后果：acp-usage 长时间不出现，settleUsageReport 不再更新，tokenCount 停在旧的 4733，growth 恒为 0，nudge 永不触发，上下文一路涨到 30 万、110 万后才被 502 撞停。换到 usage 贴在 finish_reason 帧上的渠道立刻恢复（input=252154 → 当轮 INJECT → 折叠 84%）。

这与 #4383 是两个独立缺陷：#4383 是"读侧把陈旧样本当成当前值"，本条是"真实样本根本没被读出来"。#4413/#4443 的读侧兜底能救症状，但治不了这个——修好之后每次请求的真实 usage 依然丢失，所有计量永久骑在精度差得多的本地估算上。

已在 0.1.205 的 dist/index.js 第 6102 行打补丁验证：补丁后同一会话、同一 raccoon 模型，每个请求都有 [acp-usage]，growth 正常累积。