feat(mcp): log initialize refusals, and say which bucket refused #22

Merged

jlxq0 merged 1 commit from fix-limiter-warn into main

2026-08-26 14:04:33 +00:00

jlxq0 commented

2026-08-26 14:02:36 +00:00

Owner

Refs #20, step 1 of the order. A gate, not a step: it ships and gets provoked on beta before any of the rest, because the whole diagnosis rests on inference from a logged absence and a good chain is not an observation.

What was missing

Nobody has directly observed this branch being taken. A user hitting the limit produced no server-side evidence at all: auth succeeded, no tool call followed, and the gap between them was the entire diagnosis. That gap is why the cause took an afternoon to find, and why the conclusion drawn from it — that the window "needs real time to reset" — was wrong in the direction that guarantees a second failure after the wait.

Two halves

The warn line. user_hash is the domain-separated identity hash, never the subject or the token. burst and refill_seconds are logged so the line carries the rule it enforced rather than making a reader go and find it.

And it names which bucket refused, because a refusal that says only "refused" is the same object as the 429 that says only "later". Three diagnoses were one value:

scope	meaning
`bearer`	one token reconnecting
`subject`	one identity across rotated tokens
`bucket_capacity`	the limiter's own map at `MAX_BUCKETS_PER_MAP` — not a quota refusal at all, and indistinguishable from one until now

subject is the shape a client minting a fresh token per session makes: every attempt gets a new bearer bucket and the same subject bucket, so the subject bucket is what runs out. That is #21, and it is almost certainly what happened here. Without the scope, the log line would have been unable to tell the two apart, which would have repeated the original fault one layer in.

No behaviour change

Same requests refused, same status, same body. Retry-After, a distinguishable error code, the env vars and the status counter are the rest of #20 and are deliberately absent here.

Verified by mutation

mutation	died
subject refusal reported as `Bearer`	`a_refusal_names_the_subject_bucket`, alone
bearer refusal reported as `Subject`	`a_refusal_names_the_bearer_bucket`, alone
`Subject` logs the string `"bearer"`	`refusal_scopes_have_distinct_log_values`, alone

Each with the pattern asserted to apply and the harness checked for a test result: line.

What is not tested here, stated rather than papered over: that the warn line itself fires. That needs a tracing subscriber capture, and the verification Alan sequenced is better than a test would be — provoke it on caldav-mcp-beta, which has logged two lines since 08:21:50Z, both startup. A 429 against that background is unmissable. A test would prove the code path; beta proves the deployed artefact.

Gates

cargo fmt --check, cargo clippy -D warnings, cargo test --all-features (113 + 9), cargo audit, cargo deny check bans licenses sources — green on rustc 1.98.0, through the shared build slot.

Refs #20, step 1 of the order. **A gate, not a step:** it ships and gets provoked on beta before any of the rest, because the whole diagnosis rests on inference from a logged absence and a good chain is not an observation. ## What was missing Nobody has directly observed this branch being taken. A user hitting the limit produced no server-side evidence at all: auth succeeded, no tool call followed, and the gap between them was the entire diagnosis. That gap is why the cause took an afternoon to find, and why the conclusion drawn from it — that the window *"needs real time to reset"* — was wrong in the direction that guarantees a second failure after the wait. ## Two halves **The warn line.** `user_hash` is the domain-separated identity hash, never the subject or the token. `burst` and `refill_seconds` are logged so the line carries the rule it enforced rather than making a reader go and find it. **And it names which bucket refused**, because a refusal that says only "refused" is the same object as the 429 that says only "later". Three diagnoses were one value: | scope | meaning | |---|---| | `bearer` | one token reconnecting | | `subject` | one identity across rotated tokens | | `bucket_capacity` | the limiter's own map at `MAX_BUCKETS_PER_MAP` — **not a quota refusal at all**, and indistinguishable from one until now | `subject` is the shape a client minting a fresh token per session makes: every attempt gets a new bearer bucket and the same subject bucket, so the subject bucket is what runs out. That is #21, and it is almost certainly what happened here. Without the scope, the log line would have been unable to tell the two apart, which would have repeated the original fault one layer in. ## No behaviour change Same requests refused, same status, same body. `Retry-After`, a distinguishable error code, the env vars and the status counter are the rest of #20 and are deliberately absent here. ## Verified by mutation | mutation | died | |---|---| | subject refusal reported as `Bearer` | `a_refusal_names_the_subject_bucket`, alone | | bearer refusal reported as `Subject` | `a_refusal_names_the_bearer_bucket`, alone | | `Subject` logs the string `"bearer"` | `refusal_scopes_have_distinct_log_values`, alone | Each with the pattern asserted to apply and the harness checked for a `test result:` line. **What is not tested here, stated rather than papered over:** that the warn line itself fires. That needs a tracing subscriber capture, and the verification Alan sequenced is better than a test would be — provoke it on `caldav-mcp-beta`, which has logged two lines since `08:21:50Z`, both startup. A 429 against that background is unmissable. A test would prove the code path; beta proves the deployed artefact. ## Gates `cargo fmt --check`, `cargo clippy -D warnings`, `cargo test --all-features` (113 + 9), `cargo audit`, `cargo deny check bans licenses sources` — green on `rustc 1.98.0`, through the shared build slot.

jlxq0 added 1 commit

2026-08-26 14:02:36 +00:00

feat(mcp): log initialize refusals, and say which bucket refused

CI / cargo (pull_request) Successful in 38s

Details

CI / docker (pull_request) Successful in 1m3s

Details

67f29f8fc2

Nobody has ever observed this branch being taken. A user hitting the limit
produced no server-side evidence at all: auth succeeded, no tool call followed,
and the gap between them was the entire diagnosis. That gap is why the cause
took an afternoon to find and why the conclusion drawn from it — that the
window "needs real time to reset" — was wrong.

The warn line is the first half. The second half is that it names which bucket
refused, because a refusal that says only "refused" is the same object as the
429 that says only "later". Three diagnoses were previously one value:

- Bearer: one token reconnecting.
- Subject: one identity across rotated tokens. This is the shape a client
  minting a fresh token per session makes — every attempt gets a new bearer
  bucket and the same subject bucket, so the subject bucket is what runs out.
  It is what #21 describes and what almost certainly happened here.
- BucketCapacity: the limiter's own bucket map at MAX_BUCKETS_PER_MAP, which
  is not a quota refusal at all and was indistinguishable from one.

`user_hash` is the domain-separated identity hash, never the subject or the
token. `burst` and `refill_seconds` are logged so the line carries the rule it
enforced rather than requiring a reader to go and find it.

No behaviour change: the same requests are refused with the same status and the
same body. Retry-After, a distinguishable error code, the env vars and the
status metric are the rest of #20 and are deliberately not in this commit — the
warn line is a gate, not a step. It gets provoked on beta before any of them
ship, because the whole diagnosis currently rests on inference from a logged
absence and a good chain is not an observation.

Refs #20

jlxq0 merged commit 2d2d6c2e34 into main

2026-08-26 14:04:33 +00:00

jlxq0 deleted branch fix-limiter-warn

2026-08-26 14:04:34 +00:00

jlxq0 referenced this pull request from a commit

2026-08-26 14:04:35 +00:00

Merge pull request 'feat(mcp): log initialize refusals, and say which bucket refused' (#22) from fix-limiter-warn into main