Phase 2a: retry card-profile activation so the HDMI sink can appear

Root cause of the silent-alarm-on-HDMI bug, measured on the host rather than
inferred:

    $ pactl list cards | grep 'alsa_card.pci-0000_01_00.1' -A1
    Active Profile: off
    $ pactl list short sinks
    61  alsa_output.pci-0000_0d_00.6.analog-stereo   IDLE

While that card's profile is "off" the G27Q's HDMI sink does not exist, so
_list_real_sinks() cannot return it. _play_on_all_sinks re-enumerates sinks
every beep cycle -- its docstring says it picks up late outputs "without
re-running activation" -- but that can never find a sink whose card is off.
There is nothing to enumerate.

Activation runs exactly once, at startup. At wake time the monitor has not
finished its HDMI handshake, the profile reads "available: no",
_parse_profile_line drops it, and the card is never revisited. Silent alarm.

_reactivate re-runs activation on a decaying schedule (3,5,7,10,15,20,30s)
on a daemon thread, logging the full enumerated sink list every pass so the
next failure is diagnosable from the JSONL log instead of guessed at.

Verified end to end on this machine:
  BEFORE: ['alsa_output.pci-0000_0d_00.6.analog-stereo']
  AFTER : ['alsa_output.pci-0000_01_00.1.hdmi-stereo',
           'alsa_output.pci-0000_0d_00.6.analog-stereo']
and a 1 kHz tone plays through the HDMI sink (paplay exit 0). Note the
constant ALARM_AUDIO_SINK was correct all along; only the activation was
failing.

Wiring into WakeAlarm lands with the _alarm.py split, since touching that
478-line file trips the 250-line gate.

399 tests, 100% branch coverage.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01EckWmyfetYq3Mi8MAnUudh
This commit is contained in:
Krzysztof Rudnicki 2026-08-26 23:02:52 +02:00
parent f5cfc3e452
commit eeb567ccce
3 changed files with 273 additions and 0 deletions

View File

@ -92,6 +92,13 @@ SYNC_TOKEN_FALLBACK_FILES: tuple[Path, ...] = (
# Where a successful read is cached, so a network blip can't cost a wake-up.
ALARM_CACHE_FILE: Path = Path.home() / ".config" / "wake_alarm" / "alarm_cache.json"
# Delays between card-profile reactivation passes while the alarm rings.
# The G27Q's HDMI sink takes ~15 s to enumerate after the monitor wakes, and
# until its card profile is switched on the sink does not exist at all -- so
# re-enumerating sinks alone can never find it. Decaying schedule: dense early
# (when outputs are still arriving), sparse later, stopping at ~2 minutes.
REACTIVATE_ATTEMPT_DELAYS: tuple[float, ...] = (3.0, 5.0, 7.0, 10.0, 15.0, 20.0, 30.0)
# Structured logs live under XDG state, not .config: they are churning runtime
# data, not configuration. The JSONL file is additive -- the journal keeps
# receiving the same records via stderr.

130
wake_alarm/_reactivate.py Normal file
View File

@ -0,0 +1,130 @@
"""Keep retrying card-profile activation while the alarm rings.
The bug this exists to fix, measured on the host:
$ pactl list cards | grep -A1 'alsa_card.pci-0000_01_00.1'
Active Profile: off
$ pactl list short sinks
61 alsa_output.pci-0000_0d_00.6.analog-stereo IDLE
The G27Q's HDMI sink is simply **absent** while its card profile is ``off``,
so re-enumerating sinks every beep cycle can never find it -- there is nothing
to find. Only re-running ``set-card-profile`` brings the sink into existence.
At wake time the monitor has not finished its HDMI handshake, so the profile
reads ``available: no``, ``_parse_profile_line`` drops it, and the card is
never revisited. One activation pass at startup is therefore not enough: the
retry has to keep going for as long as an output might still be arriving.
Bounded and non-blocking: a background thread with a decaying schedule, so the
beep loop is never delayed by a card that will never appear.
"""
from __future__ import annotations
from collections.abc import Callable, Iterable
import logging
import threading
from wake_alarm._constants import REACTIVATE_ATTEMPT_DELAYS
_Activate = Callable[[], object]
_ListSinks = Callable[[], Iterable[str]]
_Sleep = Callable[[float], object]
_logger = logging.getLogger(__name__)
def _attempt(
activate: _Activate, list_sinks: _ListSinks, attempt: int
) -> frozenset[str]:
"""Run one activation pass and report the sinks that resulted.
Args:
activate: Callable re-running card-profile activation.
list_sinks: Callable returning the current real sink names.
attempt: 1-based attempt number, for the log line.
Returns:
The set of sink names visible after this pass.
"""
activate()
sinks = frozenset(list_sinks())
_logger.info(
"Sink reactivation pass %d: %d sink(s) present: %s",
attempt,
len(sinks),
", ".join(sorted(sinks)) or "(none)",
extra={"sinks": sorted(sinks), "attempt": attempt},
)
return sinks
def reactivate_until_stable(
activate: _Activate,
list_sinks: _ListSinks,
*,
sleep: _Sleep,
stop: threading.Event | None = None,
) -> frozenset[str]:
"""Re-run activation on a decaying schedule, logging what appears.
Every pass is logged with the full enumerated sink list, so a future
silent alarm can be diagnosed from the JSONL log instead of guessed at.
Args:
activate: Callable re-running card-profile activation.
list_sinks: Callable returning the current real sink names.
sleep: Callable delaying between passes (injected for tests).
stop: Set once the alarm is dismissed, to end retrying early.
Returns:
The sink set observed on the final pass.
"""
seen = _attempt(activate, list_sinks, 1)
for index, delay in enumerate(REACTIVATE_ATTEMPT_DELAYS, start=2):
if stop is not None and stop.is_set():
break
sleep(delay)
if stop is not None and stop.is_set():
break
current = _attempt(activate, list_sinks, index)
gained = current - seen
if gained:
_logger.warning(
"New audio output(s) appeared %s into the alarm: %s",
"late",
", ".join(sorted(gained)),
extra={"gained": sorted(gained)},
)
seen = current
return seen
def start_background_reactivation(
activate: _Activate,
list_sinks: _ListSinks,
*,
sleep: _Sleep,
stop: threading.Event,
) -> threading.Thread:
"""Run :func:`reactivate_until_stable` on a daemon thread.
Args:
activate: Callable re-running card-profile activation.
list_sinks: Callable returning the current real sink names.
sleep: Callable delaying between passes.
stop: Set once the alarm is dismissed.
Returns:
The started thread.
"""
thread = threading.Thread(
target=reactivate_until_stable,
args=(activate, list_sinks),
kwargs={"sleep": sleep, "stop": stop},
daemon=True,
name="wake-alarm-reactivate",
)
thread.start()
return thread

View File

@ -0,0 +1,136 @@
"""Tests for repeated card-profile reactivation while the alarm rings."""
from __future__ import annotations
import threading
import pytest
from wake_alarm import _reactivate
from wake_alarm._reactivate import (
reactivate_until_stable,
start_background_reactivation,
)
@pytest.fixture(autouse=True)
def _fast_schedule(monkeypatch: pytest.MonkeyPatch) -> None:
"""Use a short, deterministic retry schedule instead of the real one."""
monkeypatch.setattr(_reactivate, "REACTIVATE_ATTEMPT_DELAYS", (1.0, 2.0))
def test_runs_one_pass_per_scheduled_delay_plus_the_first() -> None:
"""A schedule of two delays means three activation passes."""
calls: list[int] = []
reactivate_until_stable(
lambda: calls.append(1),
lambda: ["sink"],
sleep=lambda _d: None,
)
assert len(calls) == 3
def test_sleeps_for_each_configured_delay() -> None:
"""The decaying schedule is honoured, not collapsed into a busy loop."""
slept: list[float] = []
reactivate_until_stable(
lambda: None,
list,
sleep=slept.append,
)
assert slept == [1.0, 2.0]
def test_returns_the_final_sink_set() -> None:
"""The caller learns which outputs ended up present."""
result = reactivate_until_stable(
lambda: None,
lambda: ["a", "b"],
sleep=lambda _d: None,
)
assert result == frozenset({"a", "b"})
def test_reports_a_sink_that_appears_late(caplog: pytest.LogCaptureFixture) -> None:
"""The HDMI case: a sink absent at first must be announced when it lands."""
sequence = [["analog"], ["analog"], ["analog", "hdmi"]]
result = reactivate_until_stable(
lambda: None,
lambda: sequence.pop(0),
sleep=lambda _d: None,
)
assert result == frozenset({"analog", "hdmi"})
assert "hdmi" in caplog.text
def test_every_pass_logs_the_enumerated_sinks(caplog: pytest.LogCaptureFixture) -> None:
"""Each pass records what it saw, so a silent alarm is diagnosable."""
with caplog.at_level("INFO"):
reactivate_until_stable(
lambda: None,
lambda: ["analog"],
sleep=lambda _d: None,
)
assert caplog.text.count("Sink reactivation pass") == 3
def test_logs_none_when_no_sink_is_present(caplog: pytest.LogCaptureFixture) -> None:
"""An empty enumeration is stated explicitly rather than logged blank."""
with caplog.at_level("INFO"):
reactivate_until_stable(lambda: None, list, sleep=lambda _d: None)
assert "(none)" in caplog.text
def test_stop_event_ends_retrying_before_the_sleep() -> None:
"""Dismissing the alarm stops the retry loop promptly."""
stop = threading.Event()
stop.set()
calls: list[int] = []
reactivate_until_stable(
lambda: calls.append(1),
list,
sleep=lambda _d: None,
stop=stop,
)
assert len(calls) == 1
def test_stop_event_set_during_the_sleep_ends_retrying() -> None:
"""A dismissal landing mid-delay is noticed on wake, not ignored."""
stop = threading.Event()
calls: list[int] = []
reactivate_until_stable(
lambda: calls.append(1),
list,
sleep=lambda _d: stop.set(),
stop=stop,
)
assert len(calls) == 1
def test_background_thread_runs_the_passes() -> None:
"""The helper actually executes the work off the beep loop's thread."""
done = threading.Event()
stop = threading.Event()
thread = start_background_reactivation(
done.set,
lambda: ["s"],
sleep=lambda _d: None,
stop=stop,
)
thread.join(timeout=5)
assert done.is_set()
def test_background_thread_is_a_daemon() -> None:
"""A stuck retry must never keep the process alive after dismissal."""
stop = threading.Event()
stop.set()
thread = start_background_reactivation(
lambda: None,
list,
sleep=lambda _d: None,
stop=stop,
)
thread.join(timeout=5)
assert thread.daemon