fix(bus): log and back off a contested bus name instead of retrying silently at 4 Hz (#653)

[vibechoom]

Refs #653

Step 1 only (the own.rs-confined half). Step 2 — consuming OwnState in
notifications.rs / tray/mod.rs — is not here; reasoning below.

The control flow, as I read it

I re-derived this from the file rather than trusting the citations, since #653
is explicit that it was never reproduced against a live competing daemon. My
reading matches the issue's, and the load-bearing detail checks out against
zbus 5.14's own docs:

run_inner_loop requests the name with
AllowReplacement | ReplaceExisting | DoNotQueue. RequestNameReply::Exists is
documented as "the name already had an owner, DoNotQueue was specified, and
either AllowReplacement was not specified by the current owner, or
ReplaceExisting was not specified by the requesting application" — we always
pass ReplaceExisting, so Exists means the current owner refused to be
replaced. Asking again cannot succeed while they hold it. (InQueue is
unreachable with DoNotQueue set, but the arm covers it.)

That arm then set Lost { transient: false, prev_owner: None }, slept 250 ms,
set Acquiring, and looped — on the same connection, so not even a reconnect
broke the cycle. It never touched consecutive_losses_to, so permanent_after
could not trip from it. Net: ~4 RequestName calls/second for the whole
process lifetime, ~14,400/hour, with zero log output — plus a Mutable write
per iteration, so any future subscriber would have been woken at 4 Hz too.

One thing the issue does not mention, which I found while restructuring: the
comment on consecutive_losses_to claimed it was "reset to None each time we
successfully (re-)acquire the name". It never was — nothing resets it on
acquisition. The actual behaviour (count losses to one peer across
re-acquisitions) is the more useful one, since that is exactly what detects a
replacement war, so I fixed the comment rather than the code.

What is logged, and at what level

All lines carry name (the contested well-known name) and, where known,
holder (the unique name actually holding it — resolved with one best-effort
GetNameOwner on the failure path).

Transition	Level	Was
Exists/InQueue, below threshold	warn!	(silent)
Exists/InQueue, latching PermanentlyTaken	warn!	(silent)
Displaced by a peer, below threshold	warn!	(silent)
Displaced by a peer, latching PermanentlyTaken	warn!	(silent)
Lost to a bus disconnect (transient)	debug!	(silent)
AccessDenied	info!	unchanged

The transient loss is debug! on purpose: connection.rs already warns about
the disconnect itself, and this line is only its consequence — warning twice for
one event is how a reconnect storm becomes unreadable.

GetNameOwner also means Lost.prev_owner and PermanentlyTaken.current_owner
are now populated on the contested path instead of None/never-reached.

The part I got wrong first, and how it was caught

Worth spelling out, because #653 is explicit that it was never reproduced and
this is precisely where a plausible-looking fix goes wrong.

My first version keyed the tally on a String holder and substituted a
"<unknown>" sentinel when GetNameOwner failed. That looked fine and passed
the new gated test — and broke the pre-existing
permanently_taken_after_three_losses, which hung for its full 15 s budget.
Instrumenting record_loss showed why:

record_loss holder=:1.1       -> consecutive=1
record_loss holder=<unknown>  -> consecutive=1
record_loss holder=:1.1       -> consecutive=1
record_loss holder=<unknown>  -> consecutive=1        ... forever

GetNameOwner does not fail rarely on this path — it fails systematically,
because a peer that refuses replacement often releases the name moments later,
so the broker answers NameHasNoOwner between our RequestName and our
lookup. With <unknown> treated as a holder in its own right, every second
observation reset the count to 1 and permanent_after could never trip: the
original 4 Hz bug, faithfully reproduced through a different door.

So record_loss now takes holder: Option<&str>, and an unattributable loss
continues the running tally and leaves its key alone rather than starting a
new one. UNKNOWN_HOLDER survives only as the display/state string for the case
where no holder was ever identified — and an all-unknown sequence still
escalates, so a broker that never answers cannot keep us retrying either. Both
rules are pinned by hermetic tests. UNKNOWN_HOLDER is exported so a consumer
matching on current_owner can recognise it.

The takeaway for review: the gated test that races two real owners is what
turned "reads correct" into "is correct", and the test that caught it was the
one already in the tree.

Cadence — the part with a live argument attached

permanent_after now trips from the Exists/InQueue path: record_loss
feeds it, so at the default of 3 the sequence is warn, 250 ms, warn, 500 ms,
latch PermanentlyTaken + warn, 5-minute cooldown.

The below-threshold gap grows with the consecutive count (RETRY_AFTER_LOSS * consecutive) so a name that is only briefly held is not declared permanently
taken after half a second — latching lands at ~0.75 s instead. That is one
multiplication against the existing constant, deliberately not a fourth
hand-rolled backoff type (#646); the give-up cooldown, not this ramp, is what
actually bounds the retry rate.

The tally then deliberately stays latched — it is not reset on give-up —
so each cooldown wake makes exactly one RequestName and re-latches, rather
than resetting to zero and firing a fresh burst of permanent_after attempts
every cycle. Steady state against a permanent squatter:

• RequestName: 14,400/hour → 12/hour.
• Log: 0/hour → 12/hour (3 lines up front, then one per cooldown).

That is the middle ground between the two positions this repo has already
argued, and the reasoning is written into log_give_up's doc comment so the
next person does not have to re-derive it:

• fix(wifi): retry an inconclusive backend probe instead of latching "no backend" (#613) #634 kept a failing probe loud on every attempt, explicitly because its
  backoff capped at 8 s — the cap is what made per-attempt logging affordable.
  The condition there was intermittent and self-healing, so the log was the
  measurement.
• chore(services): three hand-rolled exponential backoffs, and three fixed-2s reconnect loops with no ceiling (#645 follow-up) #646 objects to the opposite: flat 2 s retries with no ceiling and a warn
  each time, indefinitely.

A contested well-known name is a static condition — nothing changes until
the other process exits — so it must not log at the retry rate, but it must
still be findable in a journal opened hours after the shell started. Capping the
line to the cooldown gives both at ~0.003 lines/s. And unlike #634's case, the
condition is also carried continuously by the live OwnState signal, so a
consumer that wants it does not need a log line at all.

Honest cost: if the squatter exits, we now notice in up to 5 minutes rather
than 250 ms. That is the same trade the already-shipped PermanentlyTaken path
made (its docs already say "the supervisor still retries every 5 minutes"), so
this makes the two paths consistent rather than introducing a new property. The
better fix is to select! the cooldown against a NameOwnerChanged saying the
name went free — the subscription is already in hand — but that is new race
surface on a path #653 could not reproduce, and it is not what the issue asked
for. Worth a follow-up.

Step 2: not done

Deliberate, not skipped for time.

• The log-only half is now near-duplicate. Step 1's warn already names the
  contested bus name and the process holding it; a second error! in
  notifications.rs saying the same thing one level louder adds a word of
  domain consequence and a second journal line per event.
• The half that actually adds something a user can see — the "visible bar
  tell" fix(bus): nothing consumes OwnState — a contested bus name is silent and retries RequestName at 4 Hz forever #653 asks for — is UI work in trollshell/src/{overlays,widgets},
  which is outside this lane and is not a small diff.

So this is Refs #653, not Closes. #653 stays open for the consumer half,
which is now strictly easier: the state it needs to render is populated with a
real holder identity instead of None.

Tests

Hermetic (default cargo test), against the extracted record_loss decision so
the accounting is covered without a broker:

• consecutive losses to one holder accumulate and trip at permanent_after;
• alternating holders each look like a first loss and never accumulate;
• an unattributable loss continues the tally and does not erase its key — the
  regression test for the bug above;
• unknown holders alone still escalate, so an unanswering broker cannot pin us
  in a retry loop either;
• a latched holder stays latched (the anti-burst property that caps the retry at
  one per cooldown);
• a new holder after a latch gets a fresh budget.

Gated (system-tests), squatted_name_escalates_to_permanently_taken: a second
connection to the ephemeral broker takes the name without
AllowReplacement, so every RequestName from the primitive comes back
Exists — the real shape of the mako-owns-org.freedesktop.Notifications
collision. It asserts PermanentlyTaken and that current_owner is the
squatter's actual unique name. Non-flaky by construction: the squatter takes the
name before the primitive starts and holds it for the entire test, so there is
no window in which the primitive could win instead; there is no sleep-and-hope
and no ordering race between the two connections.

Both pre-existing gated tests (lost_then_reacquired,
permanently_taken_after_three_losses) pass unchanged — and both now exercise
the Exists path, since their campers take the name without AllowReplacement
too, which is how the accounting bug surfaced. The whole tests/own.rs file was
run 5× back to back looking for timing flake: 5/5 green.

Gates

All run locally in the devShell, clippy with RUSTC_WRAPPER unset:

• cargo clippy --workspace --all-targets --features system-tests -- -D warnings — clean
• cargo test --workspace — all pass
• cargo test --workspace --features system-tests (real dbus-daemon, under
  xvfb-run) — all pass
• nix fmt — 385 files, 0 changed

Live-verify

Nothing in CI runs a competing notification daemon, so the end-to-end behaviour
is unverified on a real session. To check on the deployed shell:

# 1. Start a squatter for the name trollshell wants.
systemctl --user start mako          # or dunst
systemctl --user restart trollshell

# 2. Expect exactly three warns within the first second, then one every 5 min.
journalctl --user -u trollshell -f | grep -i 'D-Bus name'
#   ... name=org.freedesktop.Notifications holder=:1.NN consecutive=1 ...
#   ... name=org.freedesktop.Notifications holder=:1.NN consecutive=2 ...
#   ... consecutive=3 retry_in_secs=300 "held by another connection ..."

# 3. Confirm the retry actually backed off (this is the regression under test):
busctl --user monitor --match \
  "type='method_call',member='RequestName',arg0='org.freedesktop.Notifications'"
#   pre-fix: ~4 calls/second, forever. post-fix: 3 quickly, then 1 per 5 min.

# 4. Recovery: stop the squatter, expect re-acquisition within one cooldown.
systemctl --user stop mako

org.kde.StatusNotifierWatcher (against another tray host) and the Mutter
DisplayConfig shim (against a real mutter) take the same path and should
behave identically.