diff --git a/wake_alarm/_constants.py b/wake_alarm/_constants.py index 554da72..f34042a 100644 --- a/wake_alarm/_constants.py +++ b/wake_alarm/_constants.py @@ -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. diff --git a/wake_alarm/_reactivate.py b/wake_alarm/_reactivate.py new file mode 100644 index 0000000..17bac3d --- /dev/null +++ b/wake_alarm/_reactivate.py @@ -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 diff --git a/wake_alarm/tests/test_reactivate.py b/wake_alarm/tests/test_reactivate.py new file mode 100644 index 0000000..b2b12fd --- /dev/null +++ b/wake_alarm/tests/test_reactivate.py @@ -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