Skip to content

Hardcoded 2s post-done exit grace silently drops the next message #238

Description

@RockerMJ031

TL;DR(中文)DEFAULT_POST_DONE_EXIT_GRACE_MS = 2e3 硬编码且无法配置。实测 claude CLI 从 result 事件到进程退出的固定开销就有 1.0–1.13 秒,2 秒预算只剩 0.9 秒余量。一旦超时进程被 run.stop() 强杀,被杀的 session 会污染下一条消息——用户在群里 @ bot 得不到任何回复,必须再发一次。整个过程只记一条 info 日志,用户完全无从知晓。


Environment

lark-channel-bridge 0.6.1 → also reproduced by code inspection on 0.6.4 and 0.7.0-beta.0
agent Claude Code (claude -p --output-format stream-json --resume <id>)
OS macOS 15 (Darwin 25.5.0), run via LaunchAgent
model claude-sonnet-5

Symptom

Users @ the bot in a Lark group and get no reply at all. Sending the exact same message a second time works. Over one month of logs: 314 runs, 11 force-kills, 8 dropped replies (~2.5%), but heavily clustered — on the busiest day it was 3 drops out of 12 runs (25%).

The dropped run is not an error. It is logged as a clean success:

{"phase":"run","event":"completed","result":"normal","durationMs":497,"traceId":"xxh19kvk"}
{"phase":"stream","event":"producer-not-started-before-agent-terminal","mode":"markdown"}

result: "normal" in ~500ms with zero output. Because it is "normal", nothing retries and nothing warns the user.

Root cause

src/runtime/run-executor.ts:

var DEFAULT_POST_DONE_EXIT_GRACE_MS = 2e3;
// ...
const exited = await run.waitForExit(this.postDoneExitGraceMs);
if (!exited) {
  log.warn("run", "post-done-exit-timeout", { ...dimensions, graceMs: this.postDoneExitGraceMs });
  await run.stop().catch(...);   // <-- SIGKILL-ish; leaves the Claude session mid-turn
}

The chain:

  1. Agent emits result → bridge considers the run done → waits 2s for process exit.
  2. Process does not exit in time → run.stop() force-kills it → the Claude session is left in an un-finalized turn.
  3. The next message resumes that same session id. The resumed session opens with a leftover
    Continue from where you left off.No response requested. (or immediately consumes a stale
    <task-notification>), goes terminal in ~500ms having produced nothing.
  4. awaitRenderAwareStream sees the agent terminal with no producer → calls runFallbackReply,
    but the fallback renders the agent's (empty) state, so nothing is sent to the chat.
  5. User sees silence, resends. The second message runs against a now-flushed session and works.

Correlation in our logs is exact: every dropped reply was immediately preceded, in the same
scope, by a run that hit post-done-exit-timeout.

Why 2s is not enough — measurement

I instrumented claude -p --output-format stream-json directly and measured the gap between the
result event and actual process exit, 6 runs:

scenario time to result result → exit
fresh session 4.69s 1.03s
resume, turn 2 4.04s 1.01s
resume, turn 3 4.92s 1.05s
resume, turn 4 3.77s 1.10s
with tool calls 8.15s 1.12s
resume + tool calls 8.96s 1.13s

The exit lag is constant at ~1.1s regardless of turn duration, tool count, or resume. It is
fixed shutdown cost (flushing the session file, tearing down MCP child processes), not work.

So the 2000ms budget is really ~900ms of headroom, and these measurements were taken under
favourable conditions: haiku, a few-KB session file, a moderately loaded machine. Our real
workload is sonnet-5 with a 684 KB session file and a dozen sibling agent processes running.
900ms does not absorb that.

This also explains why the failure looks random: force-kills hit runs of 174s and 9.5s alike, while
runs of 635s survived. What decides it is not how long the turn took, but whether shutdown fits in
the leftover 900ms.

Impact

Silent message loss with no user-visible signal. For a chat bridge this is the worst failure mode —
the user cannot distinguish "bot is thinking", "bot is broken", and "message vanished".

Note that 0.6.4 changed this path and downgraded the log line from warn to info:

- log.warn("stream", "producer-not-started-before-agent-terminal", { mode: input.mode });
+ log.info("outbound", "progress-stream-skipped", { mode: input.mode });

which makes the failure even harder to notice.

Suggested fixes

In rough priority order:

  1. Make the grace configurable and raise the default. There is a postDoneExitGraceMs field on
    RunExecutor, but nothing ever injects it from config — it is effectively a constant. Given a
    measured ~1.1s fixed cost, a 2s default has no margin. We are locally patching it to 3e4.
  2. Do not let a force-kill silently poison the next turn. If a run had to be killed, the next
    run on that scope should either start a fresh session or detect and discard the
    Continue from where you left off. / No response requested. no-op turn and retry once.
  3. Never let a run end with zero user-visible output. When producerStarted() is false and the
    fallback state is empty, post something ("agent produced no output, please resend") instead of
    staying silent. Silence is indistinguishable from a lost message.

(1) is a one-line mitigation; (2) is the actual bug; (3) makes the class of failure self-evident
instead of invisible.

Happy to supply the full JSONL logs or test the fix.

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