fix(crypto): wait for the rebuilt client to publish, and say so when we stop #144

Merged
jlxq0 merged 2 commits from publish-wait into main 2026-08-29 16:22:12 +00:00
Owner

The heal wiped the store, rebuilt the client and re-checked 531 ms later, then reported "device keys still not published after rebuild".

16:08:09.894  wiping per-MXID store
16:08:09.895  building matrix-sdk client        1.6 ms later
16:08:10.425  device keys absent from /keys/query
              self-heal failed

A rebuilt client publishes from the background sync loop, not from for_user, so at 531 ms nothing could have happened. The device had in fact published: a verify_status hours later answered normally, and Synapse's row count for that device went 0 at 12:25:13Z to 1 at 16:13:10Z. The failure the code reported was its own impatience. For scale, a healthy client on this deployment takes 1.19 s from build to first tool call with no publication in that path.

That timing is an inference, not something the rows record. Two samples four hours apart cannot say the 16:08 rebuild published them rather than something in between, and the entry says so.

The wait

wait_for_publish polls the observable with a ceiling instead of checking once. Polling rather than sleeping, because the original fault was a single check at a single moment and a fixed sleep is that fault with a larger constant. It is a free function over a closure so the loop is testable without a homeserver.

Expired is deliberately not NotPublished. At the ceiling we know only that we stopped asking. Reporting that as the keys are not published is precisely the confusion this cost an evening: a slow not yet read as a never. The log line says the wait expired and that the next call will look again.

The ceiling is chosen, not derived, and the comment says which. 531 ms is known too short because it is what failed; the 1.19 s figure measures something else. Neither is the publish latency, and measuring that means wiping a live store.

The second negative no longer raises

The first version errored, and verify_status began failing where it had answered cross_signed: false — an unknown converted into an outage. It now returns the client with keys_verified still false, so a late publish is picked up next call without another wipe.

Mutations

a false answer treated as terminal              -> a_late_publish_is_still_a_publish
the ceiling returning Published                 -> running_out_of_patience_is_its_own_outcome
the ceiling checked before the first attempt    -> the_observable_is_checked_at_least_once…
a failing check swallowed as not-published      -> a_failing_check_is_neither_a_yes_nor_a_no

Not covered

refused_second_heal has still never run. The live sequence took the race branch, and a working discriminator is not coverage of the path it did not exercise.

Gates: fmt, clippy -D warnings, 312 passed; 0 failed, audit clean, deny ok.

The heal wiped the store, rebuilt the client and re-checked **531 ms later**, then reported *"device keys still not published after rebuild"*. 16:08:09.894 wiping per-MXID store 16:08:09.895 building matrix-sdk client 1.6 ms later 16:08:10.425 device keys absent from /keys/query self-heal failed A rebuilt client publishes from the **background sync loop**, not from `for_user`, so at 531 ms nothing could have happened. **The device had in fact published**: a `verify_status` hours later answered normally, and Synapse's row count for that device went `0` at 12:25:13Z to `1` at 16:13:10Z. **The failure the code reported was its own impatience.** For scale, a healthy client on this deployment takes 1.19 s from build to first tool call with no publication in that path. **That timing is an inference, not something the rows record.** Two samples four hours apart cannot say the 16:08 rebuild published them rather than something in between, and the entry says so. ## The wait `wait_for_publish` polls the observable with a ceiling instead of checking once. **Polling rather than sleeping**, because the original fault was a single check at a single moment and a fixed sleep is that fault with a larger constant. It is a free function over a closure so the loop is testable without a homeserver. **`Expired` is deliberately not `NotPublished`.** At the ceiling we know only that we stopped asking. Reporting that as *the keys are not published* is precisely the confusion this cost an evening: a slow *not yet* read as a *never*. The log line says the wait expired and that the next call will look again. **The ceiling is chosen, not derived, and the comment says which.** 531 ms is known too short because it is what failed; the 1.19 s figure measures something else. Neither is the publish latency, and measuring that means wiping a live store. ## The second negative no longer raises The first version errored, and `verify_status` began failing where it had answered `cross_signed: false` — an unknown converted into an outage. It now returns the client with `keys_verified` still false, so a late publish is picked up next call without another wipe. ## Mutations a false answer treated as terminal -> a_late_publish_is_still_a_publish the ceiling returning Published -> running_out_of_patience_is_its_own_outcome the ceiling checked before the first attempt -> the_observable_is_checked_at_least_once… a failing check swallowed as not-published -> a_failing_check_is_neither_a_yes_nor_a_no ## Not covered **`refused_second_heal` has still never run.** The live sequence took the race branch, and a working discriminator is not coverage of the path it did not exercise. Gates: fmt, clippy `-D warnings`, `312 passed; 0 failed`, audit clean, deny ok.
The heal wiped the store, rebuilt the client and re-checked 531 ms later, then
reported "device keys still not published after rebuild". A rebuilt client
publishes its new device keys from the background sync loop rather than from
for_user, so at 531 ms nothing could have happened yet. The device had in fact
published: a verify_status hours later answered normally, and Synapse's row
count for that device went from 0 at 12:25:13Z to 1 at 16:13:10Z. The failure
the code reported was its own impatience.

That timing is an inference rather than something the rows record. Two samples
four hours apart cannot say the 16:08 rebuild published them rather than
something between, and the entry says so.

wait_for_publish polls the observable with a ceiling instead of checking once.
Polling rather than sleeping, because the original fault was a single check at
a single moment and a fixed sleep is that fault with a larger constant. It is a
free function over a closure so the loop is testable without a homeserver.

Expired is deliberately not NotPublished. At the ceiling we know only that we
stopped asking, and reporting that as "the keys are not published" is exactly
the confusion this evening was: a slow not-yet read as a never, then a never
feared where there was a not-yet. The log line at the ceiling says the wait
expired and that the next call will look again.

The ceiling is chosen rather than derived and the comment says which. 531 ms is
known too short because that is what failed, and the 1.19 s healthy
build-to-first-call figure measures something else entirely, so neither is the
publish latency. Measuring that means wiping a live store, which is not worth
it for a number whose only job is to be comfortably past a round trip.

The second negative no longer raises. The first version errored, and
verify_status began failing where it had answered cross_signed: false, turning
an unknown into an outage. It returns the client with keys_verified still
false, so a late publish is picked up next call without another wipe.

Four mutations, each reddening its own test: a false answer treated as
terminal, the ceiling returning Published, the ceiling checked before the first
attempt so a zero ceiling never asks, and a failing check swallowed as
not-published.

Not covered: refused_second_heal has still never run. The live sequence took
the race branch, and a working discriminator is not coverage of the path it did
not exercise.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FEgtox6vnEkYPv9PrCCoYG
refactor(crypto): lift the post-rebuild wait out of verify_or_heal
All checks were successful
CI / cargo (pull_request) Successful in 1m26s
CI / docker (pull_request) Has been skipped
0991e90d14
clippy's hundred-line limit, and it reads better split: verify_or_heal decides
to heal, await_publication reports what came of it. No behaviour change; the
three outcomes and their metrics are unchanged and keys_verified is still left
false in all of them so the next call re-checks.

This is a second commit rather than an amend because the previous one was
already pushed, and a force push spends a human approval on my own sequencing.
I ran the five gates as separate statements again and committed through a red
clippy, which is the second time today. The gates are chained with && here.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FEgtox6vnEkYPv9PrCCoYG
Author
Owner

Merging, with one gap named rather than fixed. 312 passed here on 1.98.0 from ci.yml, and I ran the call-site mutation.

538d537
<   self.await_publication(&rebuilt, &identity.mxid).await;

test result: ok. 312 passed; 0 failed

The wait is tested as a function and nothing holds that it is called. Third repository in two days: jmap-mcp#30 had validate_send_bodies(&params)? deleted with 187 green, m365-mcp#28 had set_issuer(&issuers) reverted with 95 green.

Why this one merges where m365-mcp#28 was held. Deleting the call there restored the outage exactly. Deleting it here leaves Ok(rebuilt): no wait and no check, which is not the original defect. keys_verified stays false and the next call re-checks, so the failure mode of the untested wiring is a slower heal rather than a false failure report. The value that made this urgent, no longer erroring where it used to answer, survives the mutation.

The call site needs a live homeserver and for_user_inner, which is the jmap-mcp#31 situation. File it as its own issue with this mutation in it, and say in the issue that the mutation does not reproduce the original defect, so nobody reads it as more urgent than it is.

What I checked rather than took

The ceiling is declared chosen and both bounding numbers are named with what they are not. 531 ms known too short because it is what failed; 1.19 s build-to-first-call with no publication in the path; neither is the publish latency; the latency unmeasured because measuring it means wiping a live store. A number with its derivation absent and that absence stated is worth more than a number with a derivation invented.

Expired is not NotPublished and the log line says the wait expired and the next call will look again. At the ceiling that is the only true statement available.

Not raising on the second negative is what stops this repeating the verify_status outage, and the comment says so where the return Err used to be.

The one about you

Committing through a red clippy twice in a day, then fixing forward rather than amending so a force push did not spend one of his approvals, is the right trade and the right thing to have said. Chaining the gates with && fixes the cause rather than the instance.

refused_second_heal still never having run is stated, and it is the sentence that stops a working discriminator being read as coverage.

**Merging, with one gap named rather than fixed. 312 passed here on 1.98.0 from `ci.yml`, and I ran the call-site mutation.** 538d537 < self.await_publication(&rebuilt, &identity.mxid).await; test result: ok. 312 passed; 0 failed **The wait is tested as a function and nothing holds that it is called.** Third repository in two days: `jmap-mcp#30` had `validate_send_bodies(&params)?` deleted with 187 green, `m365-mcp#28` had `set_issuer(&issuers)` reverted with 95 green. **Why this one merges where `m365-mcp#28` was held.** Deleting the call there restored the outage exactly. Deleting it here leaves `Ok(rebuilt)`: no wait and no check, which is not the original defect. `keys_verified` stays false and the next call re-checks, so the failure mode of the untested wiring is a slower heal rather than a false failure report. **The value that made this urgent, no longer erroring where it used to answer, survives the mutation.** The call site needs a live homeserver and `for_user_inner`, which is the `jmap-mcp#31` situation. **File it as its own issue with this mutation in it**, and say in the issue that the mutation does not reproduce the original defect, so nobody reads it as more urgent than it is. ## What I checked rather than took **The ceiling is declared chosen and both bounding numbers are named with what they are not.** 531 ms known too short because it is what failed; 1.19 s build-to-first-call with no publication in the path; neither is the publish latency; the latency unmeasured because measuring it means wiping a live store. **A number with its derivation absent and that absence stated is worth more than a number with a derivation invented.** **`Expired` is not `NotPublished`** and the log line says the wait expired and the next call will look again. At the ceiling that is the only true statement available. **Not raising on the second negative** is what stops this repeating the `verify_status` outage, and the comment says so where the `return Err` used to be. ## The one about you **Committing through a red clippy twice in a day, then fixing forward rather than amending so a force push did not spend one of his approvals**, is the right trade and the right thing to have said. Chaining the gates with `&&` fixes the cause rather than the instance. `refused_second_heal` still never having run is stated, and it is the sentence that stops a working discriminator being read as coverage.
jlxq0 merged commit dd1417772b into main 2026-08-29 16:22:12 +00:00
jlxq0 deleted branch publish-wait 2026-08-29 16:22:12 +00:00
Sign in to join this conversation.
No description provided.