Skip to content

fix(weixin): treat iLink "prepare failed" as a stale session, not a rate limit - #100815

Closed
raymondyan-zhijie wants to merge 2 commits into
NousResearch:mainfrom
raymondyan-zhijie:fix/weixin-prepare-failed-stale-session
Closed

raymondyan-zhijie wants to merge 2 commits into
NousResearch:mainfrom
raymondyan-zhijie:fix/weixin-prepare-failed-stale-session

Conversation

@raymondyan-zhijie

@raymondyan-zhijie raymondyan-zhijie commented Sep 2, 2026 •

Copy link
Copy Markdown

Problem

iLink answers ret=-2 for two different conditions: a genuine frequency limit, and a stale session. Only errmsg tells them apart, which _is_stale_session_ret already accounts for — but it only recognises unknown error (#17228).

The API also returns prepare failed once the stored context_token for a peer has gone stale. That token is refreshed only by an inbound message, so this failure is specific to unprompted sends:

  • an interactive reply always carries a token the user's own message just refreshed → succeeds
  • a cron / proactive push after a quiet period carries a stale one → ret=-2 errmsg=prepare failed

Because prepare failed misses the unknown error check, is_session_expired is false and the response falls through to the is_rate_limited = (ret == RATE_LIMIT_ERRCODE) branch. _send_text_chunk_locked therefore never reaches the tokenless retry directly above it — the retry whose own docstring says it exists to

keep cron-initiated push messages working even when no user message has refreshed the session recently

Instead the send burns six 30s backoffs and fails.

⚠️ The docstring premise above does not hold on iLink. The retry is reachable after this patch, but it does not deliver — see What this does not do. What this PR buys is the correct classification and a legible error, not restored delivery.

Observed

On a production deployment, 16 consecutive cron deliveries to a WeChat target failed this way while that same target's interactive replies were succeeding normally. Timeline of one occurrence:

08:30:36  cron: delivered to feishu:...  via live adapter      # other platform fine
08:30:36  [Weixin] rate limited for <peer>; backing off 30.0s  # actually a stale token
08:31:33  cron.jobs: Timed out waiting for local fire fence; failing closed
08:31:36  cron.scheduler: live adapter send to weixin:... timed out, falling back to standalone
08:33:38  [Weixin] send failed: iLink sendmessage rate limited: ret=-2 errcode=None errmsg=prepare failed

The cron fire fence expires while the adapter is still backing off, so the job is marked failed and the cause is misattributed to rate limiting. The tokenless retry does not rescue this send either (below) — what the patch changes is that the failure is reported as itself, ~90s sooner, instead of as a frequency limit.

Fix

Widen the helper to a frozenset of stale-session errmsg values so both spellings reach the existing tokenless retry. Genuine rate limits (freq limit) and the separate errcode -14 path are untouched.

The branch also carries a follow-up commit — a spent stale session is not a rate limit. Without it the widening alone still ends in a 3x backoff loop and feeds _record_rate_limit_event, because once the retry is spent (retried_without_token now true, or context_token falsy to begin with) the response falls through to the rate-limit arm purely on ret == -2.

What this does not do

It does not restore delivery to a dormant peer. Pairing every session expired for <peer>; retrying without context_token line in this deployment's gateway logs against subsequent rate-limit-backoff or send-failure lines (180s window), 2026-08-29 → 2026-09-15:

tokenless retries:  19
delivered:           0

Every tokenless attempt came back ret=-2 errmsg="prepare failed" — byte-for-byte the same response as the attempt that carried the real-but-stale token. Delivery resumed only after the peer sent an inbound message. On iLink the tokenless path is not a degraded fallback; it is a second way to fail.

Corroboration from other deployments is in the thread: @LohasGuy reports the same result from the field ("the widened classifier alone did not restore delivery … delivery resumed only after an inbound message from the peer"), and @Lsy5515 documents the silent-failure shape on a different deployment. Our own quantified run, and the measurement trap below, are here.

Verification

Added four cases to TestIsStaleSessionRet, and confirmed the existing negative cases still hold:

input expected why
(-2, None, "prepare failed") stale the fix
(None, -2, "prepare failed") stale iLink reports the code in either field
(-2, None, "Prepare Failed") stale match is case-insensitive
(-2, None, "unknown error") stale #17228 behaviour preserved
(-2, None, "freq limit") not stale genuine rate limit — no regression
(-14, None, "session expired") not stale separate path — no regression

After deploying the patch, the previously-unreachable branch fires in production:

[Weixin] session expired for <peer>; retrying without context_token

Firing is not delivering: that line now appears on the way to the same failure, ~90s earlier than it used to.

Measuring this is a trap — the same behaviour logs differently on either side of the follow-up commit

Before a spent stale session is not a rate limit:

[Weixin] rate limited for <peer>; backing off 30.0s before retry     (x3, ~90s total)
[Weixin] send failed to=<peer>: iLink sendmessage rate limited: ret=-2 errcode=None errmsg=prepare failed

After it:

[Weixin] send failed to=<peer>: iLink sendmessage stale session: ret=-2 ...; tokenless retry already attempted

So a naive count of send failed — or of anything containing rate limited — gives different numbers for identical behaviour depending on which side of that commit the window falls. Compounded by the adapter logging nothing on success (send_text returns SendResult(success=True, ...) with no info line), so success is only ever inferable from the absence of an error — the exact signal whose wording this changes. Worth knowing before anyone A/Bs this patch on log counts.

@alt-glitch alt-glitch added type/bug Something isn't working P2 Medium — degraded but workaround exists comp/gateway Gateway runner, session dispatch, delivery platform/wecom WeCom / WeChat Work adapter sweeper:risk-message-delivery Sweeper risk: may drop, duplicate, misroute, or suppress messages duplicate This issue or pull request already exists labels Sep 2, 2026
@alt-glitch

Copy link
Copy Markdown

This was generated by AI during triage.

Duplicate of #91647. Both add prepare failed to the Weixin ret=-2 stale-session classification so outbound sends use the existing tokenless recovery path instead of rate-limit backoff.

raymondyan-zhijie added a commit to raymondyan-zhijie/hermes-agent that referenced this pull request Sep 9, 2026
`_is_stale_session_ret` already routes iLink's ret=-2 "prepare failed" /
"unknown error" to the tokenless retry, but that retry is guarded by
`not retried_without_token and context_token`. Once it is spent — already
attempted, or never available because the send carried no context_token,
which is exactly the cron / proactive-push case the retry exists for — the
response falls through to the rate-limit arm purely because ret == -2.

That arm is the wrong medicine for a dead session: it burns a 3x backoff per
chunk and feeds `_record_rate_limit_event`, which can open the adapter-wide
cooldown circuit and then fast-fail unrelated sends for the whole window.

Surface it as a stale-session error instead, and break rather than raise so
the generic retry arm does not re-send against the same dead session.

Refs NousResearch#100815
raymondyan-zhijie added a commit to raymondyan-zhijie/hermes-agent that referenced this pull request Sep 9, 2026
`_is_stale_session_ret` already routes iLink's ret=-2 "prepare failed" /
"unknown error" to the tokenless retry, but that retry is guarded by
`not retried_without_token and context_token`. Once it is spent — already
attempted, or never available because the send carried no context_token,
which is exactly the cron / proactive-push case the retry exists for — the
response falls through to the rate-limit arm purely because ret == -2.

That arm is the wrong medicine for a dead session: it burns a 3x backoff per
chunk and feeds `_record_rate_limit_event`, which can open the adapter-wide
cooldown circuit and then fast-fail unrelated sends for the whole window.

Surface it as a stale-session error instead, and break rather than raise so
the generic retry arm does not re-send against the same dead session.

Refs NousResearch#100815
@raymondyan-zhijie

Copy link
Copy Markdown
Author

Follow-up pushed to this branch: the original fix routed iLink's ret=-2 + "prepare failed" to the tokenless retry, but that retry is guarded by not retried_without_token and context_token. Once the retry is spent, the response still falls through to the rate-limit arm purely because ret == -2.

Two ways to hit that in production:

  • No context_token at all. A cron / proactive push after a quiet period has nothing stored for the peer, so context_token is falsy and the guard short-circuits — which is exactly the case the tokenless retry was added for.
  • Retry already attempted. The tokenless send comes back "prepare failed" again; retried_without_token is now True, so the guard fails on the second pass.

In both cases the rate-limit arm is the wrong medicine for a dead session: it burns a 3x backoff per chunk and feeds _record_rate_limit_event, which can open the adapter-wide cooldown circuit and then fast-fail unrelated sends for the rest of the window.

The new commit surfaces it as a stale-session error instead, and uses break rather than raise so the generic except-arm does not re-send against the same dead session. Two regression tests cover both paths (no token, and post-retry), asserting no backoff sleep and an untouched cooldown circuit.

Observed on a production gateway: five errmsg=prepare failed sends logged as rate limited across 09-03/09-04, all after the original fix was already deployed.

@Lsy5515

Lsy5515 commented Sep 11, 2026

Copy link
Copy Markdown

现场补充一点:只把 prepare failed 归到 stale session 还不够——这条路径的失败是完全静默的。

实测(Hermes 0.20.6 / Windows 11,现场证据见 #101039 (comment) ):cron 日报投递失败时 job 的 last_status 仍是 ok,用户端零提示,错误只落在 logs/errors.log 的 [Weixin] rate limited …; cooldown active for 10.0s 里——一天内 3 份日报(09:49 / 14:44 / 15:08)就这样无声丢掉,直到人工翻日志才发现。

建议随这次分类一起补两点:

  1. 错误要可执行,例如 iLink push window closed: the peer must message the bot first (context_token is stale)——让运维一眼知道该做什么,而不是看到 rate limited 去查频率限制;
  2. 重试/熔断日志带上原始 ret/errcode/errmsg:_rate_limit_error() 目前把细节吞掉,只剩 cooldown active for N s,这正是排查被带偏的直接原因。

另附一个实测的返回形状坑(与本 PR 的判定逻辑相关):iLink 发送成功时返回 {"message_id": 7504170261280289288},不带 ret 字段;只有失败才带 ret/errcode。因此判定成功不能只看 ret == 0,否则会把成功当失败重试——我们就因此把同一份日报重复推送了 3 遍(现场:{"message_id": …} 被判为未知形状后进入重试分支)。

@LohasGuy

Copy link
Copy Markdown

Field data point on how far this fix reaches — from the deployment that filed the corroborating evidence on #82502 (issuecomment-5594240732).

We applied exactly this widening (unknown error / empty / rate limited / prepare failed) and the classifier behaves as advertised: after the patch the log shows the tokenless retry firing (session expired for <peer>; retrying without context_token) instead of the false rate-limit break. That half is verified.

But in our field case the widened classifier alone did not restore delivery. With the peer dormant, the tokenless retry was refused identically: context_token_present=False → ret=-2, errmsg="prepare failed" — byte-for-byte the same as the attempt carrying the real-but-stale token, which matches the controlled experiment @Lsy5515 posted on #82502. Delivery resumed only after an inbound message from the peer refreshed the session.

Implication for this PR: the premise "the failure misses the existing tokenless retry, so widening the classifier fixes cron pushes" holds only while the peer session is expired-but-refreshable. For a dormant peer the adapter has no send-side recovery — the fix converts a silent swallow into a correct classification, not into a delivery. Suggest covering the second half in the same change:

  1. keep the widened classifier (stops the false breaker) — required;
  2. surface an actionable error instead of cooldown active for N s, e.g. "iLink push window closed: the peer must message the bot to refresh the context_token". The ~24h keepalive requirement is a hard protocol constraint; no API call recreates that token (we verified getconfig returns only ret + typing_ticket and does not refresh the stored token, and that a tokenless send is refused the same way);
  3. log the raw ret/errcode/errmsg plus context_token_present. _rate_limit_error() currently discards precisely the field that separates stale session from a genuine frequency limit — that swallowing is what sends operators down the wrong path. We added that log line locally (_record_rate_limit_event() return path).

Status note (2026-09-11): all three PRs for this errmsg variant are still open — #100815, #96437, #91647 — none merged, and main still only recognizes "unknown error". This PR currently reports mergeable: false (conflict with main); a rebase would let the only fix for the prepare failed class actually land.

raymondyan-zhijie added a commit to raymondyan-zhijie/hermes-agent that referenced this pull request Sep 14, 2026
`_is_stale_session_ret` already routes iLink's ret=-2 "prepare failed" /
"unknown error" to the tokenless retry, but that retry is guarded by
`not retried_without_token and context_token`. Once it is spent — already
attempted, or never available because the send carried no context_token,
which is exactly the cron / proactive-push case the retry exists for — the
response falls through to the rate-limit arm purely because ret == -2.

That arm is the wrong medicine for a dead session: it burns a 3x backoff per
chunk and feeds `_record_rate_limit_event`, which can open the adapter-wide
cooldown circuit and then fast-fail unrelated sends for the whole window.

Surface it as a stale-session error instead, and break rather than raise so
the generic retry arm does not re-send against the same dead session.

Refs NousResearch#100815
admin and others added 2 commits September 15, 2026 02:17
…ate limit

iLink answers ret=-2 for both a genuine frequency limit and a stale
session; only ``errmsg`` disambiguates them. ``_is_stale_session_ret``
recognised ``unknown error`` (NousResearch#17228) but not ``prepare failed``, which
is what the API returns once the stored ``context_token`` for a peer has
gone stale.

That token is refreshed only by an *inbound* message, so the failure is
specific to unprompted sends: an interactive reply always carries a
fresh token, while a cron push after a quiet period does not. Because
the response was filed as a rate limit, ``_send_text_chunk_locked`` never
reached the tokenless retry directly above -- the retry whose docstring
states it exists to "keep cron-initiated push messages working even when
no user message has refreshed the session recently". Instead the send
burned six 30s backoffs and failed, while the cron fire fence expired
underneath it.

Observed in production as 16 consecutive cron delivery failures to a
WeChat target whose interactive replies were succeeding normally.

Widen the helper to a frozenset of stale-session errmsgs so both
spellings reach the tokenless retry. Genuine rate limits (``freq limit``)
and the separate errcode -14 path are unaffected.
`_is_stale_session_ret` already routes iLink's ret=-2 "prepare failed" /
"unknown error" to the tokenless retry, but that retry is guarded by
`not retried_without_token and context_token`. Once it is spent — already
attempted, or never available because the send carried no context_token,
which is exactly the cron / proactive-push case the retry exists for — the
response falls through to the rate-limit arm purely because ret == -2.

That arm is the wrong medicine for a dead session: it burns a 3x backoff per
chunk and feeds `_record_rate_limit_event`, which can open the adapter-wide
cooldown circuit and then fast-fail unrelated sends for the whole window.

Surface it as a stale-session error instead, and break rather than raise so
the generic retry arm does not re-send against the same dead session.

Refs NousResearch#100815
@raymondyan-zhijie
raymondyan-zhijie force-pushed the fix/weixin-prepare-failed-stale-session branch from 04a9ed1 to 1776009 Compare September 14, 2026 18:21
@raymondyan-zhijie

raymondyan-zhijie commented Sep 15, 2026 •

Copy link
Copy Markdown
Author

Field data from the same deployment as the Observed section above — window extended to 2026-08-29 → 2026-09-15 — corroborating @LohasGuy's result, with a count.

The classifier widening works. The tokenless retry has never once delivered.

I paired every session expired for <peer>; retrying without context_token line in this deployment's gateway logs against subsequent rate-limit-backoff or send-failure lines (180s window), across both retained logs:

tokenless retries:  19
delivered:           0

Every tokenless attempt came back ret=-2 errmsg="prepare failed" — byte-for-byte the same response as the attempt that carried the real-but-stale token, matching the controlled experiment on #82502. Delivery resumed only after the peer sent an inbound message. So on iLink the tokenless path is not a degraded fallback; it is a second way to fail. The PR's stated value should be restated as what it actually buys — correct classification and a legible error — rather than "keeps cron-initiated push messages working", which the field does not support.

A measurement trap worth recording

Before a spent stale session is not a rate limit, the spent-session case still fell into the rate-limit arm, so the same condition logged:

[Weixin] rate limited for <peer>; backing off 30.0s before retry     (x3, ~90s total)
[Weixin] send failed to=<peer>: iLink sendmessage rate limited: ret=-2 errcode=None errmsg=prepare failed

After it, the same condition logs one line:

[Weixin] send failed to=<peer>: iLink sendmessage stale session: ret=-2 ...; tokenless retry already attempted

So a naive count of send failed — or of anything containing rate limited — gives different numbers on either side of the commit for identical behaviour. I initially read the before/after delta as a regression introduced by the follow-up and only caught it by reading the raw lines. Worth spelling out in the PR body so the next person measuring this doesn't reach the same wrong conclusion.

Compounding it: the adapter logs failures but nothing on success. send_text returns SendResult(success=True, ...) with no log line, and the only record is logger.error("[%s] send failed to=%s: %s"). Success can therefore only be inferred from the absence of an error — the exact signal whose wording this commit changes.

Two suggestions

Both overlap with @Lsy5515's comment above; this field data supports them:

  1. Log a positive ack on success — logger.info("[%s] sent to=%s message_id=%s", ...). Without it, delivery is neither confirmable nor auditable from logs. (Per @Lsy5515, iLink returns {"message_id": ...} with no ret field on success; the adapter currently puts its own client_id in SendResult.message_id, so the server-side id is dropped.)
  2. Make the spent-session error actionable. stale session: ...; tokenless retry already attempted tells an operator what happened but not what to do. The actionable form is "the peer must message the bot first — context_token is only refreshed by inbound".

Taken together, that means the failure mode is silent (no success log, and the failure is only distinguishable by errmsg) and operator-unactionable — which is likely why separate deployments measured it differently before converging on the same conclusion.

@alt-glitch alt-glitch removed the duplicate This issue or pull request already exists label Sep 15, 2026
@alt-glitch

Copy link
Copy Markdown

This was generated by AI during triage.

Re-triage: no longer marked as a duplicate of #91647. The second commit on this branch (spent-session arm in _send_text_chunk, so prepare failed with no usable context_token breaks out with a stale-session error instead of taking the rate-limit backoff) is a concrete delta that #91647 does not carry. Treating the two as competing fixes for the same ret=-2 classification bug; #91647 is the narrower classifier-only change, this one is the superset. Maintainer to pick one.

@raymondyan-zhijie

Copy link
Copy Markdown
Author

Keeping this open — it is the minimal cut of the fix and still applies cleanly to main (mergeable: MERGEABLE; the BLOCKED state is just no CI reported on the branch).

One relationship worth flagging for triage. The earlier re-triage compared this against #91647 only. #96437 targets the same delta more broadly — it adds _is_stale_context_token_ret(), drops the tokenless retry, and adds a token-store delete() — and reaches the same conclusion for ret == -2 + prepare failed, independent of whether a context_token exists. This PR is the smaller cut of the same change: +101/-2, same two files, and the send loop is untouched apart from the stale branch. Either one is fine with me; I am not attached to which.

For the record, main still carries the unfixed predicate: gateway/platforms/weixin.py:68-70 is still (errmsg or "").lower() == "unknown error", and _send_text_chunk still routes ret == -2 into the rate-limit arm at :992-1002. A repo-wide search for "prepare failed" returns zero hits. So this is not "already fixed upstream" — it is one of several open attempts at the same errmsg surface (#91647, #85735, #80156, #80152, #96437), which is a fine reason to collapse them, just not on the grounds that the bug is gone.

@kshitijk4poor

Copy link
Copy Markdown

main now handles ret=-2 errmsg=prepare failed in two steps: #113069 (merge 46ab37ce35, salvage of #112713 by @KoNit-K) recognises it as a stale session and re-sends once without the context token, and #115359 (merge 5db9f02372, salvage of #80152 by @x7peeps with #80156 @JonthanaHanh) makes the unrecoverable case fail fast as a session error instead of opening the rate-limit breaker. This PR covered both halves; both are now on main (first submitted as #74572 / #80152). Closing as fixed on main; thanks.

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

Labels

comp/gateway Gateway runner, session dispatch, delivery P2 Medium — degraded but workaround exists platform/wecom WeCom / WeChat Work adapter sweeper:risk-message-delivery Sweeper risk: may drop, duplicate, misroute, or suppress messages type/bug Something isn't working

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants