Skip to content

feat(bus): wake on NameOwnerChanged instead of polling out the cooldown (#669) - #683

Open
vibechoom wants to merge 1 commit into
mainfrom
feat/bus-wake-on-name-release-669
Open

feat(bus): wake on NameOwnerChanged instead of polling out the cooldown (#669)#683
vibechoom wants to merge 1 commit into
mainfrom
feat/bus-wake-on-name-release-669

Conversation

@vibechoom

Copy link
Copy Markdown
Contributor

The trade this un-makes

#668 (#653) fixed a real flood: a contested bus name used to retry RequestName at ~4 Hz forever — 14,400 calls an hour, silently. Feeding the Exists/InQueue path into consecutive_losses_to made permanent_after trip, latch, and drop to a cooldown: 12 attempts an hour, each logged. That fix stays, untouched.

What it cost was recovery. When the squatter exits we no longer noticed within 250 ms — we noticed on the next cooldown wake, up to ~5 minutes later. If mako or dunst holds org.freedesktop.Notifications when trollshell starts and you then stop it, notifications stayed dead for up to five minutes with nothing indicating why.

Poll-with-cooldown is the wrong shape for "wait until a name is released". D-Bus already pushes that event.

The select

give_up_and_wait no longer sleeps out the cooldown. It calls wait_for_release_or_cooldown, which select!s on:

  • the cooldown timer, and
  • the NameOwnerChanged stream this task already holds — waking on an empty new_owner, which is the broker saying the name is now unowned,

and re-attempts immediately on the signal. Near-instant recovery and the 12/hour ceiling, because the fast path is event-driven rather than polled: the attempt rate is now bounded by real ownership transitions of this one name (the broker emits exactly one per change), not by how short a sleep we dared to use.

The cooldown stays as the backstop, deliberately. A signal can be missed — the shared connection's message queue can overflow during a long wait, a match rule can fail to re-register across a broker restart — and a missed signal must degrade to "recovers in five minutes", never to "stranded forever". a_silent_subscription_falls_through_to_the_cooldown_backstop pins that, and asserts the full cooldown was served so an early return can't masquerade as the backstop.

The two wakes take deliberately different next moves, split into the pure next_attempt_after so the reasoning has somewhere to live:

wake next attempt why
Released same connection + subscription The name is free now; every millisecond spent rebuilding the subscription is a millisecond a contender can take it in — and the subscription is demonstrably live, it just delivered. Re-subscribing would re-run the RemoveMatch/AddMatch churn run_ownership documents as racy, for nothing.
Cooldown reconnect (as before #669) The timer firing with no signal is the one observation consistent with a wedged subscription, so the backstop rebuilds the thing that may have failed. That is what makes it a backstop rather than a slower copy of the fast path.

The startup race (#429's shape)

Nothing was reordered, because own.rs was already correct here — and #429 says so explicitly: it cites own.rs ("subscribes NameOwnerChanged before RequestName") as the reference the property path failed to follow. run_ownership builds the MessageStream inside with_conn, strictly before run_inner_loop issues any RequestName.

That ordering was merely tidy before; it is load-bearing now. A holder that exits between the RequestName that told us the name was taken and the start of the wait has already had its NameOwnerChanged buffered into the stream, so the wait returns on it immediately instead of falling through to the five-minute path — which would be exactly this bug, just rarer and much harder to reproduce. That is spelled out in a comment at the subscription site, including the constraint that nothing between there and run_inner_loop may re-subscribe.

Per-name filtering

Six names go through this path (notifications, tray, DisplayConfig, screensaver, bluetooth, Control), each with its own instance of this task. Filtering is at the broker: build_name_owner_changed_rule already sets an arg0 match on the name, so another name's release never reaches this process at all. is_release_of re-checks the name in-process as a second line of defence — one string compare, and it means a mis-built rule degrades into a missed wake (backstop catches it) rather than a wrong one. only_a_release_of_our_own_name_wakes_us feeds another name's release — the exact shape of our wake, on the wrong name — and asserts it is stepped over.

An ownership transfer (non-empty new_owner) is likewise not a wake: the name isn't free, so re-requesting would only earn another Exists.

What the fast recovery logs

WARN name=org.freedesktop.Notifications previous_holder=:1.42
     D-Bus name RECOVERED — the connection that was holding it has released it.
     Re-requesting now, woken by NameOwnerChanged rather than by the retry cooldown,
     so whatever this name backs comes back within milliseconds instead of minutes

warn! with RECOVERED, matching networkd's startup refresh and wifi's backend probe (#609/#613/#634) rather than inventing a shape. The level is the point: log_give_up is a warn!, so a recovery logged quieter would be invisible to exactly the person who saw the problem — they'd read "notifications are inert" and never get a line saying it stopped being true. It fires once per release actually observed, not on a timer.

log_give_up's own message also now says it is watching for the release, not just re-checking periodically.

Not regressed from #668

Tests

Hermetic (7 new, in own.rs's mod tests, no dbus-daemon) — wait_for_release_or_cooldown is generic over the stream, so the select and the filtering are driven with hand-built zbus::Messages:

  • a_release_of_the_wanted_name_ends_the_wait_at_once
  • only_a_release_of_our_own_name_wakes_us — the per-name filter
  • an_ownership_transfer_is_not_a_release
  • a_silent_subscription_falls_through_to_the_cooldown_backstop — asserts the full cooldown elapsed
  • an_ended_stream_still_serves_out_the_cooldown — a dead stream returns None forever; an early return here would spin the retry loop at CPU speed
  • an_undecodable_body_is_not_a_release
  • the_wake_decides_whether_the_subscription_is_reused — the select-arm decision

tokio's test-util (virtual time) isn't enabled in this crate and Cargo.toml was deliberately not touched, so the timing tests use a 60 ms real cooldown where they mean to reach the backstop and a 30 s one where they must not — the streams are in-memory and resolve in microseconds, so there is ~3 orders of magnitude of margin either way, and a regression fails in 30 s rather than hanging.

Gated (crates/hytte-bus/tests/own_release.rs, a new file — tests/common/mod.rs deliberately untouched, #678 is editing it): a_released_name_is_reacquired_without_waiting_out_the_cooldown. A squatter takes the name without AllowReplacement so every attempt returns Exists and the primitive latches PermanentlyTaken; the cooldown is set to 10 minutes against a 10-second recovery budget, so the cooldown wake cannot be what makes it pass — a regression times out instead of passing slowly. Deterministic by construction (the squatter owns the name before the primitive starts and holds it across the latch), and it runs in ~0.26 s.

Gates

All run locally in the devShell with RUSTC_WRAPPER unset:

  • cargo clippy --workspace --all-targets --features system-tests -- -D warnings — clean
  • cargo test --workspace — clean
  • xvfb-run -a cargo test --workspace --features system-tests — clean (54 suites)
  • nix fmt — clean

run_inner_loop's owned-then-lost arm moved into on_name_held, symmetric with on_name_taken, so both routes into a give-up share give_up_and_wait and can't drift — and run_inner_loop stays under the 100-line pedantic cap it had crossed.

Live-verify

Nothing in CI runs a competing notification daemon, so the scenario the issue is actually about needs a human on a live Niri session:

  1. systemctl --user start mako (or dunst) before trollshell, then start the shell.
  2. Confirm the journal shows the give-up warn naming mako's unique name, and that notifications are inert.
  3. systemctl --user stop mako.
  4. Expect: the D-Bus name RECOVERED warn within milliseconds, not minutes, and notify-send hi working immediately after. Before this PR that took up to five minutes and logged nothing when it happened.

Worth also checking the backstop hasn't been broken in the process: with mako left running, the give-up warn should still repeat about every 5 minutes and no more often.

Closes #669

🤖 Generated with Claude Code

…wn (#669)

#668 stopped a contested D-Bus name retrying `RequestName` at 4 Hz forever by
feeding the `Exists`/`InQueue` path into the consecutive-loss tally, so
`permanent_after` trips, latches, and drops to a 5-minute cooldown. That fix
stays. What it cost was recovery: when the squatter exits we noticed on the
next cooldown wake, so stopping mako left notifications dead for up to five
minutes with nothing saying why.

Poll-with-cooldown is the wrong shape for "wait until a name is released" —
D-Bus already pushes that event. The give-up now `select!`s on the cooldown
timer AND the `NameOwnerChanged` subscription this task already holds, and
re-requests the instant the signal reports the name unowned.

- `wait_for_release_or_cooldown` is the select. The timer stays as the
  backstop: a missed signal must degrade to "recovers in five minutes", never
  to "stranded forever". It is generic over the stream, so the select and the
  filtering are covered by hermetic tests with hand-built messages.
- No startup race: `run_ownership` already subscribes strictly before the
  first `RequestName` (#429 cites this ordering as the reference the property
  path failed to follow), so a release landing between the attempt and the
  wait is already buffered in the stream. Nothing was reordered; the ordering
  is now load-bearing and commented as such.
- Filtering is per-name at the broker (the `arg0` match rule), with an
  in-process re-check, so one of the six owned names releasing cannot wake the
  other five.
- The recovery logs at `warn!` with `RECOVERED`, matching networkd's startup
  refresh and wifi's backend probe (#609/#613/#634): the give-up is a `warn!`,
  so a quieter recovery would be invisible to exactly the person who saw the
  problem.
- The tally is deliberately untouched — `record_loss` still takes
  `Option<&str>` and an unattributable loss still continues the tally (#668);
  turning that back into a sentinel reintroduced the original bug once
  already.

`run_inner_loop`'s owned-then-lost arm moves into `on_name_held`, symmetric
with `on_name_taken`, so both routes into a give-up share `give_up_and_wait`
(and the function stays under the 100-line pedantic cap).

Closes #669

Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
@vibechoom

Copy link
Copy Markdown
Contributor Author

Adversarial review — the parts CI cannot check

Verdict: sound. No correctness defect found. I attacked the select! for cancellation-safety, the asymmetric wake routes for a non-terminating state, the #668 latch interaction, the startup-race claim, the per-name filter, and the test budgets. All five survived, several with a stronger guarantee than the PR body claims. Three non-blocking items below: one wrong mechanism in a design rationale, one ceiling that changed hands from us to the peer, one redundant assertion. Nothing here needs to hold the merge.

Line numbers are against own.rs at PR head (49572ac).

Finding 1 — the failure mode the backstop is justified by cannot happen in zbus 5.14

What. own.rs:501-503 (next_attempt_after) and own.rs:547-549 (wait_for_release_or_cooldown), plus the PR body, justify Cooldown ⇒ Reconnect with "a NameOwnerChanged dropped because the shared connection's broadcast queue overflowed while we waited". zbus 5.14 does not drop.

The per-match-rule channel is created at zbus-5.14.0/src/connection/mod.rs:1066 (broadcast(max_queued), default 64 via DEFAULT_MAX_QUEUED at mod.rs:45) and set_overflow appears nowhere in the crate. The socket reader publishes with sender.broadcast_direct(msg.clone()).await (zbus-5.14.0/src/connection/socket_reader.rs:73). On a non-overflow async_broadcast channel that call blocks until there is room. A full queue therefore stalls the socket-reader task for the entire shared connection — every other property/proxy/signal subscription on that bus, and every pending method reply — rather than silently losing our signal.

Why it matters, given no code change is needed. The backstop is still correctly justified by the other reasons stated (broker restart, AddMatch never registered, a bug), so the design stands. But two things follow from the real mechanism:

  1. Keeping the stream polled is a hard requirement, not an optimisation — MessageStream's own doc says "You must ensure a MessageStream is continuously polled or you will experience hangs" (zbus-5.14.0/src/message_stream.rs:22). This PR is an improvement here, and the PR body undersells it: the pre-feat(bus): wake on NameOwnerChanged instead of polling — #668's cooldown made squatter recovery take up to 5 min #669 sleep(cooldown) left a live, registered MessageStream unpolled for five minutes; the select! now polls it throughout the wait.
  2. The same latent stall is still open one function away, untouched by this PR: on_request_name_error's AccessDenied branch sleeps the full cooldown at own.rs:838 while the stream is alive and unpolled, and own.rs:882 sleeps a minute the same way. Pre-existing, not this PR's to fix, but it is the last five-minute unpolled window in the file and worth a follow-up now that the give-up one is gone.

Refutation attempted. (i) Maybe zbus enables overflow elsewhere — grepped the whole crate source, set_overflow is absent. (ii) Maybe receiver.set_await_active(false) (mod.rs:1067) changes queue-full behaviour — no, it only controls whether the sender waits for an active receiver. (iii) Maybe broadcast_direct errors instead of blocking when the receiver is inactive — it does, but the MessageStream holds an active Receiver for the whole wait, so it blocks. The claim survives.

Suggested fix. Correct the two comments to name the real mechanisms (broker restart / lost AddMatch / bug), and drop the overflow one — or state it as "the reader stalls", which argues for the select even more strongly. Optionally file the own.rs:838 window.

Severity: maintenance hazard (low). Doc-only; the code is right.

Finding 2 — the attempt/log ceiling stops being self-imposed and becomes peer-imposed

What. #653's complaint and #668's fix were about a ceiling we controlled: 12 attempts and 12 warn lines an hour, whatever the peer does. After this PR, give_up_and_wait (own.rs:619-628) re-attempts once per observed release with no floor between attempts, log_release_wake (own.rs:461-467) fires unconditionally on every release wake at warn!, and if the re-request then loses, log_give_up (own.rs:440-448) fires again at warn!.

Failure sequence. A contender that flaps the name — a notification daemon crash-looping, or any process doing RequestName/ReleaseName in a loop — drives one RequestName and up to two warn! lines per flap, with no rate cap anywhere in the path. The steady state is stable at that rate: on each release we usually win, go Owned, get replaced (we always pass AllowReplacement, own.rs:890), take the on_name_held give-up route because the tally is latched, and wait again. At 100 flaps/s that is 200 warn!/s. log_give_up's own doc still opens with "This fires at most once per cooldown" (own.rs:422), which its next sentence then contradicts.

Refutation attempted. (i) systemd's StartLimitBurst caps daemon restart loops — true for a systemd unit, but not for a script or a long-lived process that flaps the name directly, and the tray / DisplayConfig / screensaver names can be contended by things that are not units at all. (ii) The PR body concedes "one further line per observed release that we then still fail to win" and argues it "cannot become a flood on its own" — that concedes the mechanism and only denies that we are the ones driving it, which is exactly the property that changed. (iii) Each attempt lands on a name that is genuinely free, so it is a claim rather than a retry storm — I accept this for the attempt rate, which is why this is not a defect; it does not apply to the log rate. The finding survives, narrowed to logging.

Related, same site: the RECOVERED line is emitted before the RequestName that would confirm it (own.rs:619-622), and on the on_name_taken route holder is attributed_holder(tally) (own.rs:778), which can be UNKNOWN_HOLDER or a peer other than the one that just released. So a journal can legitimately show "D-Bus name RECOVERED … comes back within milliseconds" immediately followed by the give-up warn, naming the wrong previous holder.

Suggested fix. Cheap version: keep the Instant of the last release-wake log and drop to debug! when the previous one was less than cooldown / 10 ago, or log the first and every Nth consecutive release-wake that failed to win. Truthful version for the wording: emit RECOVERED after the acquisition succeeds rather than on the wake — more plumbing, so the rate cap is the better value-for-effort.

Severity: maintenance hazard (low).

Finding 3 — one redundant latency assertion in the new hermetic tests

What. own.rs:1236-1240, a_release_of_the_wanted_name_ends_the_wait_at_once asserts both Wake::Released and started.elapsed() < FAST_PATH_BUDGET (5 s wall clock). The first assertion is already a total proof of the property: the function returns a discriminated enum, so an implementation that fell through to the timer returns Wake::Cooldown and fails assert_eq! regardless of timing. The elapsed check has no discriminating power left to add, and it is the one line in the new tests that can produce a false red and cannot produce a true one — the shape #676 argues against ("liveness guards, not latency assertions") and #678 extends to this crate.

Refutation attempted. It would catch an implementation that returns Released only after sleeping out the cooldown — contrived, and LONG_COOLDOWN at 30 s already bounds that case as a liveness guard while the assert_eq! names it. Survives, weakly.

Suggested fix. Delete the elapsed() assertion; keep LONG_COOLDOWN.

Severity: minor / style.

Coverage — what I attacked and why it survived

  • select! cancellation-safety (the priority suspect): safe, unconditionally. futures_util::StreamExt::next returns Next<'a, St> { stream: &'a mut St } (futures-util-0.3.3x/src/stream/stream/next.rs:10-12) — the future holds no state, only a borrow, so dropping the losing arm cannot consume or lose an item. MessageStream::poll_next delegates straight to async_broadcast::Receiver (zbus-5.14.0/src/message_stream.rs:182-186), whose read position advances only on Ready. tokio::select! also runs the handler for whichever branch first returned Ready and stops polling the rest, so a Ready(Some(msg)) can never be polled-then-discarded. No signal can be lost here.
  • The timer is created outside the loop and re-borrowed with &mut timer (own.rs:558-562), not rebuilt per iteration. This is the classic bug in this shape — a sleep(cooldown) written inside the select! would have its deadline reset by every non-matching message, letting a peer postpone the backstop indefinitely. The code gets it right.
  • Released ⇒ SameConnection cannot livelock on a dying subscription. Enumerated every continuation: DBusProxy::new failure → 250 ms → reconnect (own.rs:868-873); RequestName error → on_request_name_error → reconnect (own.rs:897-902); PrimaryOwnerwatch_for_loss on a dead stream returns None → transient → reconnect (own.rs:694-703); Exists → give up → wait, and the timer is freshly re-armed on every entry to wait_for_release_or_cooldown (own.rs:558), so the cooldown can never fail to re-arm. Every path either reconnects or arms the backstop; none loops without one.
  • Stream-end serves out the remaining cooldown (own.rs:573-576) rather than returning early — correct, and load-bearing. I tried to argue for an immediate return (a dead stream is positive evidence to reconnect now, and the reconnect path has its own 250 ms floors). It fails: if with_conn and add_match both succeed but the fresh stream also ends immediately, the loop give-up → wait → end → reconnect → RequestNameExists → give-up contains no sleep other than this one. Serving out the cooldown is what bounds it. The test comment's "spin at CPU speed" is imprecise (a D-Bus round trip per iteration, not a CPU spin) but the conclusion is right.
  • fix(bus): log and back off a contested bus name instead of retrying silently at 4 Hz (#653) #668's latch: the non-reset is right and the unbounded tally is harmless. record_loss is byte-identical to fix(bus): log and back off a contested bus name instead of retrying silently at 4 Hz (#653) #668 — the PR touches no line of it, and Option<&str> still continues the tally on an unattributable loss (own.rs:390-405), so the <unknown> sentinel oscillation feat(bus): wake on NameOwnerChanged instead of polling — #668's cooldown made squatter recovery take up to 5 min #669 warns about has not been reintroduced. On repeated take/release the count grows via saturating_add (no overflow) and nothing reads its magnitude except the >= permanent_after test and the log field; the one arithmetic use, RETRY_AFTER_LOSS * consecutive (own.rs:796), is only reachable on the Retry arm where consecutive < permanent_after by construction, so it cannot grow with the tally.
  • Startup-race claim: verified, and it holds for a stronger reason than the PR gives. fix(bus): property tracking calls Get before subscribing — changes in the window are silently lost #429 does cite this file ("own.rs subscribes NameOwnerChanged before RequestName") as the reference. The subscription is built at own.rs:288-289, inside with_conn, strictly before run_inner_loop (own.rs:312) issues the first RequestName (own.rs:887). Better than program order: MessageStream::for_match_rule awaits conn.add_match(...) (zbus-5.14.0/src/message_stream.rs:130), which awaits the AddMatch method call to the broker (zbus-5.14.0/src/connection/mod.rs:1068-1077) before returning. The rule is registered broker-side before RequestName is even written to the socket, so the window is closed by acknowledgement, not just by ordering.
  • Per-name filter: really arg0. own.rs:964.arg(0, name) on the rule builder, and the line is pre-existing (this PR only added the explanatory doc above it). is_release_of (own.rs:527-534) re-checks in-process as claimed. A release of another owned name cannot reach the process, let alone wake the wrong waiter.
  • Ownership transfer correctly not a wake. With DoNotQueue on both sides we are never queued, so a holder exiting with a queued third party produces a transfer rather than an empty new_owner; the name is not free and is_release_of correctly returns false.
  • Stale buffered releases do not misbehave. A release buffered from before a re-acquisition can wake the wait spuriously. Traced it: RequestNameExistsrecord_loss sees a different holder → tally resets to 1 → the normal 250/500 ms ramp → re-latch. Self-limiting, and the buffer can only accumulate during the short unpolled windows (the RequestName round trip and the ≤750 ms ramp), because the wait now polls continuously. Costs one spurious RECOVERED line — folded into Finding 2, not a separate defect.
  • Test budgets — the 60 ms constants cannot flake, in either direction. Both uses are >= lower bounds (own.rs:1291, own.rs:1306), and tokio rounds sleep deadlines up to the next millisecond (tokio/src/runtime/time/source.rs:18-19, "Round up to the end of a ms"), so a sleep never returns early; contention can only make these pass more easily. The third 60 ms use (own.rs:1273) does not race at all — the stream is exhausted, so the None arm awaits the timer to completion deterministically. I disagree that 60 ms is a new flake source; the only flake-capable assertion in the hermetic set is the 5 s upper bound in Finding 3, and it is redundant rather than tight.
  • own_release.rs budgets: adequate, but it adds an 11th tenant to test(bus): the same 3s dbus-daemon handshake budget gates all 10 hytte-bus test files (#676 sibling) #678's gate. The 10 s poll-loop deadlines sit above the 1–5 s band test(bus): the same 3s dbus-daemon handshake budget gates all 10 hytte-bus test files (#676 sibling) #678 flags, against ~0.3–0.5 s of expected work (two refused attempts plus a 250 ms ramp), and wait_for_state's inner timeout drop is cancellation-safe for the same Next-holds-only-a-borrow reason. But the new file goes through common::ephemeral_bus, whose single-shot 3 s dbus-daemon handshake guard at crates/hytte-bus/tests/common/mod.rs:87 is exactly what test(bus): the same 3s dbus-daemon handshake budget gates all 10 hytte-bus test files (#676 sibling) #678 is open about — this makes it eleven files behind that gate rather than ten. Worth noting on test(bus): the same 3s dbus-daemon handshake budget gates all 10 hytte-bus test files (#676 sibling) #678, not a change to make here.
  • mod common; costs nothing: the module exports only ephemeral_bus and BusGuard, address already carries #[allow(dead_code)] (tests/common/mod.rs:24), and the new binary uses both — no new -D warnings surface.

What I did not verify

The live scenario itself. Nothing in nix flake check runs a competing notification daemon, and I did not run one either — the live-verify block in the PR body remains the only way to confirm the mako/dunst path end to end, and it is written correctly for that (including the "backstop still fires every ~5 min with mako left running" half, which is the part a fast-path-only check would miss).

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

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

feat(bus): wake on NameOwnerChanged instead of polling — #668's cooldown made squatter recovery take up to 5 min

1 participant