Skip to content

[Bug]: prePruneTokens is a stale prev-usage estimate, so an inflated upstream usage report (measured 1.76–2.05×) triggers growth nudges with candidateCount=0 #476

Open

Description

@nsdbjh

opencode-acp 1.18.3, OpenCode dev build 999.0.0, third-party OpenAI-compatible gateway (@ai-sdk/openai-compatible), Linux. Config: compress.maxContextLimit=40%, minContextLimit=35%.

Problem

Two independent defects compound into a compress thrash loop (single steps stuck for 15+ minutes):

  1. prePruneTokens is a stale prev-usage estimate, not a count of the outgoing payload.
    Pairing every Chat transform complete line with the actual request usage (tokens.input + tokens.cache.read + tokens.output) gives a 3-way match over 269 pairs:

    best == self      :  12   (the request this transform describes)
    best == self+out  :  19
    best == prev+out  : 238   (previous request's prompt + previous output)   <== dominant
    

    238/269 match "prev prompt + prev output" within 0.0–0.6%. So the logged number is an
    incremental estimate carried over from the previous request's reported usage — new tool
    results are not counted, and whatever the upstream reported last is inherited verbatim.

  2. trigger=growth nudges ignore candidate availability. Same day: 49 nudges injected,
    49 with candidateCount=0 microCandidates=0 estimatedCandidateTokens=0. Other paths do
    suppress (Nudge suppressed: nothing to compress), the growth path does not.

Consequence chain observed in one session:

upstream usage report inflated 1.764×          108,499 → reported 191,403
  → next transform inherits it                 prePruneTokens 108,527 → 191,761 (usagePct 42% → 74%)
  → growthSinceBaseline +83,234 (fake)         nudge injected (candidateCount=0)
  → model guesses a compress range             picks an already-consumed ID
  → compress tool error                        "endId m00264 is not available — likely consumed
                                                by an existing block. ... retry with valid IDs."
  → model re-guesses, loop                     single step 15m02s

Evidence: the upstream report is inflated, not just misread

Fresh-session first requests have an identical payload (system prompt + tool schemas + a fixed
78-char user message), so their reported usage must match across requests. Same model
(gpt-6.1-sol), last 3 days:

route n min median max
gpt-6.1-sol (other gateways) 33 19,843 24,223 25,439
offending pay-per-use route 8 24,874 43,813 45,565

The offending route's 8 samples, all identical payload, all cacheR=0:

24,874 / 24,961 / 27,375            ← normal, consistent with the 33-sample baseline
43,813 / 43,813 / 43,834 / 44,113 / 45,565   ← 1.76–1.83×

Session-wide scan of "reported / (prev prompt + prev output)":

normal steps (0.85–1.2×): 244
inflated  (1.5–2.2×)    :   3     factors 2.054 / 1.764 / 1.929, median 1.929
excess tokens           : 217,866

108,499 × 1.764 ≈ 191,403 — the +82,876 "growth" that fired the nudge is exactly the
inflation of that single report. The estimator itself is accurate (0.6% agreement on the 238
clean pairs); it just has no defense against a lying report.

Reproduction

# transforms: [(ts, prePruneTokens)] from ACP log "Chat transform complete"
# P: [(ts, prompt, output)] prompt = message.tokens.input + tokens.cache.read
counts = {"self": 0, "self+out": 0, "prev+out": 0}
for ts, pre in transforms:
    idx = last assistant message with ts <= transform.ts + 1s
    c = {"self": P[idx].prompt,
         "self+out": P[idx].prompt + P[idx].output,
         "prev+out": P[idx-1].prompt + P[idx-1].output}
    if c["self"] == 0 and c["prev+out"] == 0: continue   # aborted requests
    counts[min(c, key=lambda k: abs(c[k] - pre) / max(pre, 1))] += 1
# observed: {"self": 12, "self+out": 19, "prev+out": 238}   (269 pairs)

Expected / suggested acceptance

  • Recount prePruneTokens from the message list actually being sent, instead of incrementally
    deriving it from the previous request's reported usage.
  • Reject or re-estimate when the reported usage jumps >1.5× without a corresponding payload
    change (relay-side usage inflation must not reach the growth heuristic).
  • Suppress growth nudges when candidateCount == 0, matching the existing
    Nudge suppressed: nothing to compress paths.
  • On compress validation failure, return the still-compressible ranges in the error instead of
    endId ... not available, call acp_status(), retry — the current message invites the model to
    keep guessing consumed IDs.

Related

Not claiming the inflated usage report is an ACP defect — it is gateway-side. But ACP currently
propagates it into usagePct / growthSinceBaseline with no sanity bound, which is what turned
one bad report into a 15-minute compress thrash loop.

ACP_debug_logs.md

Activity

  1. ranxianglei commented on Oct 6, 2026

    @ranxianglei
    Owner

    🤖 Powered by ework · qwen3.8-27b

    [bot] 🏷 Acknowledged — triaging now. Initial code-level confirmation of defect 1: getCurrentTokenUsage() (lib/token-utils.ts:9) returns the last assistant message's input + cacheRead + cacheWrite + output + reasoning — i.e. the previous request's reported prompt + its output, inherited verbatim. That is exactly your 238/269 "prev+out" match, and it flows unbounded into usagePct, overMaxLimit, and growthSinceBaseline via isContextOverLimits() (lib/messages/inject/utils.ts:196) — no sanity check against the actual outgoing payload. A 1.76× inflated relay report therefore propagates 1:1 into the growth heuristic.

    Defect 2 confirmed structurally: in range mode (candidates off — the default), the nothingToCompress guard (lib/messages/inject/inject.ts:481-484) has a vacuous hole — when buildCompressibleRanges yields zero ranges (fresh/small visible context, everything else already compressed), none of allProtected / allInProtectedZone / allBelowMin is true, so the guard stays false and a growth nudge fires with no actionable ranges — the model then has to guess IDs, which is your consume-error thrash loop. (The candidateCount=0 in those log lines is also expected in range mode — that field only tracks opt-in candidate planning.)

    Not a duplicate of #346 (limit-unknown in spawn+resume) or #436 (round-trip cost) — distinct mechanism, though #346's post == pre symptom shares the same stale-number root. Working on a fix covering all four acceptance items; will follow up with PR link.

  2. ranxianglei commented on Oct 6, 2026

    @ranxianglei
    Owner

    🤖 Powered by ework · qwen3.8-27b

    [bot] 🏷 Triage complete — both defects confirmed in code, not duplicates of #346/#436. Working on a fix now; PR to follow in this thread.

    What I verified (against current master)

    Defect 1 — stale usage channel (confirmed). prePruneTokens is computed by getCurrentTokenUsage() (lib/token-utils.ts:9), which returns the last assistant message's reported input + cacheRead + cacheWrite + output + reasoning — i.e. exactly "previous request's reported prompt + its output", never counting the message list. Your 238/269 post == prev_prompt + prev_output match is therefore expected behavior, not coincidence. The same value feeds:

    • isContextOverLimits() → currentTokens → overMin/overMax, growth decision, anchor logic (lib/messages/inject/utils.ts:196)
    • the hard-guard budget check and all transform logging (lib/hooks.ts:360,417)

    So one inflated relay report poisons every downstream decision for that turn.

    Defect 2 — vacuous suppression hole (confirmed). In default range mode, nothingToCompress = allProtected || allInProtectedZone || allBelowMin (lib/messages/inject/inject.ts:481). Each disjunct requires some analyzed range to exist:

    • allProtected: compressible=0 and protected>0
    • allInProtectedZone: protectedRefs>0 and unprotectedCompressible=0
    • allBelowMin: compressible>0 and recommended=0

    When buildCompressibleRanges() yields zero ranges and zero protected (visible context is entirely compressed blocks + recent zone), all three are false → nothingToCompress=false → growth nudge fires with no actionable ranges → model guesses IDs → endId ... not available retry loop. This matches your 49× candidateCount=0 injections (candidateCount itself only tracks opt-in candidates, so 0 there is normal — the real signal was zero compressible ranges).

    The trigger chain you measured lines up with computeShouldNudge (growth-only cadence: growthSinceLastNudge >= nudgeGrowthTokens || overMaxLimit) — an inflated currentTokens jump of +83K trivially clears any growth floor.

    Layer judgment (root cause vs symptom)

    • Root cause A: the nudge/growth machinery trusts upstream-reported usage without any cross-check against the actual outgoing payload. Your AC Add CI workflow for testing and building #2 (reject/re-estimate on >1.5× unexplained jump) targets exactly this.
    • Root cause B: the suppression predicate has a logical hole for the empty-analysis case. Your AC docs: Test suite development summary (346→350 tests, 5-tier coverage) #3 targets exactly this.
    • AC feat: expand message ref format from 4-digit to 5-digit (9999→99999) #1: I'll implement it as part of the same mechanism — the re-estimation path recounts from the actual message list (fast chars/4 estimate + cached system-prompt tokens), used whenever the reported value fails the sanity gate. I am deliberately not switching the steady-state channel to estimates-only: chars/4 systematically undercounts CJK-heavy content vs provider counts, which would shift every calibrated threshold (maxContextLimit, growth floors) for all sessions on honest providers — a larger regression than the bug being fixed. Honest reports stay authoritative; anomalous ones get replaced by the recount.
    • AC docs: add devlog system for development iteration tracking #4: confirmed partially present — the error already appends a recovery hint (lib/compress/search.ts:259 buildBoundaryRecoveryHint) with the visible ref span + block count, but no list of actually-free sub-ranges. I'll extend it to enumerate contiguous free spans so a retry doesn't need acp_status().

    Plan

    1. New usage-sanity resolver: per-turn pair {reported, payloadEstimate} stored on session state (persisted); if reported jumps >1.5× while the fresh payload estimate grows <1.5× (with a small-context floor to avoid noise), downstream decisions use the re-estimate instead. Applied at the two choke points: isContextOverLimits().currentTokens and hooks' pre/post tokens.
    2. Close the nothingToCompress hole: zero-ranges-and-zero-protected ⇒ suppress, with a distinct audit reason (no_compressible_ranges), consistent with existing suppression paths.
    3. Extend the boundary-error hint with the free-range listing.
    4. Tests per §5.7 (multi-turn, side-effect assertions, production config preserveRecentMessages > 0, and each new test verified to fail against the unfixed code), devlog entry, PR referencing this issue.

    Behavior changes will be explicitly flagged in the PR description (log values on the re-estimate path, new suppression case, richer error text, one new persisted state field).

  3. ranxianglei commented on Oct 6, 2026

    @ranxianglei
    Owner

    🤖 Powered by ework · qwen3.8-27b

    [bot] 🏷 已修复,PR:#477(未合并,等 CI + 人工合并)。

    审核结论(Triage)

    结构化七问

    1. 是什么问题:中继网关虚报 prompt usage(1.76–2.05×),ACP 照单全收并据此触发"增长",而当时可见上下文全是压缩块、没有任何可压缩范围——nudge 逼模型去猜已被消费的 ID,陷入重试空转。
    2. 什么原因导致的(分层):根因层——token 用量通道只信上游报告值、无本地交叉校验;放大层——nothingToCompress 对「零范围且零保护」组合存在逻辑空洞;表现层——compress 报错只给 "first–last 窗口 + 去调 acp_status()",窗口跨过了被消费的间隙,模型无法从中选出合法 ID。
    3. 怎么修复的(四条验收全部落实):
      • AC1+AC2:新增 lib/usage-sanity.ts 的 resolveCurrentUsage()——跨轮次跳变检测:当报告值环比 >1.5× 而本地 chars/4 载荷估算环比 ≤1.5×(两侧均 ≥5000 token 地板)时判定为 relay 膨胀,改用本地重估值并打 WARN 日志;诚实报告原样通过。三个调用点(isContextOverLimits、prePruneTokens、postTokens)统一走同一净化通道,基线算术保持一致。
      • AC3:inject.ts 增加 noRangesAtAll(零可压缩 ∧ 零保护消息)并入 nothingToCompress,审计日志新增 reason no_compressible_ranges;emergency 路径自然落到已有 cadence 门控的 /compact notice。
      • AC4:buildBoundaryRecoveryHint 重写为枚举实际连续空闲区间(Free ranges: m00001–m00002, m00005–m00007.,上限 8 段 + (+N more)),结尾 Retry with IDs inside the free ranges.。
    4. 是否有回归问题:逐项过过高危模式——诚实 provider 的数值逐字节不变(检测不触发时返回原报告值);阈值/时序/默认值均未动;错误处理仍是 fail-fast(compress 校验失败依旧抛错,只是提示更准);唯一语义变化是虚报场景下 nudge 从"注入"变"抑制"(这正是修复目标)。既有行为清单:baseline 累积/校正、emergency notice cadence、candidates 模式、T2/T3 tier trigger、Bug 20 suppress、Bug: Nudge injection loop — anchored nudges injected even when recommendation filter says "nothing to compress", and failed compress calls never reset pending-nudge state #216/perf: avoid transform work that scales with compression history #384 惰性分析——均未触碰其代码路径。
    5. 是否破坏缓存:无。新增持久化字段 usageSanity {reported, estimated} 为可选追加,旧状态文件照常加载(检测跳过一轮直到种子写入);损坏记录在 init 时丢弃而非投毒比较。重试/去重键不受影响。
    6. 是否改了设计方向:没有。用量通道仍是"报告值优先",本地估算只做异常仲裁而非替代——刻意不引入绝对值对比,因为 chars/4 对 CJK 低估可达 ~4×,绝对对比会在诚实的中文密集会话上大量误报(已在模块 docstring 与 DESIGN.md 记录此已知限制:一次性膨胀后保持稳定的场景会通过跳变门)。
    7. 是否引入了新的配置:无新 env/config/默认值;仅两个内部常量 RELAY_INFLATION_RATIO=1.5、PAYLOAD_FLOOR_TOKENS=5000(按验收标准取值,未开放配置)。

    行为变更披露(旧 → 新)

    项 旧 新
    prePruneTokens/postTokens/currentTokens 上游报告值原样 仅当 relay 膨胀时变为本地重估值(WARN 日志带新旧值);诚实报告不变
    nudge 抑制审计 reason 4 种 +no_compressible_ranges(原先这些回合会注入幽灵 nudge)
    compress 边界错误提示 Current visible: first–last (N msgs). … Call acp_status() … Free ranges: <连续空闲段>… Retry with IDs inside the free ranges.
    持久化状态 无 +可选字段 usageSanity

    验证

    • 新增 19 个测试全部通过:tests/usage-sanity.test.ts(10)、tests/nudge-no-ranges-suppression.test.ts(3,多轮 + 副作用断言,含端到端 1.76× 场景与"正常场景 nudge 仍触发"对照组)、tests/boundary-recovery-hint.test.ts(6)。
    • §5.7 fail-on-bug 矩阵:逐个临时回退修复 → 对应测试确认失败 → 恢复(AC3 回退→幽灵 nudge 注入;AC1/AC2 旁路→基线未从 100K 校正到 7K;AC4 回退→旧提示文本被抓出)。
    • typecheck 干净;全量回归交给 CI。

    判定:可合并(merge-ready),等 CI 绿后由人工点击合并——我不执行 merge。PR:#477

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions