diff --git a/custom_components/addhon/__init__.py b/custom_components/addhon/__init__.py index 1b49dcf..77ddb00 100644 --- a/custom_components/addhon/__init__.py +++ b/custom_components/addhon/__init__.py @@ -310,13 +310,17 @@ def _raise_setup_error(err: Exception) -> NoReturn: ConfigEntryNotReady so HA retries setup later. Extracted from async_setup_entry so the branch is unit-testable (a swapped branch would otherwise pass the suite). (#11) """ - from .error_codes import classify + from .error_codes import classify, error_detail from .hon_client import _requires_reauth code = classify(err) + # error_detail() drops a leading "ADDHON-NNN: " so the code appears ONCE. These two + # messages are shown by Home Assistant on the config-entry page, so the user really + # did read the code twice before (#76). + detail = error_detail(err) if _requires_reauth(err): - raise ConfigEntryAuthFailed(f"[{code.label}] Invalid hOn credentials: {err}") from err - raise ConfigEntryNotReady(f"[{code.label}] Unable to connect to hOn: {err}") from err + raise ConfigEntryAuthFailed(f"[{code.label}] Invalid hOn credentials: {detail}") from err + raise ConfigEntryNotReady(f"[{code.label}] Unable to connect to hOn: {detail}") from err def _raise_update_error(err: Exception) -> NoReturn: @@ -325,13 +329,14 @@ def _raise_update_error(err: Exception) -> NoReturn: An auth error triggers the reauth flow (ConfigEntryAuthFailed); anything else is a transient UpdateFailed (the coordinator keeps its last good snapshot and retries). Extracted for unit-testing (#11).""" - from .error_codes import classify + from .error_codes import classify, error_detail from .hon_client import _requires_reauth code = classify(err) + detail = error_detail(err) if _requires_reauth(err): - raise ConfigEntryAuthFailed(f"[{code.label}] Invalid hOn credentials: {err}") from err - raise UpdateFailed(f"[{code.label}] hOn update error: {err}") from err + raise ConfigEntryAuthFailed(f"[{code.label}] Invalid hOn credentials: {detail}") from err + raise UpdateFailed(f"[{code.label}] hOn update error: {detail}") from err # "Washer-only" sensors that were mistakenly created on the tumble dryers (TD) diff --git a/custom_components/addhon/client/budget.py b/custom_components/addhon/client/budget.py new file mode 100644 index 0000000..f26f506 --- /dev/null +++ b/custom_components/addhon/client/budget.py @@ -0,0 +1,234 @@ +# Copyright (C) 2026 tis24dev +# SPDX-License-Identifier: AGPL-3.0-or-later + +"""Per-phase time budgets for the hOn setup (issue #76). + +A SINGLE cumulative cap of 60s used to cover everything the dedicated loop ran: +the full login (9 sequential round-trips), the appliance list, every per-appliance +load and the MQTT start. One constant for three workloads that differ by an order +of magnitude -- and when it fired, the error was attributed to whichever phase the +outermost caller had last written down. A user with a merely slow network saw +"ADDHON-400: Network timeout contacting hOn" from a login that had not finished. + +Budgets here are derived, never invented: + + budget(hops) = hops * SLOW_HOP + TOTAL_TIMEOUT + +* `SLOW_HOP` is what we grant a round-trip that is slow but alive. It is our own + `CONNECT_TIMEOUT`, not a new number. +* `+ TOTAL_TIMEOUT` is the tail margin that guarantees the invariant this module + exists for: ONE stuck hop must expire on its OWN aiohttp timeout (attributed, + with a message) and never on the budget (opaque). A budget must never be the + first thing to fire on a single-hop stall. +* `retries=` adds `n * (TOTAL_TIMEOUT + RETRY_DELAY)`. Whoever changes the retry + policy in `transport/retry.py` MUST keep this term in sync, or the budget kills + the retry exactly when it is needed. + +`hops` counts SEQUENTIAL round-trips on the critical path, not requests: three +requests fired in one `asyncio.gather` are one hop. + +TWO KINDS OF NUMBER, and confusing them is what made the first attempt at #76 WORSE +than the bug it fixed: + +* a SCOPE BUDGET (`budgeted()`) measures the OWN work of one phase. Scopes NEST -- + the sign-in is lazy, so `AUTH_FULL` runs *inside* the `APPLIANCE_LIST` scope of the + request that triggered it. Two independent `asyncio.timeout`s in that shape mean the + smaller OUTER one always fires first: `APPLIANCE_LIST`(40s) killed `AUTH_FULL`(184s) + at 40s and reported it as "load_appliances" -- the #76 string, now 20s SOONER than + the 60s cap it replaced. The fix is not to inflate every outer number until it + contains every inner one (the containment chain is unbounded once the 401 recovery + ladder can re-login twice); it is for the nested sign-in to SUSPEND the scopes it + interrupts, so each budget keeps measuring its own work. See `budgeted()`. +* a CAP (`cap()`) is the outer watchdog of a call site, waited on by + `HonClient._run_on_hon_loop` from ANOTHER thread. It cannot be suspended, so it must + contain what it may hold: its own work PLUS one lazy sign-in. + +Pure module: NO Home Assistant / aiohttp import, so transport, session and client +can all import it. It also OWNS the per-request aiohttp timeouts (which used to +live in `transport/connection.py`) so a budget can never be derived from a number +someone changes elsewhere. +""" +from __future__ import annotations + +import asyncio +import time +from collections.abc import AsyncIterator +from contextlib import asynccontextmanager +from contextvars import ContextVar + +from ..error_codes import HonCodedError, phase_timeout_code +from .phase import current_phase + +# Per-request HTTP timeouts on the session WE own. Without them aiohttp defaults to +# a 300s total, so a dead/blocked endpoint only failed when the dedicated-loop cap +# fired, as an opaque message-less timeout (issue #30). +CONNECT_TIMEOUT = 10 # TCP connect + TLS handshake to one endpoint +TOTAL_TIMEOUT = 30 # whole request incl. response read +SOCK_READ_TIMEOUT = 20 # gap between received chunks + +# Retry policy (transport/retry.py) -- kept here because the budgets must account +# for it. Fixed delay, never exponential: only a constant delay makes the added +# worst case computable in advance, which is what keeps it under the budget. +RETRY_DELAY = 2.0 +RETRY_MAX_EXTRA = 2 + +SLOW_HOP = CONNECT_TIMEOUT + + +def budget(hops: int, *, tail: float = 0.0, retries: int = 0) -> float: + """Time budget for a phase of `hops` sequential round-trips.""" + return hops * SLOW_HOP + TOTAL_TIMEOUT + tail + retries * (TOTAL_TIMEOUT + RETRY_DELAY) + + +# Full Salesforce login = 9 sequential round-trips: introduce, two manual redirects, +# login page, login POST, three GETs inside _get_token, api_auth POST. The retry term +# covers the extra attempts transport/retry.py may spend on the idempotent steps. +AUTH_FULL = budget(9, retries=RETRY_MAX_EXTRA) +# Refresh = token POST + api_auth POST. Never retried (the refresh token rotates and +# is single-use), so no retry term. +AUTH_REFRESH = budget(2) +# 2FA resume = two remoting calls, the finish call, the resume-token GET and api_auth. +MFA_RESUME = budget(5) +# The appliance list is a single POST. +APPLIANCE_LIST = budget(1) +# One appliance = 2 sequential waves after #76: the gather of 3 in load_commands, then +# load_attributes. load_statistics moved to the first coordinator refresh, which redoes +# it anyway. The budget keeps a third hop of headroom for a lazy re-auth in between. +APPLIANCE_ONE = budget(3) + +# What ONE lazy sign-in can add to the request that triggers it: `_check_headers` +# tries the refresh first and, when that leaves the tokens unusable, falls back to the +# full login -- sequentially, so the worst case is their sum. Scope budgets do NOT need +# to contain this (a sign-in suspends them); caps do. +LAZY_AUTH = AUTH_REFRESH + AUTH_FULL + +# Outer watchdogs for HonClient._run_on_hon_loop. These are NOT budgets: every phase +# below bounds itself and converts its expiry into an attributed coded error, so a cap +# only has to catch a loop that stopped progressing at all (a deadlock on the refresh +# lock, a task that never gets scheduled). +_CAP_MARGIN = SLOW_HOP + + +def cap(work: float) -> float: + """Outer watchdog for a call site: its own work PLUS one lazy sign-in. + + A cap is waited on from ANOTHER thread (a `concurrent.futures.Future`), so unlike + a scope budget it cannot be suspended while a nested sign-in runs -- it has to + contain it, or it fires first and destroys the attribution (issue #76). + + ONE sign-in is what it contains, and that is a DELIBERATE stop, not the worst case. + A single request can open three: `_check_headers` signs in lazily, then the 401 + ladder in `_intercept` adds a refresh and a second full login + (`AUTH_FULL + AUTH_REFRESH + AUTH_FULL` = 418s against COMMAND=284s). Sizing every + cap for that chain would put a user command at ~12min and the setup watchdog far + beyond what Home Assistant will wait for, to cover a case that means the tokens are + being rejected twice in a row. When it does happen the cap fires INSIDE the sign-in, + where the phase mirror reads "auth[/refresh]": the user gets the attributed, + retryable ADDHON-405/406, never the ADDHON-400 of #76. The degradation is bounded + and named -- that is the property, and `test_setup_budgets.py` pins it. + """ + return work + LAZY_AUTH + _CAP_MARGIN + + +CLOSE = 15 +# A command is one POST, but a rejected token makes it re-login inline, so it gets the +# sign-in allowance too. It used to be the bare 60s run cap, which truncated exactly +# the re-login it was waiting for. +COMMAND = cap(budget(1)) +# One appliance polled by the coordinator (hon_client._update_appliance_sync). +APPLIANCE_POLL = cap(APPLIANCE_ONE) +# Config-flow validation: minimal=True, no MQTT, no per-appliance loads -> a lazy +# refresh attempt, the full login and the appliance list. +VALIDATION_CAP = cap(APPLIANCE_LIST) +# Runtime setup adds MQTT and the per-appliance hydration. Sized for the inventory +# beyond which a stalled setup is a stall rather than slowness. +_WATCHDOG_APPLIANCES = 4 +MQTT_START = budget(1, tail=10) +SETUP_CAP = VALIDATION_CAP + MQTT_START + _WATCHDOG_APPLIANCES * APPLIANCE_ONE + + +# --- Scope budgets ------------------------------------------------------------ + +# Budget scopes currently open in THIS task, outermost first. Two things read it: a +# nested sign-in, to suspend the scopes it interrupts, and the login retry gate, to +# know the deadline that is actually in force instead of re-deriving one from a +# constant that may not be the tightest (issue #76). +_ACTIVE: ContextVar[tuple[asyncio.Timeout, ...]] = ContextVar( + "addhon_budget_scopes", default=() +) + + +def current_deadline() -> float | None: + """`time.monotonic()` instant at which the TIGHTEST open budget expires. + + None outside any budgeted scope (direct use, unit tests). Returned on the + `time.monotonic()` clock -- asyncio deadlines live on the loop clock, which is + built on `time.monotonic()` but is not required to be the same origin -- so + callers keep using the one clock they already use. + """ + deadlines = [ + when for scope in _ACTIVE.get() if (when := scope.when()) is not None + ] + if not deadlines: + return None + return time.monotonic() + (min(deadlines) - asyncio.get_running_loop().time()) + + +def _shift(scopes: tuple[asyncio.Timeout, ...], delta: float) -> None: + """Push the deadline of every scope in `scopes` by `delta` seconds.""" + if not delta: + return + for scope in scopes: + when = scope.when() + if when is None: + continue + try: + scope.reschedule(when + delta) + except RuntimeError: + # Already expired, or not entered: there is nothing left to suspend. + continue + + +@asynccontextmanager +async def budgeted( + seconds: float, *, suspends_caller: bool = False +) -> AsyncIterator[None]: + """Bound a phase and turn its expiry into an ATTRIBUTED coded error. + + Mandatory conversion rule: a bare TimeoutError must NEVER leave a budgeted scope. + It would reach the dedicated-loop cap with no phase attached and be mapped to the + mute ADDHON-460, which is what made transporting the phase pointless before (#76). + Converted HERE, i.e. still INSIDE the `phase()` scope the caller opened, so + `current_phase()` names the innermost step that actually stalled. A per-request + aiohttp timeout raised from inside is converted the same way and keeps its own + exception as `__cause__`. + + `suspends_caller=True` marks work the CALLER did not ask for: the sign-in that + `_check_headers` starts lazily inside somebody else's request. Its budget is pushed + onto every enclosing scope on entry and the unused remainder is taken back on exit, + so an enclosing budget keeps measuring its OWN work and can neither truncate the + sign-in (the #76 regression: `APPLIANCE_LIST`=40s killing `AUTH_FULL`=184s and + calling it "load_appliances") nor be spent by it. This is what lets every number + above stay the size of the work it names instead of growing to contain an unbounded + chain of nested re-logins. + """ + loop = asyncio.get_running_loop() + enclosing = _ACTIVE.get() + if suspends_caller: + _shift(enclosing, seconds) + started = loop.time() + try: + async with asyncio.timeout(seconds) as scope: + token = _ACTIVE.set((*enclosing, scope)) + try: + yield + finally: + _ACTIVE.reset(token) + except TimeoutError as err: + stalled = current_phase() + raise HonCodedError(phase_timeout_code(stalled), phase=stalled) from err + finally: + if suspends_caller: + # Give back what the sign-in did NOT use, so the caller's remaining budget + # is exactly what it had minus the time the interruption really cost. + _shift(enclosing, -(seconds - (loop.time() - started))) diff --git a/custom_components/addhon/client/engine/appliance.py b/custom_components/addhon/client/engine/appliance.py index 788080a..8f128d5 100644 --- a/custom_components/addhon/client/engine/appliance.py +++ b/custom_components/addhon/client/engine/appliance.py @@ -144,6 +144,33 @@ def model_id(self) -> int: def options(self) -> dict[str, Any]: return dict(self._appliance_model.get("options", {})) + @property + def model_attributes(self) -> dict[str, Any]: + """Per-MODEL metadata from `applianceModel.attributes` (cloud catalogue). + + Distinct from `attributes`, which is the device SHADOW (live telemetry): + this describes what the MODEL is, not what it is currently doing: + `zones`, `vtRoom1`/`vtRoom2`, `seriesVersion`, `doorNumber`, ... The hOn + app treats these as authoritative where the shadow is not: it decides + which fridge zones exist from `zones`.split("|"), never from which + `tempZ*`/`tempSel*` keys the shadow happens to carry. + + The cloud sends a LIST of `{parName, parValue, ...}` rows; flatten it to + parName -> parValue, the same normalisation __init__ applies to the + appliance-level `attributes`. Some payloads send a mapping already; + accept both and never raise on a malformed row. + """ + raw = self._appliance_model.get("attributes") + if isinstance(raw, Mapping): + return {str(key): value for key, value in raw.items()} + if isinstance(raw, list): + return { + str(row["parName"]): row.get("parValue") + for row in raw + if isinstance(row, Mapping) and row.get("parName") + } + return {} + @property def commands(self) -> dict[str, HonCommand]: return self._commands diff --git a/custom_components/addhon/client/phase.py b/custom_components/addhon/client/phase.py new file mode 100644 index 0000000..8d15e50 --- /dev/null +++ b/custom_components/addhon/client/phase.py @@ -0,0 +1,130 @@ +# Copyright (C) 2026 tis24dev +# SPDX-License-Identifier: AGPL-3.0-or-later + +"""Hierarchical setup phase, transported with the operation (issue #76). + +Before this module the phase was a plain attribute written by the OUTERMOST +caller (`NativeHon._setup_phase`) plus a second, unrelated tracker inside the auth +layer (`HonAuth._current_phase`). The login is LAZY -- it starts inside +`connection._check_headers`, triggered by the very request that `load_appliances` +issues -- so a stalled sign-in was attributed to `load_appliances` and mapped to +ADDHON-400 "Network timeout contacting hOn": the exact string reported in #76. + +Here the phase is a ContextVar composed by nesting, so an inner step wins over the +outer one (`load_appliances/auth/refresh`) and the scope is RESTORED on exit -- a +nested re-login no longer leaves the phase pointing at the auth layer forever. + +CROSS-THREAD CONSTRAINT (do not "simplify" this away): the ContextVar lives on the +dedicated hOn loop, while the waiter that must attribute an expired cap +(`HonClient._run_on_hon_loop`) runs on ANOTHER thread and cannot read it. The +`PhaseTracker` string mirror is that channel, not a leftover. Under +`asyncio.gather` each task gets a COPY of the context, so the mirror reflects the +last sibling that wrote it; that is acceptable because the precise value matters to +whoever RAISES (it reads its own `current_phase()` inside its own task) while the +mirror only serves the external attribution. + +Pure module: NO Home Assistant / aiohttp / awscrt import (same discipline as +`error_codes`, which is the only thing it imports, and `debug_utils`). The ledger +holds phase names, rounded seconds and a closed-domain outcome only -- never +identity, URL or payload. +""" +from __future__ import annotations + +import time +from collections import deque +from collections.abc import Iterator +from contextlib import contextmanager +from contextvars import ContextVar + +from ..error_codes import PHASE_TIMEOUT_CODES, HonCodedError + +_PHASE: ContextVar[str] = ContextVar("addhon_phase", default="") + +# Bounded so a long-lived session cannot grow it without limit; 40 entries cover a +# full setup (login steps + appliance list + per-appliance loads + MQTT) with room +# to spare. +_LEDGER_MAX = 40 + + +def current_phase() -> str: + """The composed phase of the operation running in THIS task ('' outside any).""" + return _PHASE.get() + + +class PhaseTracker: + """Cross-thread mirror of the phase stack plus a bounded timing ledger. + + One instance per `NativeHon`, shared down into the connection and the auth layer + (the auth object is REPLACED on every re-login, so the tracker cannot live there). + """ + + def __init__(self) -> None: + self.current: str = "" + self._ledger: deque[tuple[str, float, str]] = deque(maxlen=_LEDGER_MAX) + + def step(self, name: str) -> None: + """Refine the mirror with a sub-step of the ACTIVE scope (no ContextVar push). + + Used by the auth layer, whose `_phase()` markers are plain calls rather than + scopes. The enclosing `phase()` restores the mirror on exit, so a refinement + can never outlive its scope. + """ + base = _PHASE.get() + self.current = f"{base}/{name}" if base else name + + def record(self, name: str, seconds: float, outcome: str) -> None: + self._ledger.append((name, round(seconds, 1), outcome)) + + def entries(self) -> list[dict]: + """The ledger as closed-domain primitives (for Download Diagnostics).""" + return [ + {"phase": name, "seconds": seconds, "outcome": outcome} + for name, seconds, outcome in self._ledger + ] + + def summary(self) -> str: + """One-line ledger for the logs, e.g. 'auth 2.1s ok, load_appliances 58.4s timeout'.""" + return ", ".join( + f"{name} {seconds}s {outcome}" for name, seconds, outcome in self._ledger + ) + + +@contextmanager +def phase(segment: str, tracker: PhaseTracker | None = None) -> Iterator[str]: + """Enter a phase scope: compose, mirror, time, then RESTORE on exit. + + `segment` may itself contain '/' (e.g. "auth/refresh") when a step is naturally + two levels deep. + """ + parent = _PHASE.get() + composed = f"{parent}/{segment}" if parent else segment + token = _PHASE.set(composed) + previous = tracker.current if tracker is not None else "" + if tracker is not None: + tracker.current = composed + started = time.monotonic() + outcome = "ok" + try: + yield composed + except TimeoutError: + # asyncio.TimeoutError and concurrent.futures.TimeoutError are both + # TimeoutError since Python 3.11, so this one clause covers a per-request + # aiohttp timeout that nothing budgeted has converted yet. + outcome = "timeout" + raise + except HonCodedError as err: + # A budgeted scope converts its expiry into a coded error while it is still + # INSIDE this scope -- that is what lets it name the innermost step -- so the + # clause above never sees a budget expiry. Without this branch every budget + # expiry was filed as a plain 'error' and the 'timeout' outcome that + # diagnostics documents was unreachable in production. + outcome = "timeout" if err.error_code in PHASE_TIMEOUT_CODES else "error" + raise + except BaseException: + outcome = "error" + raise + finally: + _PHASE.reset(token) + if tracker is not None: + tracker.current = previous + tracker.record(composed, time.monotonic() - started, outcome) diff --git a/custom_components/addhon/client/session.py b/custom_components/addhon/client/session.py index fb9f5fc..e468d23 100644 --- a/custom_components/addhon/client/session.py +++ b/custom_components/addhon/client/session.py @@ -13,9 +13,11 @@ `subscribe_updates`/`notify` (the MQTT client reads exactly those members). Setup sequence: create connection -> `api.load_appliances()` -> for each appliance -build the HonAppliance and load commands/attributes/statistics -> start MQTT. The order -matters: the load_* calls make the first HTTP requests that populate the tokens, so that -when MQTT starts `api.auth.id_token` is present. +build the HonAppliance and load commands/attributes -> start MQTT. The order matters: +the load_* calls make the first HTTP requests that populate the tokens, so that when +MQTT starts `api.auth.id_token` is present. The statistics are NOT loaded here (issue +#76): the first coordinator refresh redoes them anyway, before any platform is +forwarded. """ from __future__ import annotations @@ -26,10 +28,18 @@ import aiohttp from . import factory +from ..debug_utils import redact_mac +from .budget import APPLIANCE_LIST, APPLIANCE_ONE, MQTT_START, budgeted +from .phase import PhaseTracker, phase from .transport.api import HonApi from .transport.auth import MFAChallengeRequired, NativeAuthError from .transport.connection import HonConnection -from ..error_codes import APPLIANCE_DATA_MALFORMED +from ..error_codes import ( + APPLIANCE_DATA_MALFORMED, + HonCodedError, + classify, + representative_failure, +) _LOGGER = logging.getLogger(__name__) @@ -69,9 +79,33 @@ def __init__( self._appliances: list[Any] = [] self._mqtt_client: Any = None self._notify_function: Any = None - # Coarse setup phase, read by HonClient when the dedicated-loop 60s cap fires + # Coarse setup phase, read by HonClient when the dedicated-loop cap fires # to attribute the (otherwise message-less) timeout to a stable error code. + # Kept FLAT ("load_appliances", "" when done) -- it is the shipped mirror the + # MQTT layer writes and the tests pin; `current_phase` below is the new, + # hierarchical one. self._setup_phase: str = "" + # Hierarchical phase mirror + timing ledger, shared down into the connection and + # the auth layer so a lazy sign-in names itself (client/phase.py, issue #76). + self._phase_tracker = PhaseTracker() + # "mac#zone" -> classified code for appliances whose hydration failed, for BOTH + # reasons an appliance can be appended half-built: a transport fault and a + # malformed payload. An entry means "the device exists but its data is + # partial", not "setup failed". The ZONE is part of the key because a + # multi-zone appliance is built once per zone under the SAME mac; without it + # the all-failed guard below would under-count the failures and ship a fully + # broken entry in silence. + self._hydration_failures: dict[str, Any] = {} + # The same failures with their exception, in order: the all-failed guard + # re-raises the REAL cause instead of a generic ADDHON-220 (the loss of cause + # CR#6 had already fixed on the poll path). + self._hydration_causes: list[tuple[str, Exception]] = [] + # The subset a RETRY could still fix: appliances left partial by a transport + # fault, held by identity. Two readers, and both are the reason the fault + # boundary is not just a swallowed exception -- the all-failed guard below and + # `needs_rehydration`, which makes the first coordinator refresh re-run + # load_commands before any entity is created. + self._retryable_partials: list[Any] = [] async def __aenter__(self) -> "NativeHon": return await self.create() @@ -107,6 +141,7 @@ async def create(self) -> "NativeHon": mobile_id=self._mobile_id, refresh_token=self._refresh_token, auth_trace=self._auth_trace, + phase_tracker=self._phase_tracker, ).create() self._api = HonApi(self._connection) await self.setup() @@ -198,9 +233,15 @@ async def _create_appliance(self, appliance_data: dict, zone: int = 0) -> None: self._appliances.append(appliance) return try: - await appliance.load_commands() - await appliance.load_attributes() - await appliance.load_statistics() + with phase("load_appliance", self._phase_tracker): + async with budgeted(APPLIANCE_ONE): + await appliance.load_commands() + await appliance.load_attributes() + # load_statistics() is NOT called here on purpose (issue #76): it is 2 + # more sequential round-trips per appliance, and the first coordinator + # refresh -- which runs BEFORE any platform is forwarded -- redoes them + # unconditionally (hon_client._update_appliance_sync). Loading them at + # setup only spends them twice, inside the budget we are trying to fit. except self._APPLIANCE_BUILD_ERRORS as error: # LOAD failure: the appliance object EXISTS but its data is partial. Keep # it appended (partial state -- the shipped behavior) and log. Broadened @@ -208,8 +249,83 @@ async def _create_appliance(self, appliance_data: dict, zone: int = 0) -> None: # (load_attributes pops a non-dict "shadow" then .get on it) and TypeError, # which previously escaped this catch and aborted the whole loop. self._log_malformed(error, appliance_data) + # Counted as partial too, though NOT as retryable: an appliance appended by + # THIS branch is just as unusable as one appended by the transport branch + # below, and the all-failed guard has to see both or it under-counts a + # mixed inventory (one malformed + one timed out = "1 failure out of 2" + # and an entry with zero working devices shipped in silence). + self._record_partial( + appliance, zone, APPLIANCE_DATA_MALFORMED, error, retryable=False + ) + except Exception as error: # noqa: BLE001 - re-raised below when fatal + # TRANSPORT fault boundary (issue #76, cause 4). aiohttp.ClientError and + # TimeoutError are not in _APPLIANCE_BUILD_ERRORS (TimeoutError derives from + # OSError, not from any of those five), so a single slow appliance used to + # escape here, unwind setup() and tear the whole config entry down. + # + # An AUTH rejection still MUST be fatal: it has to reach _raise_setup_error + # and open the reauth flow instead of quietly shipping a broken entry. + # asyncio.CancelledError is a BaseException and is outside this catch by + # construction, so a cancelled setup still propagates. + code = classify(error) + if code.requires_reauth: + raise + self._record_partial(appliance, zone, code, error, retryable=True) + # Leak-proof: the code label and a count only. The redacted mac goes to + # DEBUG, never to home-assistant.log at WARNING (same rule as + # _log_malformed). + _LOGGER.warning( + "[%s] Appliance kept with partial data after a transport failure " + "(%d so far this setup); the first coordinator refresh re-runs " + "load_commands before any entity is created", + code.label, + len(self._hydration_failures), + ) + _LOGGER.debug( + "addhOn: partial hydration for %s (%s)", + redact_mac(appliance.mac_address), + type(error).__name__, + ) self._appliances.append(appliance) + def _record_partial( + self, + appliance: Any, + zone: int, + code: Any, + error: Exception, + *, + retryable: bool, + ) -> None: + """Remember an appliance that was appended without complete data. + + Containing a TRANSPORT failure here is only half a fault boundary: + `load_commands` is what CREATES the command entities, and the integration has + no dynamic discovery, so an appliance left with empty `commands` would stay + without select/number/switch/button/climate/fan entities until a MANUAL + reload. The other half is `needs_rehydration` below, which makes + `hon_client._update_appliance_sync` re-run `load_commands` BEFORE the first + snapshot the platforms are built from, and lets a second failure abort the + first refresh -- so Home Assistant retries the setup instead of shipping a + crippled entry. + + `retryable=False` (a malformed payload) is recorded but NOT queued for that: + re-requesting a payload the parser cannot read produces the same payload, and + failing the setup forever would leave the user with LESS than the degraded + entry that ships today. + """ + self._hydration_failures[f"{appliance.mac_address}#{zone}"] = code + self._hydration_causes.append((redact_mac(appliance.mac_address), error)) + if retryable: + self._retryable_partials.append(appliance) + + def needs_rehydration(self, appliance: Any) -> bool: + """True if this appliance was appended without its commands by a TRANSPORT fault. + + By identity, not by mac: the caller holds the very object this session built. + """ + return any(pending is appliance for pending in self._retryable_partials) + async def setup(self) -> None: # Drop any partial inventory from an earlier setup() that a mid-setup MFA # challenge interrupted: submit_mfa_code() resumes by calling setup() again, and @@ -218,8 +334,19 @@ async def setup(self) -> None: # coordinator dedupes by id, so no double entities, just wasted work). Clear # IN PLACE, never rebind: the MQTT client binds this list by reference. self._appliances.clear() + self._hydration_failures.clear() + self._hydration_causes.clear() + self._retryable_partials.clear() self._setup_phase = "load_appliances" - appliances = await self.api.load_appliances() + # The hierarchical scope is what makes a LAZY sign-in nested in this request name + # itself ("load_appliances/auth/...") instead of borrowing this label -- the + # misattribution reported in #76. The flat mirror above is kept untouched. + # APPLIANCE_LIST budgets THIS POST only: a sign-in triggered from inside it + # suspends this scope for as long as it runs (client/budget.py), so the number + # here stays the size of the work it names. + with phase("load_appliances", self._phase_tracker): + async with budgeted(APPLIANCE_LIST): + appliances = await self.api.load_appliances() self._setup_phase = "load_appliance" for appliance in appliances: # Guard a non-dict element BEFORE appliance.get(...)/appliance.copy() can @@ -246,12 +373,50 @@ async def setup(self) -> None: for zone in range(zones): await self._create_appliance(appliance.copy(), zone=zone + 1) await self._create_appliance(appliance) + # Anti-illusion guard, symmetric with the all-failed rule the poll already + # applies: containing ONE broken appliance is a degradation, containing ALL of + # them is a masked failure. An entry that starts with nothing usable must fail + # loudly so Home Assistant retries, not ship an empty integration. + # + # Counting: EVERY partial appliance counts as unusable, whatever left it that + # way -- otherwise a mixed inventory (one malformed + one timed out) reads as + # "1 of 2 failed" and ships. Triggering: at least one of them must be + # RETRYABLE, because that is the premise of raising -- Home Assistant retries. + # An inventory that is only malformed will parse exactly the same way next + # time, so failing forever would give the user less than the degraded entry + # that ships today. + if ( + self._appliances + and self._retryable_partials + and len(self._hydration_failures) >= len(self._appliances) + ): + # Re-raise the REAL cause, chained: with a single appliance (the common + # case) a bare APPLIANCE_LOAD_FAILED told the user "could not load + # appliance data" and threw away the ADDHON-400/430/450 that says why. + # Same helper the poll path uses, so the two cannot drift. + code, cause = representative_failure(self._hydration_causes) + raise HonCodedError( + code, + f"No usable appliance after loading all {len(self._appliances)}", + phase="load_appliance", + ) from cause if self._enable_mqtt and not self._mqtt_client: # NativeMqttClient owns MQTT recovery. On a retryable AWS token/transport # outage create() returns a retained, temporarily-disconnected client whose # watchdog retries in the background; unexpected programming/configuration # errors still propagate instead of being silently converted to polling-only. - self._mqtt_client = await self._make_mqtt() + # + # The scope is the invariant, not a decoration: MQTT_START is SUMMED into + # SETUP_CAP (client/budget.py) yet this was the one phase inside that cap + # with no budget of its own, so a first connect that stalled was bounded + # only by SETUP_CAP -- the config entry took ~10 minutes to fail on a phase + # whose own number says 50s, and "every phase limits itself, the cap only + # catches a loop that stopped progressing" was false exactly here. The MQTT + # layer keeps REFINING the mirror inside this scope (mqtt_connect, + # mqtt_subscribe), so the attribution stays as precise as it was. + with phase("mqtt_start", self._phase_tracker): + async with budgeted(MQTT_START): + self._mqtt_client = await self._make_mqtt() # Setup done: clear the phase so a later (non-setup) loop timeout is not # mis-attributed to a setup step. self._setup_phase = "" @@ -273,6 +438,30 @@ def refresh_token(self) -> str: except Exception: # noqa: BLE001 - no auth yet return "" + @property + def current_phase(self) -> str: + """Hierarchical phase of the operation in flight, e.g. 'load_appliances/auth'. + + This is the CROSS-THREAD channel: `HonClient._run_on_hon_loop` waits on another + thread and cannot read the ContextVar that carries the phase inside the loop. + """ + return self._phase_tracker.current + + @property + def phase_ledger(self) -> list[dict]: + """Per-phase duration+outcome for the last operations (leak-proof primitives).""" + return self._phase_tracker.entries() + + @property + def phase_summary(self) -> str: + """One-line ledger for the logs, e.g. 'auth 2.1s ok, load_appliances 58.4s timeout'.""" + return self._phase_tracker.summary() + + @property + def degraded_appliances(self) -> dict[str, Any]: + """'mac#zone' -> code for appliances kept with partial data (diagnostics only).""" + return dict(self._hydration_failures) + @property def auth_phase(self) -> str: """Last login phase the auth layer reached (for diagnostics attribution).""" diff --git a/custom_components/addhon/client/transport/auth.py b/custom_components/addhon/client/transport/auth.py index b54603c..a0f82dc 100644 --- a/custom_components/addhon/client/transport/auth.py +++ b/custom_components/addhon/client/transport/auth.py @@ -43,8 +43,11 @@ summarize_response, summarize_tokens, ) +from ..budget import AUTH_FULL, current_deadline +from ..phase import PhaseTracker from .device import HonDevice from .headers import USER_AGENT +from .retry import RetryBudget, retry_transport from .oauth import ( APEXREMOTE_PATH, AUTH_API, @@ -163,6 +166,7 @@ def __init__( password: str, device: HonDevice, auth_trace: AuthDiagnosticTrace | None = None, + phase_tracker: PhaseTracker | None = None, ) -> None: self._session = session self._email = email @@ -181,13 +185,23 @@ def __init__( self._loaded: Any = None self._page_url = "" # Last login phase reached, for the DEBUG trace + diagnostics attribution ("failed - # during mfa_verify"). Updated by _phase(); read via NativeHon.auth_phase. + # during mfa_verify"). Updated by _phase(); read via NativeHon.auth_phase. Stays + # FLAT on purpose: it is the legacy mirror the diagnostics already publish. self._current_phase = "" + # Shared with the session/connection (client/phase.py): the cross-thread mirror + # of the HIERARCHICAL phase, so a login running lazily inside load_appliances + # says "load_appliances/auth/..." instead of borrowing its caller's label (#76). + self._phase_tracker = phase_tracker + # Extra attempts for the idempotent steps of the CURRENT authenticate(); None + # outside it, so the refresh and 2FA paths are never retried. + self._retry_budget: RetryBudget | None = None def _phase(self, name: str, **fields: Any) -> None: """Mark + DEBUG-log a login phase. Content is STRUCTURE only (status/booleans/ phase name) -- never email/password/OTP/token/csrf/cookie/url (leak-proof).""" self._current_phase = name + if self._phase_tracker is not None: + self._phase_tracker.step(name) if _LOGGER.isEnabledFor(logging.DEBUG): extra = " ".join(f"{k}={v}" for k, v in fields.items()) _LOGGER.debug("auth phase %s%s", name, f": {extra}" if extra else "") @@ -370,8 +384,13 @@ async def _manual_redirect(self, url: str) -> str: async def _handle_redirects(self, login_url: str) -> str: self._phase("redirects") - r1 = await self._manual_redirect(login_url) - r2 = await self._manual_redirect(r1) + budget = self._retry_budget + r1 = await retry_transport( + budget, "manual_redirect", lambda: self._manual_redirect(login_url) + ) + r2 = await retry_transport( + budget, "manual_redirect", lambda: self._manual_redirect(r1) + ) return f"{r2}&System=IoT_Mobile_App&RegistrationSubChannel=hOn" async def _open_login_page(self, login_url: str) -> None: @@ -578,20 +597,58 @@ async def _api_auth(self) -> None: self._phase("api_auth", status=resp.status, cognito_token=True) async def authenticate(self) -> None: + # WHAT IS RETRIED, and why the rest is not (issue #76). Retried, because a + # duplicate delivery costs nothing: _introduce (a GET whose replay only opens + # another authorize session, and which re-mints its own nonce), the two + # _manual_redirect hops (GETs with allow_redirects=False that read one header), + # _open_login_page (a GET, and the replay re-reads the fwuid/loaded that a + # framework rotation would have invalidated) and _api_auth (the hOn endpoint we + # already re-invoke on every successful refresh). + # + # NOT retried: _login submits the credentials and advances the Salesforce + # session (its payload embeds the fwuid captured one step earlier, and a + # duplicate delivery races the `sid` cookie the next three steps depend on); the + # three GETs inside _get_token each consume a SINGLE-USE hand-off (a second + # post-login fetch lands on a login page -> "no href" -> a transient blip would + # become a permanent credentials error, and a second ProgressiveLogin fetch mints + # a NEW MfaContext that any already-sent OTP no longer matches); refresh() spends + # a rotating, single-use refresh token; every MFA step sends an email or burns a + # verification attempt. self.clear() + # Deadline for the shared retry budget, taken from the budget scope that is + # ACTUALLY in force (client/budget.py) rather than re-derived from AUTH_FULL. + # Re-deriving it was a fiction: the enclosing scope may be tighter, and a gate + # measured against a deadline nobody enforces never refuses anything -- so the + # retry became the very thing that spent the budget, the opposite of the + # invariant retry.py claims. None only outside any scope (direct use, unit + # tests), where the phase budget the call sites open is the honest stand-in. + deadline = current_deadline() + if deadline is None: + deadline = time.monotonic() + AUTH_FULL + budget = RetryBudget(deadline=deadline) + self._retry_budget = budget + # The enclosing `phase("auth")` scope is opened by the CALLER (connection.py), + # next to the AUTH_FULL budget it belongs to, so an expiry is still inside the + # scope when it is converted into a coded error. try: - login_url = await self._introduce() - redirect = await self._handle_redirects(login_url) - await self._open_login_page(redirect) - url = await self._login() - await self._get_token(url) - await self._api_auth() - except _NoAuthNeeded: - # The authorize page already carried the OAuth tokens (a still-valid SSO - # cookie), so the login steps are skipped -- but cognito_token is minted - # ONLY by _api_auth and connection.py needs it for every API call. Run it - # so this path completes with usable auth headers instead of empty ones. - await self._api_auth() + try: + login_url = await retry_transport(budget, "introduce", self._introduce) + redirect = await self._handle_redirects(login_url) + await retry_transport( + budget, "login_page", lambda: self._open_login_page(redirect) + ) + url = await self._login() + await self._get_token(url) + await retry_transport(budget, "api_auth", self._api_auth) + except _NoAuthNeeded: + # The authorize page already carried the OAuth tokens (a still-valid + # SSO cookie), so the login steps are skipped -- but cognito_token is + # minted ONLY by _api_auth and connection.py needs it for every API + # call. Run it so this path completes with usable auth headers + # instead of empty ones. + await retry_transport(budget, "api_auth", self._api_auth) + finally: + self._retry_budget = None # Login complete: clear the phase so a LATER non-auth failure (e.g. a poll) is # not mis-attributed to the last auth step. self._current_phase = "" diff --git a/custom_components/addhon/client/transport/connection.py b/custom_components/addhon/client/transport/connection.py index 604338d..5a21e06 100644 --- a/custom_components/addhon/client/transport/connection.py +++ b/custom_components/addhon/client/transport/connection.py @@ -21,20 +21,29 @@ import aiohttp from ...error_codes import DECODE_ERROR +from ..budget import AUTH_FULL, AUTH_REFRESH, MFA_RESUME +from ..budget import CONNECT_TIMEOUT as _CONNECT_TIMEOUT +from ..budget import SOCK_READ_TIMEOUT as _SOCK_READ_TIMEOUT +from ..budget import TOTAL_TIMEOUT as _TOTAL_TIMEOUT +from ..budget import budgeted as _budgeted +from ..phase import PhaseTracker, phase from .auth import HonAuth, NativeAuthError from .device import HonDevice from .headers import build_auth_headers _LOGGER = logging.getLogger(__name__) -# Per-request HTTP timeouts on the session WE own. Without them aiohttp defaults to -# a 300s total, so a dead/blocked endpoint (e.g. api-iot.he.services or AWS IoT -# unreachable on the user's network) only failed when the 60s dedicated-loop cap -# fired, as an opaque message-less timeout (issue #30). These bound each request -# well under that cap, so a stuck endpoint fails fast and attributable. -_CONNECT_TIMEOUT = 10 # TCP connect + TLS handshake to one endpoint -_TOTAL_TIMEOUT = 30 # whole request incl. response read -_SOCK_READ_TIMEOUT = 20 # gap between received chunks +# The per-request HTTP timeouts now live in client/budget.py, which derives the +# per-phase budgets from them: a budget must never be computed from a number that +# someone can change in another file (issue #76). Re-exported under the original +# private names so this module reads as before. `_budgeted` comes from there too, so +# the session and the transport cannot drift apart on the conversion rule. +# +# EVERY auth scope below passes `suspends_caller=True`. The sign-in is LAZY: it starts +# inside whatever request happened to need a token, so its budget is nested inside a +# CALLER's budget that is deliberately smaller (a single POST is worth 40s, a +# nine-hop login 184s). Without the suspension the outer scope always fired first and +# the login was reported as "load_appliances timed out" -- issue #76 itself. class HonConnection: @@ -48,12 +57,17 @@ def __init__( mobile_id: str = "", refresh_token: str = "", auth_trace: Any = None, + phase_tracker: PhaseTracker | None = None, ) -> None: self._email = email self._password = password self._device = HonDevice(mobile_id) self._refresh_token = refresh_token self._auth_trace = auth_trace + # Hierarchical-phase mirror shared with the session (client/phase.py). It lives + # on the CONNECTION (a stable owner) and not on HonAuth, which create() replaces + # on every re-login. + self._phase_tracker = phase_tracker or PhaseTracker() self._owns_session = session is None self._session = session self._auth: HonAuth | None = None @@ -113,6 +127,7 @@ async def create(self) -> "HonConnection": self._password, self._device, auth_trace=self._auth_trace, + phase_tracker=self._phase_tracker, ) except BaseException: # We just created (and own) the ClientSession; if anything after that fails @@ -145,11 +160,21 @@ def _need_auth() -> bool: # refresh (token endpoint outage, consumed token). Bumping the gen # anyway would make a concurrent 401-retry sibling believe a fresh # token exists and SKIP its own refresh, reusing stale tokens. - if await self.auth.refresh(self._refresh_token): + # + # The phase scope + budget are HERE, not inside HonAuth: this is the + # lazy sign-in that #76 mis-attributed. Nested under whatever the + # caller is doing, so the phase reads e.g. + # "load_appliances/auth/refresh" -> ADDHON-406, not ADDHON-400. + with phase("auth/refresh", self._phase_tracker): + async with _budgeted(AUTH_REFRESH, suspends_caller=True): + refreshed = await self.auth.refresh(self._refresh_token) + if refreshed: self._refresh_token = self.auth.refresh_token self._refresh_gen += 1 if _need_auth(): - await self.auth.authenticate() + with phase("auth", self._phase_tracker): + async with _budgeted(AUTH_FULL, suspends_caller=True): + await self.auth.authenticate() self._refresh_token = self.auth.refresh_token self._refresh_gen += 1 return build_auth_headers(self.auth.cognito_token, self.auth.id_token, headers) @@ -176,7 +201,10 @@ async def _refresh_after_rejection(self, gen_at_send: int) -> None: # returns False leaving the stale tokens in place. Bumping regardless would # let a concurrent sibling skip its own refresh and reuse tokens that were # never actually rotated -- guaranteeing its next request 401s too. - if await self.auth.refresh(self._refresh_token): + with phase("auth/refresh", self._phase_tracker): + async with _budgeted(AUTH_REFRESH, suspends_caller=True): + refreshed = await self.auth.refresh(self._refresh_token) + if refreshed: self._refresh_token = self.auth.refresh_token self._refresh_gen += 1 @@ -204,8 +232,15 @@ async def _reauth_after_rejection(self, gen_at_send: int) -> None: raise self._reauth_error return # a sibling already re-authenticated; reuse its fresh tokens try: - await self.create() - await self.auth.authenticate() + # Budget INSIDE the try: the expiry is converted to a coded error here, + # so the `except BaseException` below caches it in _reauth_error exactly + # like any other failure. Without that, the siblings of a burst would + # each fire their own login -- the multiple-OTP scenario this + # single-flight exists to prevent. + with phase("auth", self._phase_tracker): + async with _budgeted(AUTH_FULL, suspends_caller=True): + await self.create() + await self.auth.authenticate() except asyncio.CancelledError: # A cancellation is specific to THIS task, not a shared auth failure: # caching it in _reauth_error would re-raise it into sibling requests @@ -332,12 +367,23 @@ async def post(self, *args: Any, **kwargs: Any) -> AsyncIterator[aiohttp.ClientR async def submit_mfa_code(self, context: Any, code: str) -> None: """Resume a paused 2FA login: verify the OTP on the auth, then adopt the freshly minted tokens (so the rest of setup runs without re-authenticating).""" - await self.auth.submit_mfa_code(context, code) + with phase("auth/mfa_verify", self._phase_tracker): + async with _budgeted(MFA_RESUME, suspends_caller=True): + await self.auth.submit_mfa_code(context, code) self._refresh_token = self.auth.refresh_token self._refresh_gen += 1 async def resend_mfa_code(self, context: Any) -> None: - await self.auth.resend_mfa_code(context) + # The same scope its twin submit_mfa_code opens. Without it this was the ONE + # auth entry point reaching `HonAuth._phase()` with no `phase()` around it, so + # the cross-thread mirror stayed at "mfa_send" for the life of the client: every + # scope RESTORES the value it found on exit, and `_run_on_hon_loop` prefers the + # hierarchical mirror to the flat one, so a stale "mfa_send" SHIELDED the flat + # mirror that would have been accurate and collapsed every later expiry to the + # mute ADDHON-460. The config flow calls this on EVERY entry into the 2FA step, + # not only on a resend, so the leak was on the normal 2FA path. + with phase("auth/mfa_send", self._phase_tracker): + await self.auth.resend_mfa_code(context) async def close(self) -> None: if self._owns_session and self._session is not None: diff --git a/custom_components/addhon/client/transport/mqtt.py b/custom_components/addhon/client/transport/mqtt.py index 9aefc93..f2c0f78 100644 --- a/custom_components/addhon/client/transport/mqtt.py +++ b/custom_components/addhon/client/transport/mqtt.py @@ -202,15 +202,26 @@ def client(self) -> mqtt5.Client: return self._client def _set_setup_phase(self, phase: str) -> None: - """Record the setup phase on the parent session so a dedicated-loop 60s - timeout during the FIRST connect is attributed to the right MQTT step. Only - set from create() (not the watchdog reconnect, which runs after setup).""" + """Record the setup phase on the parent session so a setup watchdog expiring + during the FIRST connect is attributed to the right MQTT step. Only set from + create() (not the watchdog reconnect, which runs after setup).""" hon = self._hon if hon is not None: try: hon._setup_phase = phase except Exception: # pragma: no cover - defensive pass + try: + # The HIERARCHICAL mirror too (client/phase.py). `NativeHon.setup()` + # wraps this call in a `phase("mqtt_start")` scope for the MQTT_START + # budget, and that scope is what the cross-thread watchdog reads -- + # without the refinement the outer name would SHIELD the flat mirror + # above and cost the connect/subscribe distinction. `step()` only + # rewrites the mirror (no ContextVar push), and the enclosing scope + # restores it on exit, so a refinement cannot outlive the start. + hon._phase_tracker.step(phase) + except Exception: # pragma: no cover - defensive + pass async def create(self) -> "NativeMqttClient": try: diff --git a/custom_components/addhon/client/transport/retry.py b/custom_components/addhon/client/transport/retry.py new file mode 100644 index 0000000..0dd0a5f --- /dev/null +++ b/custom_components/addhon/client/transport/retry.py @@ -0,0 +1,115 @@ +# Copyright (C) 2026 tis24dev +# SPDX-License-Identifier: AGPL-3.0-or-later + +"""Retry for the IDEMPOTENT transport steps only (issue #76). + +The validation path had NO retry at all: the login is 9 sequential round-trips, so +the odds that at least one is hit by a transient blip are 9x those of a single +request -- and any one of them turned straight into a permanent user-facing error. +The only backoff that existed lived downstream, in the appliance poll. + +TWO RULES make this safe, and both are load-bearing: + +1. INCLUSION, never a decorator. Every retried step is wrapped explicitly at its + call site. A step that submits credentials, consumes a single-use hand-off URL, + mints a fresh MFA context, or spends a rotating refresh token must NEVER be + retried: a duplicate delivery there costs a second OTP email, an invalid session, + or a permanently burnt refresh token. The list of what is wrapped (and why the + rest is not) is in `HonAuth.authenticate`. +2. A SHARED budget with a deadline gate. The extra attempts belong to the whole + login, not to each step, so the added worst case is bounded and computable: + `RETRY_MAX_EXTRA * (TOTAL_TIMEOUT + RETRY_DELAY)`. The gate refuses a retry that + the remaining time cannot absorb, so the retry can never be the reason the phase + budget expires. That accounting is mirrored in `client/budget.py::AUTH_FULL`. + The deadline MUST be the one really in force -- `budget.current_deadline()`, read + from the innermost open scope. Rebuilding it from a constant made the gate + unfalsifiable: it compared against a deadline nobody enforced, allowed every + retry, and the retries then spent a shorter, real budget. + +Fixed delay, never exponential: a constant delay is the only one whose worst case is +known in advance, which is exactly what the budget needs. +""" +from __future__ import annotations + +import asyncio +import logging +import time +from collections.abc import Awaitable, Callable +from typing import TypeVar + +from ..budget import RETRY_DELAY, RETRY_MAX_EXTRA, TOTAL_TIMEOUT +from ...error_codes import ( + CONNECTION_REFUSED, + DNS_FAILURE, + LOOP_TIMEOUT, + NETWORK_TIMEOUT, + classify, +) + +_LOGGER = logging.getLogger(__name__) + +T = TypeVar("T") + +# We retry ONLY when nothing was received: a timeout, a name that did not resolve, a +# connection that was refused/reset. A RECEIVED HTTP response is never retried here -- +# 5xx/429 already have the appliance-layer backoff and would be counted twice, 401/403 +# are a rejection, and a TLS failure does not fix itself in two seconds. Single source +# of truth so the predicate cannot drift as `classify` gains structural branches. +RETRYABLE_CODES = frozenset({NETWORK_TIMEOUT, DNS_FAILURE, CONNECTION_REFUSED, LOOP_TIMEOUT}) + + +class RetryBudget: + """Extra attempts shared by every retried step of ONE login, plus a deadline.""" + + def __init__( + self, extra: int = RETRY_MAX_EXTRA, deadline: float | None = None + ) -> None: + self.extra = extra + # Absolute time.monotonic() at which the enclosing phase budget expires, as + # reported by `budget.current_deadline()` -- the tightest scope actually open, + # never a number re-derived from a constant. None (direct use / unit tests) + # leaves only the counter: acceptable there, NOT in production, where a retry + # without the gate could be the very thing that burns the budget. + self.deadline = deadline + + def allows(self) -> bool: + if self.extra <= 0: + return False + if self.deadline is None: + return True + return self.deadline - time.monotonic() >= TOTAL_TIMEOUT + RETRY_DELAY + + def consume(self) -> None: + self.extra -= 1 + + +def _is_retryable(err: BaseException) -> bool: + return classify(err) in RETRYABLE_CODES + + +async def retry_transport( + budget: RetryBudget | None, + endpoint: str, + factory: Callable[[], Awaitable[T]], +) -> T: + """Await `factory()`, retrying a no-response transport failure after a fixed delay. + + `endpoint` is a label from the closed vocabulary in `auth_diagnostics` and is only + used for logging (no URL, no identity). + """ + attempt = 1 + while True: + try: + return await factory() + except Exception as err: # noqa: BLE001 - re-raised unless clearly retryable + if budget is None or not _is_retryable(err) or not budget.allows(): + raise + budget.consume() + _LOGGER.warning( + "addhOn: transient transport failure on %s (attempt %d), retrying in %ss", + endpoint, + attempt, + RETRY_DELAY, + ) + attempt += 1 + await asyncio.sleep(RETRY_DELAY) diff --git a/custom_components/addhon/config_flow.py b/custom_components/addhon/config_flow.py index e209be2..eb018c5 100644 --- a/custom_components/addhon/config_flow.py +++ b/custom_components/addhon/config_flow.py @@ -29,6 +29,7 @@ UNKNOWN, HonErrorCode, classify, + error_detail, ) from .hon_client import HonClient, _requires_reauth @@ -133,12 +134,19 @@ async def validate_input( except ImportError as err: code = classify(err) client.emit_auth_diagnostics(code, "setup", "unexpected") - _LOGGER.error("Validation failed [%s]: required dependency not installed: %s", code.label, err) + _LOGGER.error( + "Validation failed [%s]: required dependency not installed: %s", + code.label, error_detail(err), + ) raise CannotConnect(code) from err except Exception as err: code = classify(err) client.emit_auth_diagnostics(code, "setup", "unexpected") - _LOGGER.error("Validation failed [%s]: %s", code.label, err) + # error_detail() strips a leading "ADDHON-NNN: ": a HonCodedError already + # renders as "ADDHON-400: reason", so printing the label too produced + # "Validation failed [ADDHON-400]: ADDHON-400: ..." -- the doubled line + # reported in #76, which also crowds out the detail that would help. + _LOGGER.error("Validation failed [%s]: %s", code.label, error_detail(err)) if _requires_reauth(err): raise InvalidAuth(code) from err raise CannotConnect(code) from err @@ -163,7 +171,10 @@ async def validate_input( client.emit_auth_diagnostics( code, "appliance_list", "appliance_list_failed" ) - _LOGGER.error("Validation failed [%s] fetching appliances: %s", code.label, err) + _LOGGER.error( + "Validation failed [%s] fetching appliances: %s", + code.label, error_detail(err), + ) if _requires_reauth(err): raise InvalidAuth(code) from err raise CannotConnect(code) from err diff --git a/custom_components/addhon/diagnostics.py b/custom_components/addhon/diagnostics.py index 3cb5428..78a1739 100644 --- a/custom_components/addhon/diagnostics.py +++ b/custom_components/addhon/diagnostics.py @@ -9,6 +9,14 @@ by async_get_device_diagnostics below); no custom button is needed. Per appliance the dump carries, beyond the bare key list it used to emit: + * `model_attributes` - the cloud CATALOGUE metadata for the model + (`applianceModel.attributes`): `zones`, `seriesVersion`, + `doorNumber`, `vtRoom1`/`vtRoom2`, ... It answers what the + appliance IS, which the shadow cannot: the hOn app decides + which fridge zones exist from `zones`.split("|"), not from + which `tempZ*` keys the shadow carries. Without it, a + zone-indexing report (issue #75) needs a round trip to the + reporter before it can even be diagnosed. * `attributes` - the attribute VALUES (telemetry/state), recursively redacted; * `commands` - the writable schema per command param: value + enum + min/max/ step + typology, so a maintainer sees the real ranges/options; @@ -176,6 +184,13 @@ # future-capability bounds it announces itself rather than truncating silently. _ENTITY_MAX_PER_DOMAIN = 80 +# Bound on materialising a RANGE's grid into the dump (see `_param_schema`). Only a +# grid this small is enumerated, so the never-enumerate-a-setpoint rule stands. 8 +# covers every few-position control observed so far -- a 0/1 lock or tone, a 0..2 +# panel light, a 0..4 aroma -- and eight short numeric strings are noise next to the +# blocks around them. +_RANGE_MAX_MATERIALISED = 8 + _FUTURE_MAX_ENTRIES = 40 _FUTURE_MAX_VALUES = 20 # A separate CHARACTER bound. An unhandled state value is one scalar, so it needs a @@ -258,8 +273,9 @@ def _param_value(param): def _param_schema(param) -> dict: - """Schema of one command parameter: value + metadata, plus range (min/max/step) - for a range param OR enum as a fallback only when the param is not a range.""" + """Schema of one command parameter: value + metadata, plus range (min/max/step, + and the materialised grid when it is small enough) for a range param OR enum as + a fallback only when the param is not a range.""" schema: dict = { "value": _param_value(param), "typology": getattr(param, "typology", None), @@ -274,7 +290,27 @@ def _param_schema(param) -> dict: # meaningful for enum/fixed params, where param_range() returns None. rng = param_range(param) if rng is not None: + low, high, step = rng schema["min"], schema["max"], schema["step"] = rng + # ...and, for a SMALL grid only, the values it actually materialises. + # + # min/max/step cannot answer the question a missing 0/1 control raises. + # param_range() casts through float(), so a schema spelling its bounds + # "0"/"1" and one spelling them "0.0"/"1.0" print IDENTICALLY here, while + # `.values` yields ['0', '1'] for the first and ['0.0', '1.0'] for the + # second -- and the capability gates compare exactly those STRINGS + # (air_purifier.supports_lock is `lock_values == {"0", "1"}`). A single + # decimal-spelled minimumValue or incrementValue therefore removes a + # control, and until now the deciding input appeared nowhere in the dump. + # + # The bound is what keeps the rule above intact: a real setpoint range is + # still never enumerated. The point count is computed ARITHMETICALLY, and + # param_range() has already guaranteed step > 0 and max >= min, so a + # 0..1400 step 100 grid is refused without `.values` ever being read. + # Emitted under its own key, never `enum`: this is the grid a range + # materialises, not an enumeration the device declares. + if (high - low) / step + 1 <= _RANGE_MAX_MATERIALISED: + schema["values"] = param_values(param) else: enum = param_values(param) if enum: @@ -282,6 +318,20 @@ def _param_schema(param) -> dict: return schema +def _model_attributes(appliance) -> dict: + """Cloud catalogue metadata for the MODEL, flattened to parName -> parValue. + + Read straight off the appliance (`applianceModel.attributes`, already + normalised by the engine), not off the coordinator entry: it is per-model + and immutable for the session, so it never belongs in the polled snapshot. + Returns {} for any appliance implementation that does not expose it. + """ + raw = getattr(appliance, "model_attributes", None) + if not isinstance(raw, Mapping): + return {} + return {str(name): value for name, value in raw.items()} + + def _command_schema(appliance) -> dict: """Per-command, per-parameter schema for every command the appliance exposes.""" commands = getattr(appliance, "commands", None) @@ -543,16 +593,18 @@ def _appliance_block( statistics = statistics if isinstance(statistics, Mapping) else {} commands = _command_schema(appliance) + model_attributes = _model_attributes(appliance) coverage = _coverage(app_type, attributes, statistics, appliance) future = _future_capabilities(app_type, attributes, appliance) _LOGGER.debug( - "Diagnostics debug: appliance id=%s name=%s type=%s attrs=%d commands=%d " - "unmapped_attrs=%d unmapped_params=%d", + "Diagnostics debug: appliance id=%s name=%s type=%s attrs=%d model_attrs=%d " + "commands=%d unmapped_attrs=%d unmapped_params=%d", redact_id(appliance_id), data.get("name"), app_type, len(attributes), + len(model_attributes), len(commands), len(coverage["attributes_unmapped"]), len(coverage["command_params_unmapped"]), @@ -565,6 +617,8 @@ def _appliance_block( "model": data.get("model"), "serial": _REDACTED, "mac": _REDACTED, + # Before `attributes` on purpose: what the model IS, then what it is doing. + "model_attributes": model_attributes, "attributes": dict(attributes), "commands": commands, "coverage": coverage, @@ -823,6 +877,13 @@ def _last_error(hass: HomeAssistant, entry: ConfigEntry) -> dict | None: "phase": getattr(client, "last_error_phase", None), "had_refresh_token": bool(getattr(client, "_refresh_token", "")), } + # Per-phase duration+outcome of the failed attempt (issue #76): without it a report + # cannot say WHICH phase burned the time, so no hypothesis about a timeout is + # falsifiable. Same leak-proof shape as the block above: phase names from a closed + # vocabulary, rounded seconds, and an outcome in {ok, error, timeout}. + ledger = getattr(client, "last_phase_ledger", None) + if ledger: + out["phase_ledger"] = ledger # 2FA summary only when the failure is in the MFA band (160-169) -- challenge_kind is # the enum "email"/None and can_resend is a bool; the MfaContext secrets are NEVER here. mfa = getattr(client, "last_mfa_summary", None) diff --git a/custom_components/addhon/error_codes.py b/custom_components/addhon/error_codes.py index 60be59f..1d448d6 100644 --- a/custom_components/addhon/error_codes.py +++ b/custom_components/addhon/error_codes.py @@ -25,8 +25,11 @@ import asyncio import concurrent.futures +import errno as _errno import json import re +import socket +import ssl from dataclasses import dataclass CODE_PREFIX = "ADDHON" @@ -160,6 +163,29 @@ def _reg( SERVER_ERROR = _reg(450, "server_error", "hOn server error") LOOP_TIMEOUT = _reg(460, "loop_timeout", "Setup timed out") DECODE_ERROR = _reg(470, "decode_error", "Unreadable server response") +# 405/406: a sign-in that runs out of time is NOT a rejection (requires_reauth=False). +# The login is lazy -- it starts inside the request that load_appliances issues -- so +# before these existed a slow sign-in was reported as ADDHON-400 "network timeout" +# (issue #76) or fell through to the mute ADDHON-460. The reason_en MUST keep the word +# "timeout": hon_client._is_retryable_server_error looks for that substring, which is +# what keeps a phase-timeout code retryable instead of reauth. 401/402 were deliberately +# NOT used: hon_client._is_auth_error matches the bare substrings "401"/"403", so a +# message that lost its carried code would turn a transient timeout into a reauth. +AUTH_TIMEOUT = _reg(405, "auth_timeout", "Timeout during hOn sign-in") +REFRESH_TIMEOUT = _reg(406, "refresh_timeout", "Timeout refreshing the hOn session") +# 480: the dedicated loop was torn down while a call was still in flight (an unload or +# a reload racing a poll/command). `HonClient._run_on_hon_loop` no longer waits under +# the lifecycle lock -- that wait made an unload queue behind the slowest in-flight +# call, minutes with the per-site caps -- so the teardown can now cancel the task under +# a waiter. What reaches the waiter is a bare, message-less +# concurrent.futures.CancelledError, which classify can only call ADDHON-999: the +# user's command fails with "Unknown error" and nothing says the client was shutting +# down. NOT reauth and NOT "timeout"-flavoured: nothing timed out and nothing was +# rejected, the call was simply abandoned, so the coordinator files a plain transient +# failure while the entry goes away. +CLIENT_SHUTDOWN = _reg( + 480, "client_shutdown", "hOn client shut down while the request was running", ui=False +) # 9xx - fallback UNKNOWN = _reg(999, "unknown", "Unknown error") @@ -202,14 +228,63 @@ def __init__( "connect": NETWORK_TIMEOUT, } +# Phases are now HIERARCHICAL ("load_appliances/auth/refresh", client/phase.py), so a +# lazy sign-in nested inside the appliance-list request can name itself instead of +# borrowing the caller's label. Per-SEGMENT table, scanned innermost-first: the deepest +# step that we recognise is the one that actually stalled. +_PHASE_TIMEOUT_SEGMENT: dict[str, HonErrorCode] = { + **_PHASE_TIMEOUT, + "auth": AUTH_TIMEOUT, + "refresh": REFRESH_TIMEOUT, + "subscribe": MQTT_SUBSCRIBE_TIMEOUT, + # The scope `NativeHon.setup()` opens around the MQTT start (its budget is + # MQTT_START, summed into SETUP_CAP). Coded as a CONNECT timeout because that is + # what the budget mostly pays for; the finer mqtt_connect/mqtt_subscribe split + # survives on the cross-thread mirror, which the MQTT layer keeps refining while + # the scope is open (transport/mqtt.py::_set_setup_phase). + "mqtt_start": MQTT_CONNECT_TIMEOUT, +} + +# Everything `phase_timeout_code` can return. `client/phase.py` needs it because a +# budget expiry reaches its scope ALREADY converted into a HonCodedError (the +# conversion has to happen inside the phase scope to name the innermost step), so +# without this set the ledger would file every expiry as a plain 'error'. +PHASE_TIMEOUT_CODES = frozenset({*_PHASE_TIMEOUT_SEGMENT.values(), LOOP_TIMEOUT}) + def phase_timeout_code(phase: str | None) -> HonErrorCode: - """Timeout code for a stalled setup phase (empty/unknown -> LOOP_TIMEOUT).""" + """Timeout code for a stalled setup phase (empty/unknown -> LOOP_TIMEOUT). + + Resolution, innermost wins: the exact flat name first (total backward + compatibility with the phases the MQTT layer and the legacy mirrors still + write), then each '/'-separated segment from the leaf outwards, then the + ``load_appliance*`` prefix rule, then LOOP_TIMEOUT. + """ if not phase: return LOOP_TIMEOUT + exact = _PHASE_TIMEOUT.get(phase) + if exact is not None: + return exact + for segment in reversed(phase.split("/")): + code = _PHASE_TIMEOUT_SEGMENT.get(segment) + if code is not None: + return code if phase.startswith("load_appliance"): return NETWORK_TIMEOUT - return _PHASE_TIMEOUT.get(phase, LOOP_TIMEOUT) + return LOOP_TIMEOUT + + +# A HonCodedError renders as "ADDHON-400: reason" all by itself (see __str__), so a log +# line that prepends the label again reads "Validation failed [ADDHON-400]: ADDHON-400: +# Network timeout contacting hOn" -- the doubled string reported in #76, which also +# occupies the room the useful detail would need. Anchored at the START only: a message +# that merely cites a code mid-sentence is left alone. +_CODE_PREFIX_RE = re.compile(rf"^{CODE_PREFIX}-\d+:\s*") + + +def error_detail(err: BaseException) -> str: + """`str(err)` without a leading ``ADDHON-NNN:`` prefix (never empty).""" + return _CODE_PREFIX_RE.sub("", str(err), count=1).strip() or type(err).__name__ def _is_timeout(err: BaseException) -> bool: @@ -218,6 +293,57 @@ def _is_timeout(err: BaseException) -> bool: ) +# Errnos that all mean "the peer/route did not accept the connection". Kept separate +# from the OSError subclasses because a raw OSError carries only the number. +_REFUSED_ERRNOS = frozenset( + { + _errno.ECONNREFUSED, + _errno.ECONNRESET, + _errno.ECONNABORTED, + _errno.EHOSTUNREACH, + _errno.ENETUNREACH, + _errno.ENETDOWN, + _errno.EPIPE, + } +) + + +def _structural_transport_code(err: BaseException) -> HonErrorCode | None: + """TLS vs DNS vs refused decided by TYPE/errno, not by the message text. + + aiohttp cannot be imported here (pure module, and it is not even installed in the + offline test environment), so this uses the stdlib types the aiohttp errors DERIVE + from -- `ssl.SSLError` covers ClientConnectorCertificateError/SSLError -- plus the + documented `.os_error` attribute that `ClientConnectorError` exposes for the + underlying OSError. That is what tells a name-resolution failure apart from a + refusal without reading "Name or service not known" out of a string. + """ + candidate: BaseException | None = err + # `.os_error` nests at most one level in aiohttp; the bound is defensive. + for _ in range(3): + if candidate is None: + return None + if isinstance(candidate, ssl.SSLError): + return TLS_FAILURE + if isinstance(candidate, socket.gaierror): + return DNS_FAILURE + if isinstance( + candidate, + ( + ConnectionRefusedError, + ConnectionResetError, + ConnectionAbortedError, + BrokenPipeError, + ), + ): + return CONNECTION_REFUSED + if getattr(candidate, "errno", None) in _REFUSED_ERRNOS: + return CONNECTION_REFUSED + nested = getattr(candidate, "os_error", None) + candidate = nested if isinstance(nested, BaseException) else None + return None + + def classify(err: BaseException, *, phase: str | None = None) -> HonErrorCode: """Map any exception to a stable :class:`HonErrorCode`. @@ -237,6 +363,20 @@ def classify(err: BaseException, *, phase: str | None = None) -> HonErrorCode: if isinstance(err, (json.JSONDecodeError, UnicodeDecodeError)): return DECODE_ERROR + # A RECEIVED HTTP response carries its status as a field (aiohttp's + # ClientResponseError, raised by our raise_for_status() call sites). Reading it + # beats grepping the message for a number. Any other value FALLS THROUGH on + # purpose: a ContentTypeError with status 200 must stay a decode problem, and an + # exception of ours that happens to own a `status` attribute must not be + # reclassified by accident. 401/403 do not return here -- they feed the existing + # rejection cascade below, which also names the auth STEP. + status = getattr(err, "status", None) + if isinstance(status, int) and not isinstance(status, bool): + if status == 429: + return RATE_LIMITED + if 500 <= status <= 599: + return SERVER_ERROR + name = type(err).__name__.lower() class_names = " ".join(cls.__name__.lower() for cls in type(err).__mro__) text = str(err).lower() @@ -255,7 +395,8 @@ def classify(err: BaseException, *, phase: str | None = None) -> HonErrorCode: # converted to MQTT polling-only retries. Retryable 429/5xx/timeouts above retain # priority, including NativeAuthError("api_auth: status 503"). auth_rejected = ( - "unauthorized" in hay + status in (401, 403) + or "unauthorized" in hay or any( marker in hay for marker in ( @@ -287,6 +428,15 @@ def classify(err: BaseException, *, phase: str | None = None) -> HonErrorCode: return AUTH_LOGIN return INVALID_CREDENTIALS + # Structural transport (TYPE/errno) BEFORE the textual TLS/DNS/refused rules, so a + # real ssl.SSLError or a gaierror wrapped in ClientConnectorError.os_error is named + # correctly even when its message says nothing recognisable. Deliberately AFTER + # rate-limit/5xx, timeouts and the explicit rejection markers: those decide WHETHER + # this is a transport fault at all, this only decides WHICH one. + structural = _structural_transport_code(err) + if structural is not None: + return structural + # TLS/certificate: key off the exception CLASS NAME or explicit certificate text, # NOT a bare "ssl" in the message. aiohttp's ClientConnectorError __str__ ALWAYS # contains "ssl:default" for ANY HTTPS connect failure (a plain outage, not a TLS @@ -313,7 +463,7 @@ def classify(err: BaseException, *, phase: str | None = None) -> HonErrorCode: or "network is unreachable" in text ): return CONNECTION_REFUSED - if "clientpayloaderror" in class_names: + if "clientpayloaderror" in class_names or "contenttypeerror" in class_names: return DECODE_ERROR if "decode error" in hay: return DECODE_ERROR @@ -359,3 +509,39 @@ def classify(err: BaseException, *, phase: str | None = None) -> HonErrorCode: if _is_auth_error(err): return INVALID_CREDENTIALS return UNKNOWN + + +def representative_failure( + failures: list[tuple[str, Exception]] +) -> tuple[HonErrorCode, Exception | None]: + """Pick a representative (code, error) from a batch of per-appliance failures (CR#6). + + The all-failed (and first-poll) paths used to raise a bare RuntimeError, which + classify() maps to UNKNOWN (ADDHON-999) -- losing the real cause from the logs, + the UpdateFailed message and Download Diagnostics. This surfaces a MEANINGFUL, + NON-AUTH code instead: deterministically, the FIRST failure (in poll order) whose + classify() is neither UNKNOWN nor a reauth code; if none qualifies, fall back to + APPLIANCE_LOAD_FAILED (ADDHON-220) paired with the first error. + + Rejecting reauth codes is what keeps routing correct. Every error here already + passed the non-auth gate (_requires_reauth was False at the call site), but + classify() is substring-based and could still name an auth code (e.g. a message + that merely contains "login") -- surfacing it would flip the transient + UpdateFailed into a reauth (ConfigEntryAuthFailed). APPLIANCE_LOAD_FAILED is + requires_reauth=False, so the fallback stays non-auth too. + + Lives HERE, not in `hon_client`, because the setup path needs the same rule: the + session cannot import the client (the client imports the session), and a private + copy would be the exact "the cause is lost again" drift this function exists to + stop. + """ + chosen: Exception | None = None # the first failure, kept as the fallback cause + for _name, err in failures: + if chosen is None: + chosen = err + code = classify(err) + if code is not UNKNOWN and not code.requires_reauth: + return code, err + # No meaningful non-auth code found (or -- defensively -- an empty list, which the + # gated call sites never pass): fall back to APPLIANCE_LOAD_FAILED, NEVER UNKNOWN. + return APPLIANCE_LOAD_FAILED, chosen diff --git a/custom_components/addhon/hon_client.py b/custom_components/addhon/hon_client.py index d5bf5bb..3db7fb1 100644 --- a/custom_components/addhon/hon_client.py +++ b/custom_components/addhon/hon_client.py @@ -8,24 +8,33 @@ import concurrent.futures import logging import threading +import time from typing import Any +from .client import budget from .client.auth_diagnostics import ( AuthDiagnosticTrace, classify_failure_reason, ) +# Aliased: `_run_on_hon_loop` binds a LOCAL named `phase` for the attribution it +# samples, and shadowing the scope factory there would be a trap for the next edit. +from .client.phase import phase as phase_scope from .command_dispatch import CommandDispatcher, CommandPatch from .debug_utils import debug_key_sample, redact_email, redact_id, redact_mac from .error_codes import ( - APPLIANCE_LOAD_FAILED, + CLIENT_SHUTDOWN, MFA_REQUIRED, - UNKNOWN, HonCodedError, HonErrorCode, classify, + error_detail, is_rate_limited_text, is_server_failure_text, phase_timeout_code, + # Moved to error_codes so the SETUP path can apply the same rule (the session + # cannot import this module). Kept under its original private name: it is the + # name every call site and its test already use. + representative_failure as _representative_failure, ) _LOGGER = logging.getLogger(__name__) @@ -267,37 +276,6 @@ def _must_propagate(err: BaseException) -> bool: return _requires_reauth(err) or _is_retryable_server_error(err) -def _representative_failure( - failures: list[tuple[str, Exception]] -) -> tuple[HonErrorCode, Exception | None]: - """Pick a representative (code, error) from per-appliance update failures (CR#6). - - The all-failed (and first-poll) paths used to raise a bare RuntimeError, which - classify() maps to UNKNOWN (ADDHON-999) -- losing the real cause from the logs, - the UpdateFailed message and Download Diagnostics. This surfaces a MEANINGFUL, - NON-AUTH code instead: deterministically, the FIRST failure (in poll order) whose - classify() is neither UNKNOWN nor a reauth code; if none qualifies, fall back to - APPLIANCE_LOAD_FAILED (ADDHON-220) paired with the first error. - - Rejecting reauth codes is what keeps routing correct. Every error here already - passed the non-auth gate (_requires_reauth was False at the call site), but - classify() is substring-based and could still name an auth code (e.g. a message - that merely contains "login") -- surfacing it would flip the transient - UpdateFailed into a reauth (ConfigEntryAuthFailed). APPLIANCE_LOAD_FAILED is - requires_reauth=False, so the fallback stays non-auth too. - """ - chosen: Exception | None = None # the first failure, kept as the fallback cause - for _name, err in failures: - if chosen is None: - chosen = err - code = classify(err) - if code is not UNKNOWN and not code.requires_reauth: - return code, err - # No meaningful non-auth code found (or -- defensively -- an empty list, which the - # two gated call sites never pass): fall back to APPLIANCE_LOAD_FAILED, NEVER UNKNOWN. - return APPLIANCE_LOAD_FAILED, chosen - - class HonClient: """Manages the connection to the Haier hOn APIs via the native client. @@ -337,6 +315,10 @@ def __init__( # leak-proof 2FA summary, surfaced in the downloadable diagnostics for triage. self.last_error_phase: str | None = None self.last_mfa_summary: dict | None = None + # Per-phase duration+outcome of the last setup attempt (leak-proof primitives: + # phase names, rounded seconds, ok/error/timeout). This is the artefact that + # makes a report like #76 diagnosable without a live probe. + self.last_phase_ledger: list[dict] | None = None self._hon_instance = None self._api = None self._hon_loop: asyncio.AbstractEventLoop | None = None @@ -369,11 +351,26 @@ def _start_hon_loop(self) -> None: self._hon_thread.start() _LOGGER.debug("Dedicated hOn loop started on thread '%s'", self._hon_thread.name) - def _run_on_hon_loop(self, coro) -> Any: + def _run_on_hon_loop(self, coro, timeout: float | None = None) -> Any: """Run a coroutine on the dedicated loop and wait for the result. Call only from a non-loop thread (e.g. HA's executor). + + `timeout` is the WATCHDOG for this call site, not a budget: every phase inside + bounds itself (client/budget.py) and converts its own expiry into an attributed + coded error. A single constant used to cover the login, the appliance list, the + per-appliance loads and a one-appliance poll alike -- workloads an order of + magnitude apart -- which is why it fired first and produced the opaque + ADDHON-400 of #76. Omitted -> the legacy 60s. """ + cap = self._RUN_TIMEOUT if timeout is None else timeout + # The lock covers the LIFECYCLE read (which loop/thread we are talking to) and + # the scheduling, NOT the wait. Waiting under it made every caller of + # `close_sync`/`setup_sync` queue behind the SLOWEST in-flight call, and the + # caps this file now passes are minutes rather than the legacy 60s: a stalled + # poll (APPLIANCE_POLL) would have blocked an unload/reload for ~5 minutes and + # Home Assistant would report the unload as slow. Nothing in the wait touches + # the lifecycle fields, so it does not belong inside the lock. with self._lifecycle_lock: loop = self._hon_loop if loop is None or not loop.is_running(): @@ -426,47 +423,123 @@ def _copy_result(done_task: asyncio.Task) -> None: coro.close() raise - try: - return future.result(timeout=self._RUN_TIMEOUT) - except concurrent.futures.TimeoutError as timeout_err: - drain_future: concurrent.futures.Future = concurrent.futures.Future() + started = time.monotonic() + try: + return future.result(timeout=cap) + except concurrent.futures.CancelledError as cancelled: + # TEARDOWN, not a timeout: an unload/reload stopped the dedicated loop while + # this call was in flight, so `_cancel_pending_tasks` cancelled the task and + # `_copy_result` cancelled the future under us. Reachable because the wait + # above is deliberately NOT under the lifecycle lock -- holding it made every + # unload queue behind the SLOWEST in-flight call, minutes with these caps. + # + # Without this clause the caller gets a bare, message-less CancelledError + # that `classify` can only map to ADDHON-999 (and `representative_failure` + # to ADDHON-220): the user's command or poll fails with "Unknown error" and + # no line anywhere says the client was shutting down -- precisely the kind of + # unfalsifiable report #76 was filed as. It is NOT re-raised as a + # cancellation because it is not one: THIS thread is a plain executor thread + # that was never cancelled (`concurrent.futures.CancelledError` has been a + # separate, ordinary Exception from `asyncio.CancelledError` since 3.8, so + # nothing here swallows a real task cancellation). Waiting for the in-flight + # call instead is the slow unload this shape exists to avoid. + raise HonCodedError( + CLIENT_SHUTDOWN, "The hOn client was shut down while the call was running" + ) from cancelled + except concurrent.futures.TimeoutError as timeout_err: + if future.done(): + # NOT our cap: since Python 3.11 `concurrent.futures.TimeoutError IS + # asyncio.TimeoutError IS TimeoutError`, so a BARE TimeoutError raised BY + # the coroutine (an aiohttp per-request timeout that no budgeted scope + # converted -- e.g. the first-poll `load_commands` rehydration) arrives + # here as the very type the cap raises. Telling them apart by TYPE is + # impossible; by STATE it is exact: on a real cap expiry the future is + # still PENDING, while a coroutine that raised has already FINISHED. + # Without this, a fault that had a name was logged as "watchdog fired + # after 0.0s" and delivered as the mute ADDHON-460 instead of its own + # code. Re-raise it untouched (or hand back a result that landed in the + # microsecond race) and let the caller classify it. + return future.result() + # Phase attribution, read BEFORE anything is cancelled. The + # hierarchical mirror (client/phase.py) names the innermost step + # actually running -- a lazy sign-in inside the appliance-list request + # reads "load_appliances/auth/..." and maps to ADDHON-405/406 instead + # of borrowing the caller's label and producing the misleading + # ADDHON-400 of #76. It MUST be sampled here: cancelling the task + # unwinds the phase scopes, and every `phase()` restores the mirror on + # the way out, so a read taken after the drain finds "" and silently + # falls back to the flat mirror -- which is the label that was wrong in + # the first place. Flat mirror as the fallback (the MQTT layer still + # writes only that one). ("" -> LOOP_TIMEOUT.) + phase = ( + getattr(self._hon_instance, "current_phase", "") + or getattr(self._hon_instance, "_setup_phase", "") + or "" + ) + drain_future: concurrent.futures.Future = concurrent.futures.Future() + # The real cause, recovered from the task we are about to cancel. Without + # it, a coroutine that failed for a NAMED reason a moment after the cap + # expired was reported as a synthetic, message-less timeout -- which is + # what made every hypothesis about #76 unfalsifiable on a real install. + drained: dict[str, BaseException] = {} + + def _cancel_and_drain() -> None: + task = task_holder.get("task") + if task is None: + future.cancel() + if not drain_future.done(): + drain_future.set_result(None) + return - def _cancel_and_drain() -> None: - task = task_holder.get("task") - if task is None: - future.cancel() - if not drain_future.done(): - drain_future.set_result(None) - return + # Lost race: the task finished (with an exception) between the cap + # expiring and this callback running. Take its error before cancel(). + if task.done() and not task.cancelled(): + done_err = task.exception() + if done_err is not None: + drained["error"] = done_err - async def _drain_task() -> None: - task.cancel() - try: - await task - except asyncio.CancelledError: - pass - except Exception as err: - _LOGGER.debug("Error while cancelling hOn task: %s", err) - if not future.done(): - future.cancel() - if not drain_future.done(): - drain_future.set_result(None) + async def _drain_task() -> None: + task.cancel() + try: + await task + except asyncio.CancelledError: + pass + except Exception as err: + drained["error"] = err + if not future.done(): + future.cancel() + if not drain_future.done(): + drain_future.set_result(None) - loop.create_task(_drain_task()) + loop.create_task(_drain_task()) - try: - loop.call_soon_threadsafe(_cancel_and_drain) - drain_future.result(timeout=self._CANCEL_TIMEOUT) - except Exception as err: - _LOGGER.debug("Timeout while cancelling hOn task: %s", err) - # The bare concurrent.futures.TimeoutError has no message and the - # cancelled coroutine's own exception is gone, so re-raise it as a - # phase-attributed coded error: the dedicated loop runs setup() on the - # hOn session, which records where it stalled (auth / appliance list / - # MQTT) in _setup_phase. This is what turns the #30 "spins then - # cannot_connect" into a precise ADDHON-NNN. (phase "" -> LOOP_TIMEOUT.) - phase = getattr(self._hon_instance, "_setup_phase", "") or "" - raise HonCodedError(phase_timeout_code(phase), phase=phase) from timeout_err + try: + loop.call_soon_threadsafe(_cancel_and_drain) + drain_future.result(timeout=self._CANCEL_TIMEOUT) + except Exception as err: + _LOGGER.debug("Timeout while cancelling hOn task: %s", err) + elapsed = round(time.monotonic() - started, 1) + original = drained.get("error") + _LOGGER.error( + "hOn loop watchdog fired after %ss (phase=%s, cause=%s) [%s]", + elapsed, + phase or "?", + type(original).__name__ if original is not None else "stall", + getattr(self._hon_instance, "phase_summary", "") or "no ledger", + ) + if original is not None: + # A 2FA challenge that landed across the cap must stay NAKED: wrapping + # it in a HonCodedError would break the interactive resume branch. + from .client.transport.auth import MFAChallengeRequired + + if isinstance(original, MFAChallengeRequired): + raise original + raise HonCodedError( + classify(original, phase=phase), phase=phase + ) from original + # Genuine stall: the drain produced only a cancellation, so the phase + # code is all we know. + raise HonCodedError(phase_timeout_code(phase), phase=phase) from timeout_err def _cancel_pending_tasks(self, loop: asyncio.AbstractEventLoop) -> None: """Cancel leftover tasks before stopping the dedicated loop.""" @@ -518,7 +591,10 @@ def _close_sync(self) -> None: if hon is not None: try: - self._run_on_hon_loop(hon.__aexit__(None, None, None)) + # Teardown must never wait as long as a setup. + self._run_on_hon_loop( + hon.__aexit__(None, None, None), budget.CLOSE + ) except Exception as err: _LOGGER.debug("Error closing hOn session: %s", err) self._stop_hon_loop() @@ -543,6 +619,7 @@ def setup_sync(self) -> None: self.last_error_code = None self.last_error_phase = None self.last_mfa_summary = None + self.last_phase_ledger = None try: if self._hon_loop is None or not self._hon_loop.is_running(): self._start_hon_loop() @@ -557,8 +634,13 @@ def setup_sync(self) -> None: ) _LOGGER.debug("Hon instance created") - # Login + aiohttp session init, on the dedicated loop - self._api = self._run_on_hon_loop(self._hon_instance.__aenter__()) + # Login + aiohttp session init, on the dedicated loop. The validation + # path (minimal, no MQTT, no per-appliance loads) gets the tighter of + # the two watchdogs: a human is waiting on the config-flow form. + self._api = self._run_on_hon_loop( + self._hon_instance.__aenter__(), + budget.VALIDATION_CAP if self._validation else budget.SETUP_CAP, + ) _LOGGER.info("Connection to hOn succeeded for %s", redact_email(self._email)) # Re-apply the realtime notify callback to the freshly built session # (rebuilt on every setup/re-auth with _notify_function=None); @@ -586,11 +668,26 @@ def setup_sync(self) -> None: _LOGGER.info("hOn login needs 2FA verification [%s]", MFA_REQUIRED.label) raise except Exception as err: - self.last_error_phase = getattr(self._hon_instance, "auth_phase", "") or None + # Prefer the phase the error CARRIES (hierarchical, recorded where it + # was raised) over the auth mirror, which only knows the login steps. + self.last_error_phase = ( + getattr(err, "phase", None) + or getattr(self._hon_instance, "auth_phase", "") + or None + ) self.last_error_code = classify(err, phase=self.last_error_phase) + self.last_phase_ledger = ( + getattr(self._hon_instance, "phase_ledger", None) or None + ) _LOGGER.error( - "hOn setup failed [%s] (phase=%s): %s", - self.last_error_code.label, self.last_error_phase or "?", err, + # error_detail() strips a leading "ADDHON-NNN: " so the code is not + # printed twice ("Validation failed [ADDHON-400]: ADDHON-400: ..." + # is the doubled line reported in #76). + "hOn setup failed [%s] (phase=%s): %s [%s]", + self.last_error_code.label, + self.last_error_phase or "?", + error_detail(err), + getattr(self._hon_instance, "phase_summary", "") or "no ledger", ) self.emit_auth_diagnostics( self.last_error_code, @@ -636,8 +733,14 @@ def submit_mfa_code_sync(self, context: Any, code: str) -> None: if self._hon_instance is None: raise RuntimeError("no pending MFA challenge") try: + # The resume verifies the OTP and then runs the full setup, so it gets + # the OTP exchange PLUS the same setup watchdog setup_sync chose -- + # including the tighter validation one when a human is waiting on the + # config-flow form, which is the whole reason the two were split. self._api = self._run_on_hon_loop( - self._hon_instance.submit_mfa_code(context, code) + self._hon_instance.submit_mfa_code(context, code), + budget.MFA_RESUME + + (budget.VALIDATION_CAP if self._validation else budget.SETUP_CAP), ) except Exception as err: # Record the precise code/phase so the form + diagnostics reflect the real @@ -664,7 +767,9 @@ def resend_mfa_code_sync(self, context: Any) -> None: if self._hon_instance is None: raise RuntimeError("no pending MFA challenge") try: - self._run_on_hon_loop(self._hon_instance.resend_mfa_code(context)) + self._run_on_hon_loop( + self._hon_instance.resend_mfa_code(context), budget.COMMAND + ) except Exception as err: self.last_error_phase = "mfa_send" self.last_error_code = classify(err, phase=self.last_error_phase) @@ -675,11 +780,11 @@ def run_command_sync(self, coro) -> Any: To be called in executor, not on HA's event loop. """ - return self._run_on_hon_loop(coro) + return self._run_on_hon_loop(coro, budget.COMMAND) def dispatch_patch_sync(self, appliance, patch: CommandPatch) -> bool: return self._run_on_hon_loop( - self._command_dispatcher.dispatch(appliance, patch) + self._command_dispatcher.dispatch(appliance, patch), budget.COMMAND ) # -- Appliances ----------------------------------------------------------- @@ -693,6 +798,15 @@ async def async_get_appliances(self) -> list: _LOGGER.error("Error fetching appliances: %s", err) raise RuntimeError(f"Error fetching appliances: {err}") from err + def _needs_rehydration(self, appliance) -> bool: + """Did setup append this appliance without its commands, for a retryable reason? + + getattr so a session double (or an older session object) simply answers "no" + instead of breaking the poll. + """ + asker = getattr(self._api, "needs_rehydration", None) + return bool(callable(asker) and asker(appliance)) + def _update_appliance_sync(self, appliance) -> None: """Update an appliance on the dedicated loop (synchronous, called in executor).""" @@ -700,6 +814,45 @@ async def _do_update(): update_returned_empty = False _debug_appliance_consumption("before update", appliance) + # Attempt 0, first poll only: RE-HYDRATE an appliance the setup contained a + # transport fault for (client/session.py::needs_rehydration). update() only + # reloads the ATTRIBUTES, so without this the appliance would sail through + # the first snapshot with empty `commands` -- and since the platforms call + # async_add_entities exactly once, from that snapshot, and the integration + # has no dynamic discovery, its select/number/switch/button/climate/fan + # entities would never exist until a MANUAL reload. That is the half of the + # fault boundary that makes containing the failure legitimate rather than a + # silently crippled entry. After the first poll it is pointless (the + # entities are already decided), so it costs at most one request per + # degraded appliance, once. + if not self._first_poll_done and self._needs_rehydration(appliance): + loader = getattr(appliance, "load_commands", None) + if callable(loader): + # NOT tolerated: a second failure propagates into the strict + # first-poll branch -> ConfigEntryNotReady -> Home Assistant retries + # the whole setup, the only path that can still produce a COMPLETE + # entity inventory. + # + # Under the SAME scope pair `NativeHon._create_appliance` opens for + # the identical call at setup (client/session.py). Without it this + # was the one await on the poll path with no budget and no phase, so + # a per-request aiohttp timeout left it BARE -- and a bare + # TimeoutError carries no phase, so `representative_failure` maps it + # to the mute ADDHON-460 "Setup timed out" instead of the + # ADDHON-400 the failure actually is. Converted here it is attributed + # (issue #76), and the budget stops an unbounded retry of the very + # request that already failed once from spending the whole cap. + with phase_scope( + "load_appliance", + # Same attribute `_needs_rehydration` asked above: both names + # hold the one NativeHon (`__aenter__` returns self), and reading + # one of them here keeps the guard and the scope from drifting. + getattr(self._api, "_phase_tracker", None), + ): + async with budget.budgeted(budget.APPLIANCE_ONE): + await loader() + _debug_appliance_consumption("after rehydrating commands", appliance) + # Attempt 1: standard update() if hasattr(appliance, "update") and callable(appliance.update): try: @@ -779,7 +932,11 @@ async def _do_update(): "check the integration version." ) - self._run_on_hon_loop(_do_update()) + # One appliance = the waves client/budget.py sizes APPLIANCE_ONE on, plus the + # lazy sign-in a rejected token can start inline. A cap is waited on from THIS + # thread and cannot be suspended the way a scope budget is, so it has to + # contain the sign-in instead (client/budget.py::cap). + self._run_on_hon_loop(_do_update(), budget.APPLIANCE_POLL) # -- Re-auth --------------------------------------------------------------- @@ -988,7 +1145,15 @@ async def async_get_appliances_data(self) -> dict[str, Any]: [(redact_id(_get_name(appliance)), err)] ) raise HonCodedError( - code, "Error updating an appliance on the first poll" + code, + "Error updating an appliance on the first poll", + # Carry the phase the cause already knows (its twin in + # session.py::setup passes phase="load_appliance"). Without + # it Download Diagnostics showed phase=null on exactly the + # failure the hierarchical phase was introduced to name: + # __init__.py reads `getattr(err, "phase", None)` off THIS + # wrapper, and the chain below it is not consulted. + phase=getattr(cause, "phase", None), ) from cause # Steady state: per-appliance resilience. A non-auth failure on ONE # appliance (a transient cloud 5xx that outlived the retries, a @@ -1021,6 +1186,11 @@ async def async_get_appliances_data(self) -> dict[str, Any]: raise HonCodedError( code, f"Update failed for all {len(failed_appliances)} appliance(s)", + # Same reason as the first-poll wrapper below: `__init__.py` reads + # `phase` off THIS object and never walks the `__cause__` chain, so + # without forwarding it a total-failure cycle files phase=null in + # Download Diagnostics even when the cause knows its phase. + phase=getattr(cause, "phase", None), ) from cause if failed_appliances: diff --git a/custom_components/addhon/manifest.json b/custom_components/addhon/manifest.json index 0a13361..6f861b9 100644 --- a/custom_components/addhon/manifest.json +++ b/custom_components/addhon/manifest.json @@ -13,5 +13,5 @@ "yarl>=1.8", "typing-extensions>=4.8" ], - "version": "5.11.0" + "version": "5.12.0" } diff --git a/custom_components/addhon/switch.py b/custom_components/addhon/switch.py index cc0b80e..7ef093f 100644 --- a/custom_components/addhon/switch.py +++ b/custom_components/addhon/switch.py @@ -259,9 +259,36 @@ def _appliance_switches(coordinator, appliance_id: str, data: dict, client) -> l # Both halves are gated: the write schema via the capability, the # read state via the reported attribute. A toggle that cannot be # read back would ship permanently unknown. - if not getattr(capabilities, desc.capability): - continue - if not reports_attribute(attributes, desc.param): + # + # A REJECTION is logged, with both verdicts and the whole capability + # set. These two gates used to `continue` in silence and the summary + # below names only what WAS built, so a purifier missing a toggle + # read exactly like a purifier that never reached this branch -- the + # state a field report sat in for two weeks. The sibling platforms + # (light.py, select.py) have always logged their skips this way. + # + # The capability set is the deciding input and nothing else carries + # it: the gate compares MATERIALISED schema values, while the + # diagnostics dump casts a range's bounds through float(), so "0"/"1" + # and "0.0"/"1.0" look identical there though only the first passes. + # Logged whole because `settings_command` answers a second question + # in the same line, namely which command the parameters were resolved + # against. Every field is derived data -- raw values, bools, a command + # name -- and none of it is identity. + writable = bool(getattr(capabilities, desc.capability, False)) + readable = reports_attribute(attributes, desc.param) + if not writable or not readable: + _LOGGER.debug( + "Switch debug: no purifier '%s' switch for id=%s " + "(%s=%s reports_%s=%s caps=%s)", + desc.key, + redact_id(appliance_id), + desc.capability, + writable, + desc.param, + readable, + capabilities, + ) continue found.append( HonAirPurifierSwitch( diff --git a/custom_components/addhon/translations/en.json b/custom_components/addhon/translations/en.json index 1d599d2..01e6d76 100644 --- a/custom_components/addhon/translations/en.json +++ b/custom_components/addhon/translations/en.json @@ -50,6 +50,8 @@ "account_action_required": "Your password was accepted, but hOn is asking for an extra step on the account (for example a new password to set, or terms to accept). Sign in on the hOn website or app, complete the requested step, then try again here. ({error_code})", "appliance_list_failed": "Could not fetch your appliance list. ({error_code})", "network_timeout": "Timed out contacting the hOn servers. Check your internet connection. ({error_code})", + "auth_timeout": "Timed out while signing in to hOn. The servers are slow or your connection dropped. Try again. ({error_code})", + "refresh_timeout": "Timed out while refreshing the hOn session. Try again in a moment. ({error_code})", "dns_failure": "Could not resolve the hOn servers (DNS). Check your network and DNS. ({error_code})", "tls_failure": "TLS/certificate error contacting hOn. Check the system date/time and network. ({error_code})", "connection_refused": "Could not connect to the hOn servers (refused, reset or unreachable). Check your network and firewall. ({error_code})", diff --git a/custom_components/addhon/translations/it.json b/custom_components/addhon/translations/it.json index 8a9d327..dd94f58 100644 --- a/custom_components/addhon/translations/it.json +++ b/custom_components/addhon/translations/it.json @@ -50,6 +50,8 @@ "account_action_required": "La password è corretta, ma hOn chiede un passaggio aggiuntivo sull'account (per esempio una nuova password da impostare o condizioni da accettare). Accedi dal sito o dall'app hOn, completa il passaggio richiesto, poi riprova qui. ({error_code})", "appliance_list_failed": "Impossibile recuperare la lista dei dispositivi. ({error_code})", "network_timeout": "Timeout nel contattare i server hOn. Controlla la connessione internet. ({error_code})", + "auth_timeout": "Timeout durante l'accesso a hOn. I server sono lenti o la connessione si è interrotta. Riprova. ({error_code})", + "refresh_timeout": "Timeout durante il rinnovo della sessione hOn. Riprova tra poco. ({error_code})", "dns_failure": "Impossibile risolvere i server hOn (DNS). Controlla rete e DNS. ({error_code})", "tls_failure": "Errore TLS/certificato nel contattare hOn. Controlla data/ora di sistema e rete. ({error_code})", "connection_refused": "Impossibile connettersi ai server hOn (rifiutata, interrotta o irraggiungibile). Controlla rete e firewall. ({error_code})", diff --git a/tests/_aiohttp_contract.py b/tests/_aiohttp_contract.py index 6090255..8edb518 100644 --- a/tests/_aiohttp_contract.py +++ b/tests/_aiohttp_contract.py @@ -139,6 +139,34 @@ def check(name: str, ok: bool, detail: str = "") -> None: (real_partial != body) == (fake_partial != body), f"real short={real_partial != body} fake short={fake_partial != body}", ) + # 4. The attributes the STRUCTURAL classifier duck-types on (issue #76). + # `error_codes` is a pure module and cannot import aiohttp, so it reads + # `ClientConnectorError.os_error` and `ClientResponseError.status` by name + # and relies on the aiohttp SSL errors deriving from `ssl.SSLError`. If the + # library ever renames or drops one of those, the classifier would silently + # fall back to grepping the message -- exactly the drift this file exists to + # catch. Nothing here needs the server. + import ssl + + check( + "ClientConnectorError exposes .os_error", + "os_error" in dir(aiohttp.ClientConnectorError), + ) + response_error = aiohttp.ClientResponseError( + None, (), status=503, message="boom" + ) + check( + "ClientResponseError carries an int .status", + getattr(response_error, "status", None) == 503, + ) + check( + "aiohttp SSL connector errors derive from ssl.SSLError", + issubclass(aiohttp.ClientConnectorCertificateError, ssl.SSLError), + ) + check( + "ServerTimeoutError is an asyncio.TimeoutError", + issubclass(aiohttp.ServerTimeoutError, asyncio.TimeoutError), + ) finally: await runner.cleanup() return failures diff --git a/tests/test_air_purifier_entities.py b/tests/test_air_purifier_entities.py index d25002d..8e852cc 100644 --- a/tests/test_air_purifier_entities.py +++ b/tests/test_air_purifier_entities.py @@ -1456,6 +1456,76 @@ def test_the_ap_switch_setter_uses_the_dispatcher(self) -> None: self.assertNotIn("async_send_settings", source) +class AirPurifierSwitchSkipLoggingTest(unittest.IsolatedAsyncioTestCase): + """A rejected toggle must say WHY. + + Both gates used to `continue` in silence while the summary line named only + what was built, so a purifier missing a control looked exactly like a + purifier that never reached the branch. A field report sat in that state for + two weeks because neither the log nor the dump carried the deciding input. + """ + + async def _skip_records(self, **kwargs): + import logging + + from custom_components.addhon import switch + + with self.assertLogs(switch._LOGGER, level=logging.DEBUG) as caught: + await _build_switches(**kwargs) + return [line for line in caught.output if "no purifier" in line] + + async def test_a_capability_rejection_names_the_capability(self) -> None: + """lockStatus declared over three values is not a toggle, so the gate + refuses it. The log must say which capability said no.""" + records = await self._skip_records( + schema=_toggle_schema(lockStatus=["0", "1", "2"]) + ) + joined = "\n".join(records) + + self.assertIn("child_lock", joined) + self.assertIn("supports_lock", joined) + self.assertIn("supports_lock=False", joined) + + async def test_a_missing_state_is_distinguished_from_a_missing_capability( + self, + ) -> None: + """The two gates fail for opposite reasons and the reader must be able to + tell them apart: here the schema is complete and the STATE is absent.""" + attributes = {k: v for k, v in FULL_ATTRIBUTES.items() if k != "lockStatus"} + records = await self._skip_records( + attributes=attributes, schema=_toggle_schema() + ) + joined = "\n".join(records) + + self.assertIn("supports_lock=True", joined) + self.assertIn("reports_lockStatus=False", joined) + + async def test_the_rejection_carries_the_capability_set(self) -> None: + """The materialised schema values are what the gate compares, and no + other artifact carries them: the dump casts a range's bounds to float, so + "0"/"1" and "0.0"/"1.0" are indistinguishable there.""" + records = await self._skip_records( + schema=_toggle_schema(lockStatus=["0", "1", "2"]) + ) + joined = "\n".join(records) + + self.assertIn("lock_values=", joined) + self.assertIn("settings_command=", joined) + + async def test_nothing_is_logged_when_both_toggles_are_built(self) -> None: + records = await self._skip_records(schema=_toggle_schema()) + self.assertEqual([], records) + + async def test_the_rejection_never_carries_the_appliance_id(self) -> None: + records = await self._skip_records( + schema=_toggle_schema(lockStatus=["0", "1", "2"]) + ) + joined = "\n".join(records) + + self.assertNotIn("ap-1", joined) + self.assertIn("***", joined) + + class _ExplodingAppliance: """An appliance whose schema cannot be read at all.""" diff --git a/tests/test_auth_error_classification.py b/tests/test_auth_error_classification.py index 87a16ad..8d88de9 100644 --- a/tests/test_auth_error_classification.py +++ b/tests/test_auth_error_classification.py @@ -161,6 +161,25 @@ def test_update_mfa_code_invalid_is_config_entry_auth_failed(self) -> None: with self.assertRaises(AuthFailed): upd(MFACodeInvalid("mfa: invalid verification code")) + def test_ha_messages_show_the_code_exactly_once(self) -> None: + # #76: HonCodedError already renders as "ADDHON-400: reason", so prepending the + # label produced "[ADDHON-400] Unable to connect to hOn: ADDHON-400: ...". Home + # Assistant SHOWS these two messages on the config-entry page, so the user + # really did read the code twice. + from custom_components.addhon.error_codes import HonCodedError, NETWORK_TIMEOUT + + _AF, NotReady, UpdateFailed, setup, upd = self._imports() + for raiser, expected in ((setup, NotReady), (upd, UpdateFailed)): + with self.subTest(raiser=raiser.__name__): + try: + raiser(HonCodedError(NETWORK_TIMEOUT)) + except expected as wrapped: + text = str(wrapped) + self.assertEqual(1, text.count("ADDHON-"), text) + self.assertIn("Network timeout contacting hOn", text) + else: + self.fail("expected a raise") + def test_chaining_preserves_original_error(self) -> None: _AF, _NotReady, UpdateFailed, _setup, upd = self._imports() original = RuntimeError("root cause") diff --git a/tests/test_auth_retry_policy.py b/tests/test_auth_retry_policy.py new file mode 100644 index 0000000..628154c --- /dev/null +++ b/tests/test_auth_retry_policy.py @@ -0,0 +1,394 @@ +# Copyright (C) 2026 tis24dev +# SPDX-License-Identifier: AGPL-3.0-or-later + +"""Which login steps may be retried, and -- far more important -- which may not. + +Issue #76 cause 3: the validation path had NO retry at all, so a single blip on any +of the 9 sequential login round-trips became a permanent user-facing error. + +The non-regression half of this file is the valuable half. Retrying a step that +submits credentials, consumes a single-use hand-off URL, mints a fresh MFA context or +spends a rotating refresh token costs a second OTP email, an invalid session or a +permanently burnt token. Those steps must be delivered EXACTLY ONCE. +""" +from __future__ import annotations + +import asyncio +import sys +import time +import unittest +from pathlib import Path + +REPO = Path(__file__).resolve().parents[1] +if str(REPO) not in sys.path: + sys.path.insert(0, str(REPO)) +if str(REPO / "tests") not in sys.path: + sys.path.insert(0, str(REPO / "tests")) + +from _golden import install_stubs # noqa: E402 + +install_stubs() + +from test_transport_auth import ( # noqa: E402 + AUTH, + FakeResp, + FakeSession, + _happy_responses, +) + +from custom_components.addhon import error_codes as ec # noqa: E402 +from custom_components.addhon.client import budget as budget_mod # noqa: E402 +from custom_components.addhon.client.session import NativeHon # noqa: E402 +from custom_components.addhon.client.transport import auth as auth_mod # noqa: E402 +from custom_components.addhon.client.transport import ( # noqa: E402 + connection as conn_mod, +) +from custom_components.addhon.client.transport import retry as retry_mod # noqa: E402 +from custom_components.addhon.client.transport.api import HonApi # noqa: E402 +from custom_components.addhon.client.transport.auth import ( # noqa: E402 + HonAuth, + NativeAuthError, +) +from custom_components.addhon.client.transport.connection import ( # noqa: E402 + HonConnection, +) +from custom_components.addhon.client.transport.device import HonDevice # noqa: E402 + +# Index of each step in the scripted happy-path response list. +_STEP_INDEX = { + "introduce": 0, + "redirect_1": 1, + "redirect_2": 2, + "login_page": 3, + "login_submit": 4, + "post_login": 5, + "token_page": 6, + "api_auth": 7, +} + + +class _FlakySession(FakeSession): + """Fails the response at `fail_at` once (with `error`), then serves it normally.""" + + def __init__(self, responses, fail_at: int, error: BaseException) -> None: + super().__init__(responses) + self._fail_at = fail_at + self._error = error + self._served = 0 + + def _next(self, method, url): + if self._served == self._fail_at and self._fail_at >= 0: + self._served += 1 + self.calls.append((method, str(url))) + raise self._error + self._served += 1 + return super()._next(method, url) + + +class _NoSleep: + """Records the retry delays instead of waiting for them.""" + + def __init__(self, test) -> None: + self.delays: list[float] = [] + original = retry_mod.asyncio.sleep + + async def fake_sleep(seconds): + self.delays.append(seconds) + + retry_mod.asyncio.sleep = fake_sleep + test.addCleanup(setattr, retry_mod.asyncio, "sleep", original) + + +def _auth(session): + return HonAuth(session, "user@x.it", "pw", HonDevice()) + + +class RetryableStepsTest(unittest.TestCase): + def setUp(self) -> None: + self.sleeper = _NoSleep(self) + + def _login_recovers_after_one_blip(self, step: str, error: BaseException) -> None: + session = _FlakySession(_happy_responses(), _STEP_INDEX[step], error) + auth = _auth(session) + asyncio.run(auth.authenticate()) + self.assertEqual("COG123", auth.cognito_token, f"{step} did not recover") + # Delivered twice (the failed attempt + the successful retry), fixed 2s delay. + self.assertEqual([retry_mod.RETRY_DELAY], self.sleeper.delays) + + def test_introduce_retries(self) -> None: + self._login_recovers_after_one_blip("introduce", asyncio.TimeoutError()) + + def test_first_redirect_retries(self) -> None: + self._login_recovers_after_one_blip("redirect_1", asyncio.TimeoutError()) + + def test_second_redirect_retries(self) -> None: + self._login_recovers_after_one_blip("redirect_2", asyncio.TimeoutError()) + + def test_login_page_retries(self) -> None: + self._login_recovers_after_one_blip("login_page", asyncio.TimeoutError()) + + def test_api_auth_retries(self) -> None: + self._login_recovers_after_one_blip("api_auth", ConnectionResetError(104, "reset")) + + + def test_sso_fast_path_is_not_swallowed_by_the_retry_wrapper(self) -> None: + # _introduce signals the already-authorized SSO fast path with a control-flow + # exception. Wrapping it in retry_transport must let that through untouched, + # or a still-valid session would be re-driven through a full login. + session = FakeSession( + [ + FakeResp( + text="...oauth/done#access_token=AAA&refresh_token=r&id_token=CCC&" + ), + FakeResp(json={"cognitoUser": {"Token": "COG123"}}), + ] + ) + auth = _auth(session) + asyncio.run(auth.authenticate()) + self.assertEqual("COG123", auth.cognito_token) + self.assertEqual(2, len(session.calls)) + self.assertEqual([], self.sleeper.delays) + + +class NonRetryableStepsTest(unittest.TestCase): + """The steps a duplicate delivery would damage. EXACTLY ONE send each.""" + + def setUp(self) -> None: + self.sleeper = _NoSleep(self) + + def _step_is_delivered_once(self, step: str) -> None: + index = _STEP_INDEX[step] + session = _FlakySession(_happy_responses(), index, asyncio.TimeoutError()) + auth = _auth(session) + with self.assertRaises(BaseException): + asyncio.run(auth.authenticate()) + # The failing step was attempted once and never re-sent. + self.assertEqual(index + 1, len(session.calls), f"{step} was re-sent") + self.assertEqual([], self.sleeper.delays) + + def test_login_submit_is_never_retried(self) -> None: + # Submits the credentials and advances the Salesforce session; its payload + # embeds the fwuid captured one step earlier. + self._step_is_delivered_once("login_submit") + + def test_post_login_handoff_is_never_retried(self) -> None: + # Single-use hand-off URL: a second GET lands on a login page -> "no href" -> + # a transient blip would become a permanent ADDHON-130 credentials error. + self._step_is_delivered_once("post_login") + + def test_token_page_is_never_retried(self) -> None: + # Carries the #access_token fragment: the OAuth hand-off, consumable once. + self._step_is_delivered_once("token_page") + + def test_refresh_is_never_retried(self) -> None: + # The refresh token ROTATES and is single-use: a duplicate delivery burns it + # while the unseen response carried its replacement -> forced full login, and + # an OTP prompt on a 2FA account. + session = _FlakySession([FakeResp(json={})], 0, asyncio.TimeoutError()) + auth = _auth(session) + with self.assertRaises(asyncio.TimeoutError): + asyncio.run(auth.refresh("rt")) + self.assertEqual(1, len(session.calls)) + self.assertEqual([], self.sleeper.delays) + + +class RetryPredicateTest(unittest.TestCase): + def setUp(self) -> None: + self.sleeper = _NoSleep(self) + + def test_retryable_code_set_is_pinned(self) -> None: + # A guard against drift: if `classify` moves one of these codes, the retry + # policy would change silently. + self.assertEqual( + { + ec.NETWORK_TIMEOUT, + ec.DNS_FAILURE, + ec.CONNECTION_REFUSED, + ec.LOOP_TIMEOUT, + }, + set(retry_mod.RETRYABLE_CODES), + ) + + def test_received_http_responses_are_not_retried(self) -> None: + # A RECEIVED response is never a "nothing came back" blip: 5xx/429 already have + # the appliance-layer backoff, 401/403 are a rejection. + for err in ( + NativeAuthError("api_auth: status 401"), + RuntimeError("hOn server error (status 503)"), + RuntimeError("hOn rate limited (status 429)"), + ): + with self.subTest(err=err): + self.assertFalse(retry_mod._is_retryable(err)) + + def test_shared_budget_is_spent_across_steps(self) -> None: + calls = {"n": 0} + + async def always_times_out(): + calls["n"] += 1 + raise asyncio.TimeoutError() + + async def scenario(): + budget = retry_mod.RetryBudget() + with self.assertRaises(asyncio.TimeoutError): + await retry_mod.retry_transport(budget, "introduce", always_times_out) + return budget + + budget = asyncio.run(scenario()) + # 1 original attempt + RETRY_MAX_EXTRA retries, then it gives up. + self.assertEqual(1 + retry_mod.RETRY_MAX_EXTRA, calls["n"]) + self.assertEqual(0, budget.extra) + + def test_deadline_gate_refuses_a_retry_that_would_not_fit(self) -> None: + calls = {"n": 0} + + async def always_times_out(): + calls["n"] += 1 + raise asyncio.TimeoutError() + + async def scenario(): + import time + + budget = retry_mod.RetryBudget(deadline=time.monotonic() + 5) + with self.assertRaises(asyncio.TimeoutError): + await retry_mod.retry_transport(budget, "introduce", always_times_out) + + asyncio.run(scenario()) + # No room left for another 30s request + 2s delay -> no retry at all. This is + # what stops the retry from being the reason the phase budget expires. + self.assertEqual(1, calls["n"]) + + +def _appliance_list_response() -> FakeResp: + """What the wire answers AFTER the login: the single POST setup() is there for.""" + return FakeResp( + json={ + "modules": { + "applianceList": { + "payload": { + "appliances": [{"macAddress": "AA", "applianceTypeName": "WM"}] + } + } + } + } + ) + + +class DeadlineComesFromTheEnclosingScopeTest(unittest.TestCase): + """Whose deadline the gate measures against -- through the REAL production nesting. + + `authenticate()` used to rebuild the deadline as `monotonic() + AUTH_FULL`, a + number the enclosing scope does not have to agree with. Measured against a deadline + nobody enforces, the gate allowed every retry, and the retries then spent a shorter, + real budget: the exact opposite of the invariant retry.py states. + + These tests used to wrap `authenticate()` in a BARE `budgeted(10)` / `budgeted(300)` + of their own. Production never builds that: the login is lazy, so it always runs + inside `budgeted(AUTH_FULL, suspends_caller=True)` opened by `_check_headers`, + itself nested in the caller's scope -- and pinning a nesting production does not + build is the exact mistake that let the first attempt at #76 ship green. So the + login is driven from `NativeHon.setup()` through `HonApi`, `_intercept` and + `_check_headers`, and what differs between the two cases is the size of the scope + PRODUCTION opens, changed where production reads it. + """ + + def setUp(self) -> None: + self.sleeper = _NoSleep(self) + + def _sign_in_scope_of(self, seconds: float) -> None: + original = conn_mod.AUTH_FULL + conn_mod.AUTH_FULL = seconds + self.addCleanup(setattr, conn_mod, "AUTH_FULL", original) + + def _setup_driven_login(self, *, with_blip: bool = True): + # A connection reset, not a TimeoutError: it is just as retryable + # (CONNECTION_REFUSED is in RETRYABLE_CODES) and it travels out of the scopes + # untouched, so the assertion is about the RETRY and nothing else. + responses = [*_happy_responses(), _appliance_list_response()] + session = _FlakySession( + responses, + _STEP_INDEX["introduce"] if with_blip else -1, + ConnectionResetError(104, "reset"), + ) + hon = NativeHon(email="user@x.it", password="pw", enable_mqtt=False, minimal=True) + connection = HonConnection( + "user@x.it", "pw", session=session, phase_tracker=hon._phase_tracker + ) + connection._auth = HonAuth( + session, "user@x.it", "pw", HonDevice(), phase_tracker=hon._phase_tracker + ) + hon._connection = connection + hon._api = HonApi(connection) + return hon, connection + + def _deadlines_handed_to_the_gate(self) -> list[float]: + """Seconds of room the login's RetryBudget was given, as it was given them.""" + seen: list[float] = [] + original = auth_mod.RetryBudget + + class _Recording(original): # type: ignore[valid-type,misc] + def __init__(self, extra=retry_mod.RETRY_MAX_EXTRA, deadline=None): + seen.append( + None if deadline is None else deadline - time.monotonic() + ) + super().__init__(extra, deadline) + + auth_mod.RetryBudget = _Recording + self.addCleanup(setattr, auth_mod, "RetryBudget", original) + return seen + + def test_the_gate_measures_the_sign_ins_own_scope(self) -> None: + # The lazy sign-in SUSPENDS the request that triggered it, so the tightest scope + # in force while it runs is its own AUTH_FULL -- not the caller's APPLIANCE_LIST + # (40s), which would refuse retries the login is entitled to, and not a number + # re-derived from a constant, which would allow retries nothing can pay for. + seen = self._deadlines_handed_to_the_gate() + hon, _connection = self._setup_driven_login(with_blip=False) + asyncio.run(hon.setup()) + self.assertEqual(1, len(seen)) + room = seen[0] + self.assertIsNotNone(room, "production must arm the gate with a real deadline") + self.assertGreater(room, budget_mod.APPLIANCE_LIST) + self.assertLessEqual(room, budget_mod.AUTH_FULL) + self.assertGreater(room, budget_mod.AUTH_FULL - 1) + + def test_a_wide_sign_in_scope_lets_the_retry_run(self) -> None: + self._sign_in_scope_of(300) + hon, connection = self._setup_driven_login() + asyncio.run(hon.setup()) + self.assertEqual("COG123", connection.auth.cognito_token) + self.assertEqual([retry_mod.RETRY_DELAY], self.sleeper.delays) + self.assertEqual(1, len(hon.appliances)) + + def test_a_sign_in_scope_too_tight_for_another_attempt_refuses_the_retry(self) -> None: + # 10s left cannot absorb a 30s request plus the 2s delay, so the blip must + # surface now instead of being turned into a budget expiry a moment later. + # Same login, same blip, same call path -- only the scope production opens + # around the sign-in differs. + self._sign_in_scope_of(10) + hon, _connection = self._setup_driven_login() + with self.assertRaises(ConnectionResetError): + asyncio.run(hon.setup()) + self.assertEqual([], self.sleeper.delays) + + +class StepOrderUnderBlipTest(unittest.TestCase): + def setUp(self) -> None: + self.sleeper = _NoSleep(self) + + def test_transient_failure_does_not_alter_the_step_order(self) -> None: + session = _FlakySession( + _happy_responses(), _STEP_INDEX["login_page"], asyncio.TimeoutError() + ) + auth = _auth(session) + asyncio.run(auth.authenticate()) + methods = [m for m, _ in session.calls] + # The retried login page shows up twice; everything else keeps its place. + self.assertEqual( + ["GET", "GET", "GET", "GET", "GET", "POST", "GET", "GET", "POST"], methods + ) + self.assertTrue(str(session.calls[-1][1]).endswith("/auth/v1/login")) + self.assertIn(AUTH, str(session.calls[0][1])) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_config_flow_error_codes.py b/tests/test_config_flow_error_codes.py index cb09249..9b92d09 100644 --- a/tests/test_config_flow_error_codes.py +++ b/tests/test_config_flow_error_codes.py @@ -146,6 +146,18 @@ async def test_ui_code_drives_slug_and_label(self) -> None: self.assertEqual(res["errors"]["base"], "network_timeout") self.assertEqual(res["description_placeholders"]["error_code"], "ADDHON-400") + async def test_auth_timeout_code_drives_its_own_slug(self) -> None: + # ADDHON-405/406 are what a slow sign-in reports now; before #76 they did not + # exist and the login timeout was shown as ADDHON-400 "network timeout". + res = await self._run_user(cf.CannotConnect(ec.AUTH_TIMEOUT)) + self.assertEqual(res["errors"]["base"], "auth_timeout") + self.assertEqual(res["description_placeholders"]["error_code"], "ADDHON-405") + + async def test_refresh_timeout_code_drives_its_own_slug(self) -> None: + res = await self._run_user(cf.CannotConnect(ec.REFRESH_TIMEOUT)) + self.assertEqual(res["errors"]["base"], "refresh_timeout") + self.assertEqual(res["description_placeholders"]["error_code"], "ADDHON-406") + async def test_invalid_auth_code(self) -> None: res = await self._run_user(cf.InvalidAuth(ec.INVALID_CREDENTIALS)) self.assertEqual(res["errors"]["base"], "invalid_credentials") diff --git a/tests/test_coordinator_resilience.py b/tests/test_coordinator_resilience.py index a4acc8a..3f6b7e4 100644 --- a/tests/test_coordinator_resilience.py +++ b/tests/test_coordinator_resilience.py @@ -230,6 +230,33 @@ def _update(appliance): self.assertIs(classify(ctx.exception), DECODE_ERROR) self.assertFalse(c._first_poll_done) + def test_first_poll_failure_keeps_the_phase_the_cause_knows(self) -> None: + # The strict first-poll wrapper is the twin of the all-failed raise in + # `NativeHon.setup()`, which passes phase="load_appliance". This one did not, so + # the ONE failure the hierarchical phase was introduced to name arrived with + # phase=None: __init__.py reads `getattr(err, "phase", None)` off THIS wrapper + # (the __cause__ chain below it is never consulted) and Download Diagnostics + # showed a null phase for a fault that knew exactly where it happened. + # DECODE_ERROR rather than a timeout for the same reason as the test above: a + # retryable code would spend the 15s of server backoff before reaching the + # branch under test. What is being pinned is the wrapper forwarding the phase, + # which does not depend on which non-auth code the cause carries. + from custom_components.addhon.error_codes import DECODE_ERROR + + bad = FakeAppliance("bad") + c = _client([bad]) # _first_poll_done False -> the strict branch + + def _update(appliance): + raise HonCodedError( + DECODE_ERROR, "unreadable command payload", phase="load_appliance" + ) + + c._update_appliance_sync = _update + with self.assertRaises(HonCodedError) as ctx: + asyncio.run(c.async_get_appliances_data()) + self.assertIs(DECODE_ERROR, ctx.exception.error_code) + self.assertEqual("load_appliance", ctx.exception.phase) + def test_zero_appliances_returns_empty_without_raising(self) -> None: c = _client([]) c._update_appliance_sync = lambda appliance: None diff --git a/tests/test_diagnostics.py b/tests/test_diagnostics.py index f9f664a..3459483 100644 --- a/tests/test_diagnostics.py +++ b/tests/test_diagnostics.py @@ -233,6 +233,19 @@ def __init__(self, parameters): class FakeAppliance: + def __init__(self, commands, model_attributes=None): + self.commands = commands + if model_attributes is not None: + self.model_attributes = model_attributes + + +class FakeApplianceNoModel: + """An appliance implementation with NO `model_attributes` surface at all. + + Guards the getattr default: an older/foreign appliance object must not make + the whole dump raise. + """ + def __init__(self, commands): self.commands = commands @@ -276,9 +289,16 @@ def _build_coordinator() -> FakeCoordinator: # no entity writes this -> unmapped writable "mysteryParam": FakeParam(value="3", typology="enum", values=["3", "4"]), }), - } + }, + # Cloud CATALOGUE metadata (applianceModel.attributes), not shadow telemetry. + model_attributes={ + "zones": "fridge|freezer|vtRoom2", + "seriesVersion": "fd90Series7a", + "doorNumber": 4, + }, ) - wd = FakeAppliance( + # No model_attributes surface at all -> the block must still build, with {}. + wd = FakeApplianceNoModel( commands={ "settings": FakeCommand({ "program": FakeParam(value="9", typology="enum", values=["9", "10"]), # mapped @@ -375,6 +395,63 @@ def test_range_param_schema_omits_enumerated_grid(self): schema = diagnostics._param_schema(param) self.assertEqual((schema["min"], schema["max"], schema["step"]), (0, 1400, 100)) self.assertNotIn("enum", schema) + self.assertNotIn("values", schema) + + def test_a_small_range_carries_the_values_it_materialises(self): + """min/max/step cannot answer why a 0/1 control is missing: param_range + casts through float(), so "0"/"1" and "0.0"/"1.0" print the same here, + while the capability gates compare those exact strings.""" + param = FakeParam( + value="0", typology="range", rng=(0, 1, 1), values=["0", "1"] + ) + self.assertEqual(["0", "1"], diagnostics._param_schema(param)["values"]) + + def test_a_decimal_spelled_range_is_visible_as_such(self): + """The whole point: the dump must distinguish the grid that passes a + capability gate from the one that silently removes the control.""" + param = FakeParam( + value="0", typology="range", rng=(0, 1, 1), values=["0.0", "1.0"] + ) + schema = diagnostics._param_schema(param) + self.assertEqual((schema["min"], schema["max"], schema["step"]), (0, 1, 1)) + self.assertEqual(["0.0", "1.0"], schema["values"]) + + def test_the_materialised_grid_is_bounded(self): + """Emitted only for a grid small enough to be a toggle or a few-position + control. The bound is evaluated arithmetically, so `.values` is never read + for a real setpoint range.""" + cap = diagnostics._RANGE_MAX_MATERIALISED + inside = FakeParam( + value="0", typology="range", rng=(0, cap - 1, 1), + values=[str(v) for v in range(cap)], + ) + outside = FakeParam( + value="0", typology="range", rng=(0, cap, 1), + values=[str(v) for v in range(cap + 1)], + ) + self.assertIn("values", diagnostics._param_schema(inside)) + self.assertNotIn("values", diagnostics._param_schema(outside)) + + def test_a_huge_grid_is_never_materialised_to_measure_it(self): + """A parameter whose `.values` would explode must be refused WITHOUT the + property ever being read: the count comes from min/max/step. Not a + FakeParam subclass, because that one ASSIGNS self.values and a property + cannot be assigned over.""" + + class ExplodingRange: + typology = "range" + category = "command" + mandatory = 0 + value = "0" + min, max, step = 0, 100000, 1 + + @property + def values(self): # pragma: no cover - must never be reached + raise AssertionError("`.values` was materialised for a huge range") + + schema = diagnostics._param_schema(ExplodingRange()) + self.assertNotIn("values", schema) + self.assertEqual(100000, schema["max"]) def test_mac_in_value_under_benign_key_is_masked(self): # Identity that lands in a string VALUE under a non-redacted key (an event @@ -399,6 +476,54 @@ def test_mac_in_value_wrapped_object_is_masked(self): self.assertEqual(out["deviceInfo"], "mac ***") +class DiagnosticsModelAttributesTest(unittest.TestCase): + """The model CATALOGUE block (`applianceModel.attributes`). + + It answers what the appliance IS where the shadow cannot: which zones the + model declares, which series it belongs to. Without it a zone-indexing + report cannot be diagnosed from the dump alone (issue #75). + """ + + def test_model_attributes_present_and_readable(self): + _, blocks = _entry_diag() + model = blocks["AC"]["model_attributes"] + self.assertEqual(model["zones"], "fridge|freezer|vtRoom2") + self.assertEqual(model["seriesVersion"], "fd90Series7a") + self.assertEqual(model["doorNumber"], 4) + + def test_appliance_without_the_surface_gets_empty_dict(self): + _, blocks = _entry_diag() + self.assertEqual(blocks["WD"]["model_attributes"], {}) + + def test_distinct_from_shadow_attributes(self): + # Same block, two axes: catalogue vs telemetry. A key of one must not + # leak into the other. + _, blocks = _entry_diag() + self.assertNotIn("zones", blocks["AC"]["attributes"]) + self.assertNotIn("tempIndoor", blocks["AC"]["model_attributes"]) + + def test_non_mapping_surface_is_ignored(self): + self.assertEqual(diagnostics._model_attributes(object()), {}) + self.assertEqual( + diagnostics._model_attributes( + FakeAppliance(commands={}, model_attributes=["zones"]) + ), + {}, + ) + + def test_redaction_still_applies_to_the_block(self): + # model_attributes goes through _redact like every other section: a + # catalogue row named after an identity key must not pass in cleartext. + app = FakeAppliance( + commands={}, model_attributes={"macAddress": "AA:BB:CC:DD:EE:FF", "zones": "fridge"} + ) + block = diagnostics._appliance_block( + "id1", {"appliance": app, "type": "AC", "attributes": {}, "statistics": {}} + ) + self.assertEqual(block["model_attributes"]["macAddress"], "***") + self.assertEqual(block["model_attributes"]["zones"], "fridge") + + class DiagnosticsCoverageTest(unittest.TestCase): def test_unmapped_bare_attribute_surfaces(self): _, blocks = _entry_diag() @@ -745,6 +870,48 @@ class _Client: self.assertFalse(le["had_refresh_token"]) self.assertNotIn("mfa", le) # not an MFA-band code + def test_last_error_includes_a_leak_free_phase_ledger(self) -> None: + # #76: without per-phase durations a report cannot say WHICH phase burned the + # time, so no timeout hypothesis is falsifiable on the user's machine. + from custom_components.addhon import error_codes as ec + + class _Client: + last_error_code = ec.REFRESH_TIMEOUT + last_error_phase = "load_appliances/auth/refresh" + last_mfa_summary = None + last_phase_ledger = [ + {"phase": "load_appliances/auth/refresh", "seconds": 50.0, "outcome": "timeout"}, + {"phase": "load_appliances", "seconds": 50.1, "outcome": "error"}, + ] + _refresh_token = "rt" + + hass = FakeHass(_build_coordinator()) + hass.data[DOMAIN]["e1"]["client"] = _Client() + result = _run(diagnostics.async_get_config_entry_diagnostics(hass, FakeEntry())) + le = result["last_error"] + self.assertEqual("ADDHON-406", le["code"]) + self.assertEqual(2, len(le["phase_ledger"])) + blob = json.dumps(le["phase_ledger"]) + self.assertNotIn("@", blob) + self.assertNotIn("http", blob) + for entry in le["phase_ledger"]: + self.assertIn(entry["outcome"], ("ok", "error", "timeout")) + + def test_last_error_omits_the_ledger_when_absent(self) -> None: + from custom_components.addhon import error_codes as ec + + class _Client: + last_error_code = ec.NETWORK_TIMEOUT + last_error_phase = "load_appliances" + last_mfa_summary = None + last_phase_ledger = None + _refresh_token = "" + + hass = FakeHass(_build_coordinator()) + hass.data[DOMAIN]["e1"]["client"] = _Client() + result = _run(diagnostics.async_get_config_entry_diagnostics(hass, FakeEntry())) + self.assertNotIn("phase_ledger", result["last_error"]) + def test_last_error_includes_mfa_summary_for_mfa_code(self) -> None: from custom_components.addhon import error_codes as ec diff --git a/tests/test_engine_appliance_root.py b/tests/test_engine_appliance_root.py index f0e9ccc..af7fa26 100644 --- a/tests/test_engine_appliance_root.py +++ b/tests/test_engine_appliance_root.py @@ -348,6 +348,50 @@ def test_explicit_disconnect_clears_liveness_no_resurrection(self) -> None: self.assertFalse(app.connection) # NOT resurrected +class ModelAttributesTest(unittest.TestCase): + """`applianceModel.attributes` -> parName/parValue mapping. + + Model CATALOGUE metadata, not shadow telemetry: it is what tells us the + appliance declares e.g. `zones = fridge|freezer|vtRoom1`, which the hOn app + treats as authoritative for which zones exist. Feeds diagnostics. + """ + + def test_empty_before_commands_are_loaded(self) -> None: + app = NaRoot(FakeApi(), json.loads(json.dumps(_INFO)), zone=0) + self.assertEqual(app.model_attributes, {}) + + def test_list_payload_flattened_from_real_dump(self) -> None: + app = NaRoot(FakeApi(), json.loads(json.dumps(_INFO)), zone=0) + _run(app.load_commands()) + attrs = app.model_attributes + self.assertEqual(attrs["zones"], "fridge|freezer|vtRoom1") + self.assertEqual(attrs["seriesVersion"], "2d60Series3bis") + self.assertEqual(attrs["doorNumber"], "2") + + def test_mapping_payload_accepted_as_is(self) -> None: + app = NaRoot(FakeApi(), json.loads(json.dumps(_INFO)), zone=0) + app._appliance_model = {"attributes": {"zones": "fridge|vtRoom2"}} + self.assertEqual(app.model_attributes, {"zones": "fridge|vtRoom2"}) + + def test_malformed_rows_skipped_without_raising(self) -> None: + app = NaRoot(FakeApi(), json.loads(json.dumps(_INFO)), zone=0) + app._appliance_model = { + "attributes": [ + {"parName": "zones", "parValue": "fridge"}, + {"parValue": "orphan"}, # no parName + {"parName": "", "parValue": "empty name"}, + "not-a-row", + {"parName": "noValue"}, # present but valueless -> None, still kept + ] + } + self.assertEqual(app.model_attributes, {"zones": "fridge", "noValue": None}) + + def test_absent_or_wrong_typed_payload_is_empty(self) -> None: + app = NaRoot(FakeApi(), json.loads(json.dumps(_INFO)), zone=0) + app._appliance_model = {"attributes": "fridge|freezer"} + self.assertEqual(app.model_attributes, {}) + + class RootGoldenTest(unittest.TestCase): def test_native_root_matches_golden(self) -> None: snap = _native_snapshot() diff --git a/tests/test_error_codes.py b/tests/test_error_codes.py index 89f51a3..9a5a5d7 100644 --- a/tests/test_error_codes.py +++ b/tests/test_error_codes.py @@ -346,13 +346,161 @@ def test_phase_timeout_code(self) -> None: self.assertIs(ec.phase_timeout_code("aws_token"), ec.MQTT_CONNECT_TIMEOUT) # Every phase-timeout code must read as retryable (so the failure is retried, # never mistaken for a reauth) -> its message must trip _is_retryable_server_error. - for slug in ("loop_timeout", "network_timeout", "mqtt_connect_timeout", "mqtt_subscribe_timeout"): + for slug in ( + "loop_timeout", + "network_timeout", + "mqtt_connect_timeout", + "mqtt_subscribe_timeout", + "auth_timeout", + "refresh_timeout", + ): self.assertTrue( hc._is_retryable_server_error(ec.HonCodedError(ec.by_slug(slug))), f"{slug} should be retryable", ) +class HierarchicalPhaseTest(unittest.TestCase): + """Phases are hierarchical now (client/phase.py); the INNERMOST known step wins. + + This is what makes #76's misattribution impossible: a lazy sign-in nested inside + the appliance-list request no longer borrows its caller's label. + """ + + def test_flat_phases_are_unchanged(self) -> None: + for phase, expected in ( + ("load_appliances", ec.NETWORK_TIMEOUT), + ("load_appliance", ec.NETWORK_TIMEOUT), + ("connect", ec.NETWORK_TIMEOUT), + ("mqtt_connect", ec.MQTT_CONNECT_TIMEOUT), + ("mqtt_subscribe", ec.MQTT_SUBSCRIBE_TIMEOUT), + ("aws_token", ec.MQTT_CONNECT_TIMEOUT), + ): + with self.subTest(phase=phase): + self.assertIs(ec.phase_timeout_code(phase), expected) + + def test_nested_leaf_wins(self) -> None: + for phase, expected in ( + # THE #76 CASE: today ADDHON-400, now the refresh names itself. + ("load_appliances/auth/refresh", ec.REFRESH_TIMEOUT), + ("load_appliances/auth", ec.AUTH_TIMEOUT), + ("auth/mfa_verify", ec.AUTH_TIMEOUT), + ("load_appliance/auth", ec.AUTH_TIMEOUT), + ("mqtt/subscribe", ec.MQTT_SUBSCRIBE_TIMEOUT), + ): + with self.subTest(phase=phase): + self.assertIs(ec.phase_timeout_code(phase), expected) + + def test_unknown_stays_mute(self) -> None: + self.assertIs(ec.phase_timeout_code("nothing/known"), ec.LOOP_TIMEOUT) + + def test_any_future_appliance_load_step_is_a_network_timeout(self) -> None: + # The `load_appliance*` PREFIX rule is a forward-compatibility net: the two + # names in use today are in the exact table, so the rule only ever fires for a + # step someone adds later. Without it such a step falls through to the mute + # ADDHON-460 "Setup timed out" -- the answer #76 was filed about -- for a + # failure that is plainly a network timeout on an appliance request. + for phase in ("load_appliance_statistics", "load_appliances_v2"): + with self.subTest(phase=phase): + self.assertIs(ec.phase_timeout_code(phase), ec.NETWORK_TIMEOUT) + + def test_the_mqtt_start_scope_keeps_its_own_code(self) -> None: + # `NativeHon.setup()` bounds the MQTT start with MQTT_START; the scope name has + # to resolve, or the one phase that was UNBUDGETED until now would trade a + # 574s stall for a correctly fast but mute ADDHON-460. + self.assertIs(ec.phase_timeout_code("mqtt_start"), ec.MQTT_CONNECT_TIMEOUT) + self.assertIs( + ec.phase_timeout_code("mqtt_start/mqtt_subscribe"), + ec.MQTT_SUBSCRIBE_TIMEOUT, + ) + + def test_auth_timeout_is_not_an_auth_error(self) -> None: + # The reason 405/406 were chosen over 401/402: hon_client._is_auth_error looks + # for the BARE substrings "401"/"403", so a message that lost its carried code + # would turn a transient timeout into a reauth. + for code in (ec.AUTH_TIMEOUT, ec.REFRESH_TIMEOUT): + with self.subTest(code=code.label): + self.assertFalse(hc._is_auth_error(ec.HonCodedError(code))) + self.assertFalse(hc._requires_reauth(ec.HonCodedError(code))) + + +class ErrorDetailTest(unittest.TestCase): + """The doubled code of #76: "Validation failed [ADDHON-400]: ADDHON-400: ...".""" + + def test_strips_only_a_leading_code_prefix(self) -> None: + self.assertEqual( + "Network timeout contacting hOn", + ec.error_detail(ec.HonCodedError(ec.NETWORK_TIMEOUT)), + ) + self.assertEqual("boom", ec.error_detail(RuntimeError("boom"))) + # Mid-sentence citations are left alone. + self.assertEqual( + "see ADDHON-400: docs", ec.error_detail(RuntimeError("see ADDHON-400: docs")) + ) + + def test_empty_message_falls_back_to_the_type(self) -> None: + self.assertEqual("RuntimeError", ec.error_detail(RuntimeError(""))) + self.assertEqual("TimeoutError", ec.error_detail(asyncio.TimeoutError())) + + def test_code_appears_once_in_a_formatted_line(self) -> None: + err = ec.HonCodedError(ec.NETWORK_TIMEOUT) + line = f"Validation failed [{ec.NETWORK_TIMEOUT.label}]: {ec.error_detail(err)}" + self.assertEqual(1, line.count("ADDHON-")) + + +class StructuralClassifyTest(unittest.TestCase): + """TLS vs DNS vs refused decided by TYPE/errno, not by grepping the message.""" + + def test_wrapped_gaierror_is_dns_even_without_dns_words(self) -> None: + import socket + + class ClientConnectorError(OSError): + pass + + err = ClientConnectorError("cannot connect to host api.example:443") + err.os_error = socket.gaierror(-2, "boom") + # The message alone would have said "cannot connect to host" -> refused. + self.assertIs(ec.classify(err), ec.DNS_FAILURE) + + def test_real_ssl_error_is_tls_even_without_certificate_words(self) -> None: + import ssl + + self.assertIs(ec.classify(ssl.SSLError("handshake gave up")), ec.TLS_FAILURE) + + def test_wrapped_refusal_is_connection_refused(self) -> None: + class ClientConnectorError(OSError): + pass + + err = ClientConnectorError("nope") + err.os_error = ConnectionRefusedError(111, "Connection refused") + self.assertIs(ec.classify(err), ec.CONNECTION_REFUSED) + + def test_status_field_beats_the_message(self) -> None: + class ClientResponseError(Exception): + def __init__(self, status): + super().__init__("request failed") + self.status = status + + self.assertIs(ec.classify(ClientResponseError(503)), ec.SERVER_ERROR) + self.assertIs(ec.classify(ClientResponseError(429)), ec.RATE_LIMITED) + self.assertIs(ec.classify(ClientResponseError(401)), ec.INVALID_CREDENTIALS) + # Any other status falls THROUGH: a decode problem with a 200 must stay one. + self.assertIs(ec.classify(ClientResponseError(200)), ec.UNKNOWN) + + def test_order_guards_still_hold(self) -> None: + # The structural branch decides WHICH transport fault, never WHETHER: the + # rate-limit/5xx and explicit-rejection rules keep priority. + self.assertIs(ec.classify(ConnectionError("503 server error")), ec.SERVER_ERROR) + + class ClientConnectionError(ConnectionError): + pass + + self.assertIs( + ec.classify(ClientConnectionError("HTTP 401 unauthorized")), + ec.INVALID_CREDENTIALS, + ) + + class RequiresReauthCouplingTest(unittest.TestCase): def test_coded_error_routes_by_its_flag(self) -> None: self.assertTrue(hc._requires_reauth(ec.HonCodedError(ec.AUTH_LOGIN))) diff --git a/tests/test_hon_client_realtime.py b/tests/test_hon_client_realtime.py index f4302bb..8200a80 100644 --- a/tests/test_hon_client_realtime.py +++ b/tests/test_hon_client_realtime.py @@ -13,6 +13,8 @@ import asyncio import sys +import threading +import time import types import unittest from pathlib import Path @@ -125,7 +127,7 @@ async def dispatch( client._command_dispatcher = Dispatcher() # type: ignore[assignment] - def run_on_hon_loop(coro: object) -> bool: + def run_on_hon_loop(coro: object, timeout: float | None = None) -> bool: loop_calls.append(coro) return asyncio.run(coro) # type: ignore[arg-type] @@ -164,6 +166,490 @@ async def _answer(result: object = value) -> object: thread.join(timeout=5) +class LoopWatchdogAttributionTest(unittest.TestCase): + """What the dedicated-loop watchdog reports when it fires (issue #76). + + It used to throw the cancelled coroutine's exception away and rebuild a synthetic + error out of phase + code, so a failure that had a NAME arrived nameless. That is + why no hypothesis about #76 was falsifiable on a real install. + """ + + def _client(self) -> HonClient: + client = HonClient(email="e@x", password="p") + client._start_hon_loop() + + def _stop() -> None: + loop = client._hon_loop + if loop is not None: + loop.call_soon_threadsafe(loop.stop) + thread = client._hon_thread + if thread is not None: + thread.join(timeout=5) + + self.addCleanup(_stop) + return client + + def test_genuine_stall_keeps_the_phase_code(self) -> None: + from custom_components.addhon import error_codes as ec + + client = self._client() + client._hon_instance = types.SimpleNamespace( + current_phase="load_appliances", phase_summary="" + ) + + async def _forever() -> None: + await asyncio.sleep(30) + + with self.assertLogs("custom_components.addhon.hon_client", level="ERROR"): + with self.assertRaises(ec.HonCodedError) as ctx: + client._run_on_hon_loop(_forever(), 0.2) + self.assertIs(ec.NETWORK_TIMEOUT, ctx.exception.error_code) + self.assertIsInstance(ctx.exception.__cause__, TimeoutError) + + def test_nested_auth_phase_is_attributed_to_the_auth_timeout(self) -> None: + # A REAL PhaseTracker driven by REAL phase() scopes, not a frozen string. With + # a types.SimpleNamespace whose `current_phase` is a constant, this test passed + # while production still answered ADDHON-400: the scopes UNWIND when the task is + # cancelled and every phase() restores the mirror on the way out, so a mirror + # read after the drain is always "". Only a mirror that really unwinds can pin + # that the read happens BEFORE the cancellation. + from custom_components.addhon import error_codes as ec + from custom_components.addhon.client.phase import PhaseTracker, phase + + tracker = PhaseTracker() + + class _Session: + """What NativeHon exposes to the watchdog, backed by the live tracker.""" + + _setup_phase = "load_appliances" + + @property + def current_phase(self) -> str: + return tracker.current + + @property + def phase_summary(self) -> str: + return tracker.summary() + + client = self._client() + client._hon_instance = _Session() + + async def _stalls_inside_a_lazy_signin() -> None: + # The exact #76 shape: the sign-in starts inside the appliance-list request. + with phase("load_appliances", tracker): + with phase("auth/refresh", tracker): + await asyncio.sleep(30) + + with self.assertLogs("custom_components.addhon.hon_client", level="ERROR"): + with self.assertRaises(ec.HonCodedError) as ctx: + client._run_on_hon_loop(_stalls_inside_a_lazy_signin(), 0.2) + self.assertIs(ec.REFRESH_TIMEOUT, ctx.exception.error_code) + self.assertEqual("load_appliances/auth/refresh", ctx.exception.phase) + # The scopes really did unwind: the mirror is empty by now, so the code above + # could only have come from a read taken before the cancellation. + self.assertEqual("", tracker.current) + + def test_real_cause_survives_the_race_with_the_watchdog(self) -> None: + from custom_components.addhon import error_codes as ec + + client = self._client() + client._hon_instance = types.SimpleNamespace( + current_phase="load_appliances", phase_summary="" + ) + + async def _reveals_its_error_on_cancel() -> None: + # The lost race, made deterministic: the coroutine's real failure only + # surfaces once the watchdog cancels it. Before, `_drain_task` swallowed it + # into a DEBUG line and the caller got a synthetic, message-less timeout. + try: + await asyncio.sleep(30) + except asyncio.CancelledError: + raise RuntimeError("hOn server error (status 503)") from None + + with self.assertLogs("custom_components.addhon.hon_client", level="ERROR"): + with self.assertRaises(ec.HonCodedError) as ctx: + client._run_on_hon_loop(_reveals_its_error_on_cancel(), 0.2) + # The real cause, not a synthetic ADDHON-400/460. + self.assertIs(ec.SERVER_ERROR, ctx.exception.error_code) + self.assertIsInstance(ctx.exception.__cause__, RuntimeError) + + def test_a_timeout_cause_that_loses_the_race_keeps_its_phase(self) -> None: + # SAME branch as the test above, other flavour of cause. The recovered error is + # classified with `classify(original, phase=phase)`, and for a TIMEOUT the phase + # is the WHOLE answer: drop the keyword and `classify` resolves it without one, + # turning the attributed ADDHON-406 back into the mute ADDHON-460 of #76 -- on a + # failure that had a name. The sibling test uses a RuntimeError, which classify + # resolves from the message alone, so it can never see that regression. + # + # The lost race, made deterministic: the coroutine yields once, then BLOCKS the + # loop past the cap and raises a bare per-request TimeoutError. `_cancel_and_drain` + # therefore runs only after the task has already finished, which is what selects + # the drained-cause branch instead of the genuine-stall one. + import time as _time + + from custom_components.addhon import error_codes as ec + from custom_components.addhon.client.phase import PhaseTracker, phase + + tracker = PhaseTracker() + + class _Session: + _setup_phase = "load_appliances" + + @property + def current_phase(self) -> str: + return tracker.current + + @property + def phase_summary(self) -> str: + return tracker.summary() + + client = self._client() + client._hon_instance = _Session() + + async def _raises_a_bare_timeout_just_too_late() -> None: + with phase("load_appliances", tracker): + with phase("auth/refresh", tracker): + await asyncio.sleep(0.05) + _time.sleep(0.5) # blocking: the drain cannot run before the raise + raise TimeoutError() + + with self.assertLogs("custom_components.addhon.hon_client", level="ERROR"): + with self.assertRaises(ec.HonCodedError) as ctx: + client._run_on_hon_loop(_raises_a_bare_timeout_just_too_late(), 0.2) + self.assertIs(ec.REFRESH_TIMEOUT, ctx.exception.error_code) + self.assertEqual("load_appliances/auth/refresh", ctx.exception.phase) + self.assertIsInstance(ctx.exception.__cause__, TimeoutError) + + def test_a_teardown_gives_the_in_flight_caller_a_coded_error(self) -> None: + # The other side of the narrow lifecycle lock. The wait is deliberately NOT held + # under it (an unload used to queue behind the slowest in-flight call, minutes + # with these caps), so `close_sync` can now cancel the task under a waiter, and + # the waiter gets a bare, message-less concurrent.futures.CancelledError back + # from the future -- which classify can only call ADDHON-999 "Unknown error", + # with nothing anywhere saying the client was shutting down. + # + # This pins the decision between the two available semantics: the in-flight call + # is ABORTED, never waited for (waiting is the ~5-minute unload the narrow lock + # exists to prevent), and the abort is converted into an attributed, ordinary + # Exception every guard in the integration already handles. + import concurrent.futures + + from custom_components.addhon import error_codes as ec + + client = HonClient(email="e@x", password="p") + client._start_hon_loop() + client._hon_instance = types.SimpleNamespace(current_phase="", phase_summary="") + entered = threading.Event() + seen: dict[str, BaseException] = {} + + async def _slow() -> None: + entered.set() + await asyncio.sleep(30) + + def _wait() -> None: + try: + client._run_on_hon_loop(_slow(), 30) + except BaseException as err: # noqa: BLE001 - that is the point + seen["err"] = err + + worker = threading.Thread(target=_wait, daemon=True) + worker.start() + self.addCleanup(worker.join, 10) + self.assertTrue(entered.wait(5), "the coroutine never started") + + started = time.monotonic() + client._close_sync() + # The teardown does NOT wait for the in-flight call (that is the rejected + # alternative: up to APPLIANCE_POLL, ~5 minutes, with Home Assistant reporting + # the unload as slow). + self.assertLess(time.monotonic() - started, 15) + worker.join(10) + + err = seen.get("err") + self.assertIsInstance(err, ec.HonCodedError) + self.assertIs(ec.CLIENT_SHUTDOWN, err.error_code) + self.assertIsInstance(err.__cause__, concurrent.futures.CancelledError) + # It routes as a transient failure, never as a reauth prompt... + self.assertFalse(ec.CLIENT_SHUTDOWN.requires_reauth) + # ...and a real task cancellation is NOT what was swallowed: since 3.8 the two + # CancelledErrors are different classes, and only the futures one is caught. + self.assertNotIsInstance(err.__cause__, asyncio.CancelledError) + # Without the conversion this is all the caller could have been told. + self.assertIs(ec.UNKNOWN, ec.classify(err.__cause__)) + + def test_mfa_challenge_at_the_cap_propagates_naked(self) -> None: + from custom_components.addhon.client.transport.auth import MFAChallengeRequired + + client = self._client() + client._hon_instance = types.SimpleNamespace( + current_phase="load_appliances", phase_summary="" + ) + + async def _challenges_on_cancel() -> None: + try: + await asyncio.sleep(30) + except asyncio.CancelledError: + raise MFAChallengeRequired("otp") from None + + with self.assertLogs("custom_components.addhon.hon_client", level="ERROR"): + # Wrapping it in a HonCodedError would break the interactive 2FA resume. + with self.assertRaises(MFAChallengeRequired): + client._run_on_hon_loop(_challenges_on_cancel(), 0.2) + + def test_a_timeout_raised_by_the_coroutine_is_not_the_watchdog(self) -> None: + # Since Python 3.11 `concurrent.futures.TimeoutError IS asyncio.TimeoutError IS + # TimeoutError`, so a BARE per-request timeout coming out of the coroutine is + # the very type the cap raises. Caught by the cap's own clause, it produced a + # false "watchdog fired after 0.0s" on a cap that never expired and handed the + # caller the mute ADDHON-460 instead of the failure's own code -- with the + # first-poll `load_commands` rehydration (an await nothing budgets) as a live + # trigger. Told apart by STATE, not type: on a real expiry the future is still + # pending, here it has already finished. + client = self._client() + client._hon_instance = types.SimpleNamespace( + current_phase="load_appliance", phase_summary="" + ) + + async def _times_out_instantly() -> None: + raise asyncio.TimeoutError() + + with self.assertNoLogs("custom_components.addhon.hon_client", level="ERROR"): + with self.assertRaises(TimeoutError) as ctx: + client._run_on_hon_loop(_times_out_instantly(), 300) + self.assertNotIsInstance(ctx.exception, HonCodedError) + + def test_the_wait_does_not_hold_the_lifecycle_lock(self) -> None: + # The wait is not a lifecycle transition, and the caps this file passes are now + # minutes rather than the legacy 60s: holding the lock across it made an + # unload/reload (`close_sync`) and a re-login queue behind the slowest in-flight + # call, so a stalled poll blocked them for a whole APPLIANCE_POLL (~5 min) and + # Home Assistant reported the unload as slow. + client = self._client() + client._hon_instance = types.SimpleNamespace(current_phase="", phase_summary="") + entered = threading.Event() + + async def _slow() -> None: + entered.set() + await asyncio.sleep(1) + + worker = threading.Thread( + target=lambda: client._run_on_hon_loop(_slow(), 5), daemon=True + ) + worker.start() + self.addCleanup(worker.join, 10) + self.assertTrue(entered.wait(5), "the coroutine never started") + acquired = client._lifecycle_lock.acquire(timeout=0.5) + if acquired: + client._lifecycle_lock.release() + self.assertTrue(acquired, "the lifecycle lock was held across the wait") + + def test_watchdog_log_carries_the_phase_and_no_identity(self) -> None: + from custom_components.addhon import error_codes as ec + + client = self._client() + client._hon_instance = types.SimpleNamespace( + current_phase="load_appliances/auth", + phase_summary="load_appliances 0.2s timeout", + ) + + async def _forever() -> None: + await asyncio.sleep(30) + + with self.assertLogs("custom_components.addhon.hon_client", level="ERROR") as cm: + with self.assertRaises(ec.HonCodedError): + client._run_on_hon_loop(_forever(), 0.2) + blob = "\n".join(cm.output) + self.assertIn("load_appliances/auth", blob) + self.assertNotIn("@", blob) + + +class FirstPollRehydrationTest(unittest.TestCase): + """The other half of the per-appliance transport fault boundary (issue #76). + + Containing a `load_commands` failure at setup is only legitimate if the commands + come back BEFORE the platforms build their entities. They do not come back on + their own: `update()` reloads the ATTRIBUTES, the platforms call + `async_add_entities` exactly once from the first snapshot, and the integration has + no dynamic discovery -- so without this the contained appliance shipped without + select/number/switch/button/climate/fan until a manual reload. + """ + + class _Appliance: + def __init__(self) -> None: + self.unique_id = "APP-1" + self.attributes = {"parameters": {"a": 1}} + self.settings: dict = {} + self.statistics: dict = {} + self.commands: dict = {} + self.calls: list[str] = [] + self.commands_error: BaseException | None = None + + async def update(self) -> None: + self.calls.append("update") + + async def load_commands(self) -> None: + self.calls.append("load_commands") + if self.commands_error is not None: + raise self.commands_error + self.commands = {"startProgram": object()} + + class _Session: + """What NativeHon answers: the REAL predicate, not a stubbed boolean.""" + + def __init__(self, degraded) -> None: + self._degraded = degraded + + def needs_rehydration(self, appliance) -> bool: + return any(item is appliance for item in self._degraded) + + def _client(self, degraded) -> HonClient: + c = HonClient(email="e@x", password="p") + c._run_on_hon_loop = lambda coro, timeout=None: asyncio.run(coro) # type: ignore[assignment] + c._api = self._Session(degraded) + return c + + def test_a_degraded_appliance_reloads_its_commands_on_the_first_poll(self) -> None: + appliance = self._Appliance() + self._client([appliance])._update_appliance_sync(appliance) + self.assertEqual(["load_commands", "update"], appliance.calls) + self.assertTrue(appliance.commands) + + def test_a_healthy_appliance_is_not_re_requested(self) -> None: + appliance = self._Appliance() + self._client([])._update_appliance_sync(appliance) + self.assertEqual(["update"], appliance.calls) + + def test_after_the_first_poll_the_entities_are_decided_so_nothing_is_re_requested( + self, + ) -> None: + appliance = self._Appliance() + client = self._client([appliance]) + client._first_poll_done = True + client._update_appliance_sync(appliance) + self.assertEqual(["update"], appliance.calls) + + def test_a_second_failure_is_not_contained_a_second_time(self) -> None: + # It must reach the strict first-poll branch -> ConfigEntryNotReady -> Home + # Assistant retries the setup, the only path that can still produce a COMPLETE + # entity inventory. Swallowing it here would ship the crippled entry after all. + appliance = self._Appliance() + appliance.commands_error = RuntimeError("commands endpoint is down") + with self.assertRaises(RuntimeError): + self._client([appliance])._update_appliance_sync(appliance) + + def test_a_second_failure_that_times_out_is_still_attributed(self) -> None: + # The rehydration used to be the ONE await on the poll path with no budget and + # no phase around it. A per-request aiohttp timeout therefore left it BARE, and + # a bare TimeoutError carries no phase: `representative_failure` classified it + # with nothing to go on and the user got the mute ADDHON-460 "Setup timed out" + # from a cap that had not expired -- for a failure whose real name is + # ADDHON-400. It still propagates (the containment is NOT repeated), but now + # under its own code, on the phase that actually stalled. + from custom_components.addhon import error_codes as ec + + appliance = self._Appliance() + appliance.commands_error = asyncio.TimeoutError() + with self.assertRaises(HonCodedError) as ctx: + self._client([appliance])._update_appliance_sync(appliance) + self.assertIs(ec.NETWORK_TIMEOUT, ctx.exception.error_code) + self.assertEqual("load_appliance", ctx.exception.phase) + self.assertIsInstance(ctx.exception.__cause__, TimeoutError) + # And what the first poll would hand Home Assistant is that code, not the 460. + self.assertIs( + ec.NETWORK_TIMEOUT, ec.representative_failure([("x", ctx.exception)])[0] + ) + + +class SetupFailureRecordTest(unittest.TestCase): + """What a failed setup_sync leaves behind for Download Diagnostics (issue #76). + + Three fields move together, and setup_sync says so out loud: the code, the phase and + the per-phase LEDGER. The ledger is the artefact that makes a report like #76 + diagnosable without a live probe -- it is what finally answers "which phase burned + the time". `diagnostics.py` publishes it and a test pins that READER, but nothing + pinned the WRITER: delete the three lines in the client and the ledger silently + disappears from every report with the suite still green. + + The phase must come from the ERROR (hierarchical, recorded where it was raised) and + not from the flat auth mirror, which only knows the login steps -- preferring the + mirror is how a lazy sign-in got called "load_appliances" in the first place. + """ + + class _Session: + auth_phase = "login" + phase_summary = "load_appliances 0.2s timeout" + phase_ledger = [ + {"phase": "load_appliances/auth/refresh", "seconds": 0.2, "outcome": "timeout"} + ] + + def __init__(self, error: BaseException | None) -> None: + self._error = error + + async def __aenter__(self): + if self._error is not None: + raise self._error + return self + + def subscribe_updates(self, fn) -> None: + pass + + def _client(self, error: BaseException | None): + import custom_components.addhon.client.factory as factory + + session = self._Session(error) + original = factory.create_session + factory.create_session = lambda email, password, **kw: session + self.addCleanup(setattr, factory, "create_session", original) + + client = HonClient(email="e@x", password="p") + client._start_hon_loop = lambda: None # type: ignore[assignment] + client._run_on_hon_loop = lambda coro, timeout=None: asyncio.run(coro) # type: ignore[assignment] + client._close_sync = lambda: None # type: ignore[assignment] + return client + + def test_a_failed_setup_publishes_the_phase_ledger(self) -> None: + from custom_components.addhon import error_codes as ec + + client = self._client( + ec.HonCodedError(ec.REFRESH_TIMEOUT, phase="load_appliances/auth/refresh") + ) + with self.assertRaises(ec.HonCodedError): + client.setup_sync() + self.assertEqual(self._Session.phase_ledger, client.last_phase_ledger) + self.assertIs(ec.REFRESH_TIMEOUT, client.last_error_code) + + def test_the_phase_comes_from_the_error_not_from_the_auth_mirror(self) -> None: + # The session's flat mirror says "login"; the error knows it was the refresh + # nested inside the appliance-list request. The hierarchical one wins, and the + # code follows it (ADDHON-406, not the ADDHON-405 "login" would give). + from custom_components.addhon import error_codes as ec + + client = self._client( + ec.HonCodedError(ec.REFRESH_TIMEOUT, phase="load_appliances/auth/refresh") + ) + with self.assertRaises(ec.HonCodedError): + client.setup_sync() + self.assertEqual("load_appliances/auth/refresh", client.last_error_phase) + + def test_a_fresh_attempt_never_shows_the_previous_ledger(self) -> None: + # The three failure fields are cleared together at the top of setup_sync: a + # SUCCESS must not leave a report carrying the phases of an earlier failure. + from custom_components.addhon import error_codes as ec + + client = self._client(ec.HonCodedError(ec.REFRESH_TIMEOUT, phase="auth/refresh")) + with self.assertRaises(ec.HonCodedError): + client.setup_sync() + self.assertIsNotNone(client.last_phase_ledger) + + import custom_components.addhon.client.factory as factory + + factory.create_session = lambda email, password, **kw: self._Session(None) + client.setup_sync() + self.assertIsNone(client.last_phase_ledger) + self.assertIsNone(client.last_error_code) + self.assertIsNone(client.last_error_phase) + + class _FallbackAppliance: """No update() attribute -> _do_update takes the load_* fallback path directly. Records which loads ran; load_statistics can be made to raise a chosen error.""" @@ -197,7 +683,7 @@ class FallbackLoadStatisticsToleranceTest(unittest.TestCase): def _client_running(self) -> HonClient: c = HonClient(email="e@x", password="p") # Run _do_update inline instead of on the dedicated loop. - c._run_on_hon_loop = lambda coro: asyncio.run(coro) # type: ignore[assignment] + c._run_on_hon_loop = lambda coro, timeout=None: asyncio.run(coro) # type: ignore[assignment] return c def test_non_auth_load_statistics_failure_is_tolerated(self) -> None: @@ -275,7 +761,7 @@ def test_callback_rewired_after_reauth(self) -> None: c.subscribe_updates(cb) # stored on the client (no session yet) # run setup_sync offline: stub the dedicated-loop machinery c._start_hon_loop = lambda: None # type: ignore[assignment] - c._run_on_hon_loop = lambda coro: coro.close() # type: ignore[assignment] + c._run_on_hon_loop = lambda coro, timeout=None: coro.close() # type: ignore[assignment] c.setup_sync() self.assertIs(c._hon_instance, new_session) self.assertIs(new_session._notify_function, cb) # re-applied to new session @@ -294,7 +780,7 @@ def test_setup_sync_syncs_refresh_token_seed(self) -> None: try: c = HonClient(email="e@x", password="p", refresh_token="") c._start_hon_loop = lambda: None # type: ignore[assignment] - c._run_on_hon_loop = lambda coro: coro.close() # type: ignore[assignment] + c._run_on_hon_loop = lambda coro, timeout=None: coro.close() # type: ignore[assignment] self.assertEqual("", c._refresh_token) c.setup_sync() self.assertEqual("RT_LIVE", c._refresh_token) # seed adopted the live token @@ -315,7 +801,7 @@ async def _boom(): try: c = HonClient(email="e@x", password="p", refresh_token="RT_OLD") c._start_hon_loop = lambda: None # type: ignore[assignment] - c._run_on_hon_loop = lambda coro: asyncio.run(coro) # type: ignore[assignment] + c._run_on_hon_loop = lambda coro, timeout=None: asyncio.run(coro) # type: ignore[assignment] with self.assertRaises(RuntimeError): # the injected setup failure, re-raised as-is c.setup_sync() self.assertEqual("RT_OLD", c._refresh_token) # seed preserved on failure @@ -340,7 +826,7 @@ def _create(email, password, **kw): try: c = HonClient(email="e@x", password="p", refresh_token="") c._start_hon_loop = lambda: None # type: ignore[assignment] - c._run_on_hon_loop = lambda coro: coro.close() # type: ignore[assignment] + c._run_on_hon_loop = lambda coro, timeout=None: coro.close() # type: ignore[assignment] c.setup_sync() # build #1 seeded with "" c.setup_sync() # build #2 must be seeded with RT1 (the 1st session's token) self.assertEqual(["", "RT1"], seen) @@ -358,7 +844,7 @@ def test_setup_sync_empty_live_token_keeps_seed(self) -> None: try: c = HonClient(email="e@x", password="p", refresh_token="RT_OLD") c._start_hon_loop = lambda: None # type: ignore[assignment] - c._run_on_hon_loop = lambda coro: coro.close() # type: ignore[assignment] + c._run_on_hon_loop = lambda coro, timeout=None: coro.close() # type: ignore[assignment] c.setup_sync() self.assertEqual("RT_OLD", c._refresh_token) # fallback kept the good seed finally: @@ -397,7 +883,7 @@ def test_setup_sync_without_subscribe_does_not_crash(self) -> None: try: c = HonClient(email="e@x", password="p") # never subscribed c._start_hon_loop = lambda: None # type: ignore[assignment] - c._run_on_hon_loop = lambda coro: coro.close() # type: ignore[assignment] + c._run_on_hon_loop = lambda coro, timeout=None: coro.close() # type: ignore[assignment] c.setup_sync() # must NOT raise self.assertIs(c._hon_instance, new_session) self.assertIsNone(new_session._notify_function) # nothing to apply @@ -422,7 +908,7 @@ async def __aenter__(self): cb = lambda _a: None # noqa: E731 c.subscribe_updates(cb) c._start_hon_loop = lambda: None # type: ignore[assignment] - c._run_on_hon_loop = lambda coro: asyncio.run(coro) # type: ignore[assignment] + c._run_on_hon_loop = lambda coro, timeout=None: asyncio.run(coro) # type: ignore[assignment] with self.assertRaises(RuntimeError): c.setup_sync() self.assertIsNone(c._hon_instance) # _close_sync ran on failure @@ -621,6 +1107,37 @@ async def fake_get_appliances(): self.assertNotIn(nick1, str(ctx.exception)) # nor the raised coded error self.assertNotIn(nick2, str(ctx.exception)) + def test_the_all_failed_wrapper_forwards_the_phase_of_its_cause(self) -> None: + # `__init__.py` reads `phase` off the wrapper and never walks `__cause__`, so a + # wrapper that drops it files phase=null in Download Diagnostics for a cause that + # knew where it died. The first-poll twin already forwards it; this is the + # steady-state sibling that used to lose it. + from custom_components.addhon import error_codes as ec + + app = types.SimpleNamespace( + mac_address="AA:BB:CC:DD:EE:11", unique_id="AA:BB:CC:DD:EE:11", + appliance_type="REF", nick_name="n", + attributes={}, settings={}, statistics={}, + ) + c = HonClient(email="e@x", password="p") + c._first_poll_done = True + + async def fake_get_appliances(): + return [app] + + coded = ec.HonCodedError(ec.NETWORK_TIMEOUT, phase="load_appliance/auth") + + def boom(_appliance): + raise coded + + c.async_get_appliances = fake_get_appliances # type: ignore[assignment] + c._update_appliance_sync = boom # type: ignore[assignment] + + with self.assertRaises(HonCodedError) as ctx: + asyncio.run(c.async_get_appliances_data()) + self.assertIs(coded, ctx.exception.__cause__) + self.assertEqual("load_appliance/auth", ctx.exception.phase) + class RealtimeWiringSourceGuard(unittest.TestCase): """The cross-thread wiring in async_setup_entry can't be exercised by the stub diff --git a/tests/test_native_session.py b/tests/test_native_session.py index 75c833a..4730290 100644 --- a/tests/test_native_session.py +++ b/tests/test_native_session.py @@ -61,6 +61,7 @@ def _install_stubs() -> None: _install_stubs() +from custom_components.addhon import error_codes as ec # noqa: E402 from custom_components.addhon.client import factory # noqa: E402 from custom_components.addhon.client import session as session_mod # noqa: E402 from custom_components.addhon.client.session import NativeHon # noqa: E402 @@ -240,15 +241,26 @@ def test_setup_loads_each_appliance_then_mqtt_last(self) -> None: self.assertEqual([a.mac_address for a in nh.appliances], ["A", "B"]) self.assertEqual(h.events[0], "load_appliances") self.assertEqual(h.events[-1], "mqtt") - # for each appliance: cmd -> attr -> stat, and all BEFORE mqtt + # for each appliance: cmd -> attr, and all BEFORE mqtt. load_statistics is NOT + # part of setup any more (#76): the first coordinator refresh redoes it before + # any platform is forwarded, so loading it here only spent 2 extra sequential + # round-trips per appliance inside the budget we were overflowing. self.assertEqual( h.events, ["load_appliances", - "cmd:A:0", "attr:A:0", "stat:A:0", - "cmd:B:0", "attr:B:0", "stat:B:0", + "cmd:A:0", "attr:A:0", + "cmd:B:0", "attr:B:0", "mqtt"], ) + def test_setup_never_calls_load_statistics(self) -> None: + data = [{"macAddress": "A", "applianceTypeName": "REF"}] + h = _Harness(self, data) + h.install() + nh = self._nh_with_api(h) + _run(nh.setup()) + self.assertEqual([e for e in h.events if e.startswith("stat:")], []) + def test_zone_appliance_split(self) -> None: data = [{"macAddress": "Z", "applianceTypeName": "AC", "zone": "2"}] h = _Harness(self, data) @@ -543,6 +555,187 @@ async def fake_make_mqtt(hon): with self.assertRaises(asyncio.CancelledError): _run(nh.setup()) + def test_transport_error_on_one_appliance_keeps_the_others(self) -> None: + # #76 cause 4. asyncio.TimeoutError derives from OSError, not from any of the + # five _APPLIANCE_BUILD_ERRORS, so it used to escape _create_appliance, unwind + # setup() and tear the whole config entry down. One slow device must now be + # contained: it is kept with partial data and the others still load. + class SlowAppliance(FakeAppliance): + async def load_commands(self) -> None: + self.events.append(f"cmd:{self.mac_address}:{self.zone}") + raise asyncio.TimeoutError() + + bad = {"macAddress": "BAD", "applianceTypeName": "REF"} + good = {"macAddress": "OK", "applianceTypeName": "WM"} + h = _Harness(self, [bad, good]) + + def fake_create_appliance(api, data, zone=0): + cls = SlowAppliance if data.get("macAddress") == "BAD" else FakeAppliance + return cls(api, data, zone, h.events) + + async def fake_make_mqtt(hon): + h.events.append("mqtt") + return FakeMqtt(h) + + self._patch(factory, "create_appliance", fake_create_appliance) + self._patch(NativeHon, "_make_mqtt", fake_make_mqtt) + nh = self._nh_with_api(h) + with self.assertLogs(session_mod._LOGGER, level="WARNING") as cm: + _run(nh.setup()) + self.assertEqual([a.mac_address for a in nh.appliances], ["BAD", "OK"]) + self.assertIn("cmd:OK:0", h.events) + self.assertEqual(h.events[-1], "mqtt") + self.assertEqual(["BAD#0"], list(nh.degraded_appliances)) + # The WARNING is not gated by the debug toggles -> it lands in + # home-assistant.log and must be leak-proof: code label + count, no mac. + blob = "\n".join(cm.output) + self.assertNotIn("BAD", blob) + + def test_auth_error_during_hydration_still_aborts_setup(self) -> None: + # Containing a transport fault must NOT swallow a credentials rejection: it has + # to reach _raise_setup_error and open the reauth flow. + class RejectedAppliance(FakeAppliance): + async def load_commands(self) -> None: + raise NativeAuthError("api_auth: status 401") + + data = [{"macAddress": "A", "applianceTypeName": "REF"}] + h = _Harness(self, data) + + def fake_create_appliance(api, data, zone=0): + return RejectedAppliance(api, data, zone, h.events) + + self._patch(factory, "create_appliance", fake_create_appliance) + self._patch(NativeHon, "_make_mqtt", lambda hon: None) + nh = self._nh_with_api(h) + with self.assertRaises(NativeAuthError): + _run(nh.setup()) + + def test_all_appliances_failing_hydration_raises_the_real_cause(self) -> None: + # Containing ONE appliance is a degradation; containing ALL of them would be a + # masked failure that ships an empty integration. And it must carry the REAL + # cause: a generic ADDHON-220 with no __cause__ threw away the only code that + # tells the user (and Download Diagnostics) what actually happened -- the loss + # CR#6 had already fixed on the poll path. + class SlowAppliance(FakeAppliance): + async def load_commands(self) -> None: + raise asyncio.TimeoutError() + + data = [ + {"macAddress": "A", "applianceTypeName": "REF"}, + {"macAddress": "B", "applianceTypeName": "WM"}, + ] + h = _Harness(self, data) + + def fake_create_appliance(api, data, zone=0): + return SlowAppliance(api, data, zone, h.events) + + self._patch(factory, "create_appliance", fake_create_appliance) + self._patch(NativeHon, "_make_mqtt", lambda hon: None) + nh = self._nh_with_api(h) + with self.assertLogs(session_mod._LOGGER, level="WARNING"): + with self.assertRaises(session_mod.HonCodedError) as ctx: + _run(nh.setup()) + self.assertIs(ec.NETWORK_TIMEOUT, ctx.exception.error_code) + # The chain reaches the original exception, not a synthetic replacement. + chain, cause = [], ctx.exception.__cause__ + while cause is not None and len(chain) < 5: + chain.append(cause) + cause = cause.__cause__ + self.assertTrue( + any(isinstance(link, asyncio.TimeoutError) for link in chain), + f"the real cause is gone: {chain}", + ) + # Never identity, not even in the "which appliances" message. + self.assertNotIn("A", str(ctx.exception).replace("ADDHON", "")) + # And it says WHERE. `HonClient.setup_sync` prefers the phase the error carries + # over the flat auth mirror, and `__init__.py` reads it straight off this + # exception -- drop the keyword and the one report that could have named the + # step shows a null phase instead. + self.assertEqual("load_appliance", ctx.exception.phase) + + def test_a_mixed_inventory_of_partial_appliances_still_fails(self) -> None: + # The under-count the guard used to have: one appliance MALFORMED (counted + # nowhere) plus one killed by a transport fault read as "1 failure out of 2" + # and shipped an entry whose every device was unusable. + class Broken(FakeAppliance): + async def load_commands(self) -> None: + if self.mac_address == "A": + raise KeyError("malformed payload") + raise asyncio.TimeoutError() + + data = [ + {"macAddress": "A", "applianceTypeName": "REF"}, + {"macAddress": "B", "applianceTypeName": "WM"}, + ] + h = _Harness(self, data) + + def fake_create_appliance(api, data, zone=0): + return Broken(api, data, zone, h.events) + + self._patch(factory, "create_appliance", fake_create_appliance) + self._patch(NativeHon, "_make_mqtt", lambda hon: None) + nh = self._nh_with_api(h) + with self.assertLogs(session_mod._LOGGER, level="WARNING"): + with self.assertRaises(session_mod.HonCodedError): + _run(nh.setup()) + + def test_an_only_malformed_inventory_still_ships_degraded(self) -> None: + # The other side of the same rule: raising means "Home Assistant, retry". A + # payload the parser cannot read will parse the same way next time, so failing + # forever would leave the user with LESS than the degraded entry that ships + # today (attributes still work, only the commands are missing). + data = [{"macAddress": "A", "applianceTypeName": "REF"}] + h = _Harness(self, data, fail_macs={"A"}) + h.install() + nh = self._nh_with_api(h) + _run(nh.setup()) + self.assertEqual(1, len(nh.appliances)) + self.assertFalse(nh.needs_rehydration(nh.appliances[0])) + + def test_a_transport_degraded_appliance_is_queued_for_rehydration(self) -> None: + # Containing the fault is only legitimate because the first poll re-runs + # load_commands before any entity is created (hon_client). + class SlowAppliance(FakeAppliance): + async def load_commands(self) -> None: + if self.mac_address == "B": + raise asyncio.TimeoutError() + await super().load_commands() + + data = [ + {"macAddress": "A", "applianceTypeName": "REF"}, + {"macAddress": "B", "applianceTypeName": "WM"}, + ] + h = _Harness(self, data) + + async def no_mqtt(hon): + return None + + def fake_create_appliance(api, data, zone=0): + return SlowAppliance(api, data, zone, h.events) + + self._patch(factory, "create_appliance", fake_create_appliance) + self._patch(NativeHon, "_make_mqtt", no_mqtt) + nh = self._nh_with_api(h) + with self.assertLogs(session_mod._LOGGER, level="WARNING"): + _run(nh.setup()) + by_mac = {app.mac_address: app for app in nh.appliances} + self.assertTrue(nh.needs_rehydration(by_mac["B"])) + self.assertFalse(nh.needs_rehydration(by_mac["A"])) + + def test_setup_exposes_a_phase_ledger(self) -> None: + data = [{"macAddress": "A", "applianceTypeName": "REF"}] + h = _Harness(self, data) + h.install() + nh = self._nh_with_api(h) + _run(nh.setup()) + phases = [entry["phase"] for entry in nh.phase_ledger] + self.assertIn("load_appliances", phases) + self.assertIn("load_appliance", phases) + self.assertTrue(all(entry["outcome"] == "ok" for entry in nh.phase_ledger)) + # Cleared after a clean setup: the hierarchical mirror follows the flat one. + self.assertEqual("", nh.current_phase) + self.assertNotIn("@", nh.phase_summary) + def test_log_malformed_tolerates_unorderable_keys(self) -> None: # _log_malformed runs INSIDE the except handlers, so it must NEVER raise: a # raise there would escape and abort the whole setup loop -- the very failure diff --git a/tests/test_phase_context.py b/tests/test_phase_context.py new file mode 100644 index 0000000..4eb2630 --- /dev/null +++ b/tests/test_phase_context.py @@ -0,0 +1,337 @@ +# Copyright (C) 2026 tis24dev +# SPDX-License-Identifier: AGPL-3.0-or-later + +"""The hierarchical, transported setup phase (issue #76). + +Pure test: `client/phase.py` imports nothing but the stdlib, so no Home Assistant / +aiohttp stubs are needed here. The behaviour that matters is the RESTORE on exit -- +that is what stops a nested re-login from leaving the phase pointing at the auth +layer for the rest of the setup. +""" +from __future__ import annotations + +import asyncio +import sys +import unittest +from pathlib import Path + +REPO = Path(__file__).resolve().parents[1] +if str(REPO) not in sys.path: + sys.path.insert(0, str(REPO)) +if str(REPO / "tests") not in sys.path: + sys.path.insert(0, str(REPO / "tests")) + +from _golden import install_stubs # noqa: E402 + +# phase.py itself is pure stdlib; the stubs are only needed because importing it goes +# through the package __init__, which imports Home Assistant. +install_stubs() + +from custom_components.addhon.client.phase import ( # noqa: E402 + PhaseTracker, + current_phase, + phase, +) + + +class PhaseCompositionTest(unittest.TestCase): + def test_nesting_composes_and_restores(self) -> None: + tracker = PhaseTracker() + self.assertEqual("", current_phase()) + with phase("load_appliances", tracker): + self.assertEqual("load_appliances", current_phase()) + self.assertEqual("load_appliances", tracker.current) + with phase("auth/refresh", tracker): + # The exact shape #76 could not express: the lazy sign-in nested inside + # the appliance-list request names ITSELF. + self.assertEqual("load_appliances/auth/refresh", current_phase()) + self.assertEqual("load_appliances/auth/refresh", tracker.current) + # Restored -- the whole point. + self.assertEqual("load_appliances", current_phase()) + self.assertEqual("load_appliances", tracker.current) + self.assertEqual("", current_phase()) + self.assertEqual("", tracker.current) + + def test_restore_happens_on_exception_too(self) -> None: + tracker = PhaseTracker() + with phase("load_appliances", tracker): + with self.assertRaises(RuntimeError): + with phase("auth", tracker): + raise RuntimeError("boom") + self.assertEqual("load_appliances", current_phase()) + + def test_step_refines_the_mirror_without_pushing(self) -> None: + tracker = PhaseTracker() + with phase("load_appliances", tracker): + with phase("auth", tracker): + tracker.step("introduce") + self.assertEqual("load_appliances/auth/introduce", tracker.current) + # The ContextVar is untouched: `step` is a mirror refinement only. + self.assertEqual("load_appliances/auth", current_phase()) + # Leaving the scope wipes the refinement; it can never outlive its scope. + self.assertEqual("load_appliances", tracker.current) + + def test_gather_siblings_do_not_pollute_each_other(self) -> None: + tracker = PhaseTracker() + seen: dict[str, str] = {} + + async def worker(name: str) -> None: + with phase(name, tracker): + await asyncio.sleep(0) + seen[name] = current_phase() + + async def main() -> None: + with phase("load_appliance", tracker): + await asyncio.gather(worker("a"), worker("b"), worker("c")) + # The ContextVar of THIS task is untouched by the children. + self.assertEqual("load_appliance", current_phase()) + + asyncio.run(main()) + self.assertEqual( + { + "a": "load_appliance/a", + "b": "load_appliance/b", + "c": "load_appliance/c", + }, + seen, + ) + + +class EveryAuthEntryPointOpensAScopeTest(unittest.TestCase): + """No auth entry point may refine the mirror without a scope to restore it. + + `PhaseTracker.step()` (which the auth layer's markers use) writes the mirror + directly; only the enclosing `phase()` puts back what it found. An entry point that + reaches the auth layer WITHOUT a scope therefore leaves the mirror pointing at its + last step for the life of the client -- and `_run_on_hon_loop` prefers that + hierarchical mirror to the flat one, so the stale value SHIELDS the accurate one and + every later expiry collapses to the mute ADDHON-460 (issue #76 attribution). + + `resend_mfa_code` was that entry point, and it is not an edge case: the config flow + calls it on EVERY entry into the 2FA step, not only on a resend. + """ + + def _connection(self, tracker: PhaseTracker): + from custom_components.addhon.client.transport.connection import HonConnection + + class _Auth: + """Only what the entry points touch, and the mirror write they really do.""" + + cognito_token = "cog" + id_token = "id" + refresh_token = "rt" + + async def resend_mfa_code(self, context) -> None: + tracker.step("mfa_send") + + connection = HonConnection("e@x", "p", session=object(), phase_tracker=tracker) + connection._auth = _Auth() + return connection + + def test_the_otp_resend_restores_the_mirror(self) -> None: + tracker = PhaseTracker() + connection = self._connection(tracker) + + asyncio.run(connection.resend_mfa_code(object())) + + self.assertEqual("", tracker.current) + self.assertEqual("", current_phase()) + # It still HAPPENED, and under its own name: a later expiry inside the resend is + # attributed to mfa_send, not borrowed from whatever ran before it. + self.assertIn("auth/mfa_send", [entry["phase"] for entry in tracker.entries()]) + + def test_a_later_scope_is_not_shielded_by_the_resend(self) -> None: + tracker = PhaseTracker() + connection = self._connection(tracker) + + asyncio.run(connection.resend_mfa_code(object())) + with phase("load_appliances", tracker): + self.assertEqual("load_appliances", tracker.current) + self.assertEqual("", tracker.current) + + +class TheTrackerReachesTheAuthLayerTest(unittest.TestCase): + """The mirror is a cross-thread channel only if it is the SAME object end to end. + + `NativeHon.current_phase` -- the value `HonClient._run_on_hon_loop` reads from + ANOTHER thread to attribute an expired cap -- is `NativeHon._phase_tracker.current`. + The login runs two layers down (session -> connection -> auth) and refines that + mirror through `PhaseTracker.step()`. Give any layer a tracker of its own and the + refinement lands where nobody reads it: the watchdog falls back to the FLAT mirror, + which still says "load_appliances" for a stalled sign-in -- ADDHON-400, #76 itself. + Each hop is one keyword argument, and none of the three was pinned. + """ + + def _session(self): + from custom_components.addhon.client.session import NativeHon + + hon = NativeHon( + email="e@x", + password="p", + session=object(), # the network boundary, never touched here + enable_mqtt=False, + minimal=True, + ) + + async def _no_network() -> None: + return None + + hon.setup = _no_network # type: ignore[assignment] + return hon + + def test_a_login_step_names_itself_on_the_session_mirror(self) -> None: + hon = self._session() + asyncio.run(hon.create()) + connection = hon._connection + + # Real NativeHon -> real HonConnection -> real HonAuth, one object throughout. + self.assertIs(hon._phase_tracker, connection._phase_tracker) + self.assertIs(hon._phase_tracker, connection.auth._phase_tracker) + + # And the refinement the auth layer really writes composes under whatever scope + # the session has open, which is what makes a lazy sign-in say where it is. + with phase("load_appliances", hon._phase_tracker): + connection.auth._phase("introduce") + self.assertEqual("load_appliances/introduce", hon.current_phase) + self.assertEqual("", hon.current_phase) + + +class PhaseScopeTableIsCompleteTest(unittest.TestCase): + """Freeze the SET and the NAMES of the phase scopes, the way the caps are frozen. + + The name is not cosmetic: `error_codes.phase_timeout_code` resolves it segment by + segment from the leaf outwards, so "auth/refresh" is ADDHON-406 while a scope + renamed "auth" is ADDHON-405, and a name nobody put in the table falls through to + the mute ADDHON-460. A behavioural test only covers the scopes someone remembered; + this covers the ones nobody did, and makes a NEW scope a deliberate choice. + """ + + EXPECTED = { + "session.py": { + "setup": ["load_appliances", "mqtt_start"], + "_create_appliance": ["load_appliance"], + }, + "connection.py": { + "_check_headers": ["auth/refresh", "auth"], + "_refresh_after_rejection": ["auth/refresh"], + "_reauth_after_rejection": ["auth"], + "submit_mfa_code": ["auth/mfa_verify"], + "resend_mfa_code": ["auth/mfa_send"], + }, + "hon_client.py": { + # The first-poll rehydration, under the same name `_build_appliance` uses + # for the identical call at setup. + "_do_update": ["load_appliance"], + }, + } + + @staticmethod + def _scopes(module) -> dict: + import ast + + tree = ast.parse(Path(module.__file__).read_text(encoding="utf-8")) + found: dict[str, list[str]] = {} + + def visit(node, owner: str) -> None: + for child in ast.iter_child_nodes(node): + if isinstance(child, (ast.FunctionDef, ast.AsyncFunctionDef)): + visit(child, child.name) + continue + if ( + isinstance(child, ast.Call) + and isinstance(child.func, ast.Name) + # `hon_client` imports it aliased, so the local `phase` variable it + # binds for the attribution cannot shadow the scope factory. + and child.func.id in ("phase", "phase_scope") + and child.args + and isinstance(child.args[0], ast.Constant) + ): + found.setdefault(owner, []).append(child.args[0].value) + visit(child, owner) + + visit(tree, "") + return found + + def test_every_phase_scope_is_pinned_to_its_name(self) -> None: + from custom_components.addhon import hon_client as hon_client_mod + from custom_components.addhon.client import session as session_mod + from custom_components.addhon.client.transport import connection as conn_mod + + for module in (session_mod, conn_mod, hon_client_mod): + name = Path(module.__file__).name + with self.subTest(module=name): + self.assertEqual(self.EXPECTED[name], self._scopes(module)) + + def test_every_scope_name_resolves_to_a_code_of_its_own(self) -> None: + # The other half: a name that the table does not know collapses to the mute + # ADDHON-460 "Setup timed out" -- the answer #76 was filed about. Whatever the + # table above says, every scope must resolve to something more specific. + from custom_components.addhon import error_codes as ec + + names = { + name + for scopes in self.EXPECTED.values() + for entries in scopes.values() + for name in entries + } + for name in sorted(names): + with self.subTest(scope=name): + self.assertIsNot(ec.LOOP_TIMEOUT, ec.phase_timeout_code(name)) + + +class PhaseLedgerTest(unittest.TestCase): + def test_ledger_records_outcome_per_phase(self) -> None: + tracker = PhaseTracker() + with phase("load_appliances", tracker): + pass + with self.assertRaises(TimeoutError): + with phase("load_appliance", tracker): + raise TimeoutError() + with self.assertRaises(ValueError): + with phase("auth", tracker): + raise ValueError("nope") + + outcomes = [(e["phase"], e["outcome"]) for e in tracker.entries()] + self.assertEqual( + [ + ("load_appliances", "ok"), + ("load_appliance", "timeout"), + ("auth", "error"), + ], + outcomes, + ) + for entry in tracker.entries(): + self.assertIsInstance(entry["seconds"], float) + + def test_an_unnamed_budget_expiry_is_still_filed_as_a_timeout(self) -> None: + # A budgeted scope converts its expiry INSIDE this scope, so `phase()` never + # sees the bare TimeoutError -- it sees a HonCodedError and decides the outcome + # from `PHASE_TIMEOUT_CODES`. LOOP_TIMEOUT is a member of that set for a reason: + # it is what a scope whose name the table does not resolve produces, and it is + # exactly the case a report needs to see as "timeout" rather than a generic + # 'error' -- the ledger is the artefact that makes a #76 report diagnosable. + from custom_components.addhon.error_codes import LOOP_TIMEOUT, HonCodedError + + tracker = PhaseTracker() + with self.assertRaises(HonCodedError): + with phase("something_new", tracker): + raise HonCodedError(LOOP_TIMEOUT, phase="something_new") + self.assertEqual( + [("something_new", "timeout")], + [(e["phase"], e["outcome"]) for e in tracker.entries()], + ) + + def test_ledger_is_leak_proof_and_bounded(self) -> None: + tracker = PhaseTracker() + for index in range(60): + with phase(f"step{index}", tracker): + pass + entries = tracker.entries() + self.assertLessEqual(len(entries), 40) + blob = tracker.summary() + self.assertNotIn("@", blob) + self.assertNotIn("http", blob) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_program_select.py b/tests/test_program_select.py index 0c42649..bbb061e 100644 --- a/tests/test_program_select.py +++ b/tests/test_program_select.py @@ -784,7 +784,7 @@ async def load_statistics(self) -> None: appliance = Appliance() client = HonClient(email="user@example.com", password="secret") - client._run_on_hon_loop = lambda coro: asyncio.run(coro) + client._run_on_hon_loop = lambda coro, timeout=None: asyncio.run(coro) client._update_appliance_sync(appliance) diff --git a/tests/test_setup_budgets.py b/tests/test_setup_budgets.py new file mode 100644 index 0000000..964eab8 --- /dev/null +++ b/tests/test_setup_budgets.py @@ -0,0 +1,892 @@ +# Copyright (C) 2026 tis24dev +# SPDX-License-Identifier: AGPL-3.0-or-later + +"""Per-phase budgets and the attribution they buy (issue #76). + +The reported symptom was "Validation failed [ADDHON-400]: ADDHON-400: Network +timeout contacting hOn" from the config flow. It was produced by ONE cumulative 60s +cap covering the whole setup, expiring while the LAZY sign-in was still running, and +being attributed to `load_appliances` -- the label the caller had written down before +the request that triggered the login. + +EVERY reproduction here enters from `NativeHon.setup()`. That is not a stylistic +preference: the first attempt at #76 shipped with a green suite because its +"reproduction" called `connection._check_headers` under a bare `phase()` scope, +WITHOUT the `budgeted(APPLIANCE_LIST)` that `setup()` wraps around it -- so it +verified a nesting production never builds, while production went on answering +ADDHON-400. The nesting IS the contract, so the test has to build it the way +`setup()` does, from `setup()`. + +The doubles stop at the network: a fake `aiohttp.ClientSession` and a stalling +`HonAuth`. Everything between `setup()` and them -- `HonApi`, `HonConnection._intercept`, +`_check_headers`, the phase scopes, the budgets -- is the shipped code. +""" +from __future__ import annotations + +import asyncio +import sys +import time +import unittest +from pathlib import Path + +REPO = Path(__file__).resolve().parents[1] +if str(REPO) not in sys.path: + sys.path.insert(0, str(REPO)) +if str(REPO / "tests") not in sys.path: + sys.path.insert(0, str(REPO / "tests")) + +from _golden import install_stubs # noqa: E402 + +install_stubs() + +from custom_components.addhon import error_codes as ec # noqa: E402 +from custom_components.addhon.client import budget # noqa: E402 +from custom_components.addhon.client import session as session_mod # noqa: E402 +from custom_components.addhon.client.budget import budgeted # noqa: E402 +from custom_components.addhon.client.transport import connection as conn_mod # noqa: E402 +from custom_components.addhon.client.transport.api import HonApi # noqa: E402 +from custom_components.addhon.client.transport.connection import ( # noqa: E402 + HonConnection, +) +from custom_components.addhon.client.session import NativeHon # noqa: E402 + +# Everything is scaled by the SAME factor, so the ORDERING of the budgets -- the only +# thing under test -- is preserved while a stall costs milliseconds instead of minutes. +# A stall is expressed as a sleep far longer than ANY budget (STALL below), so what a +# test measures is which budget fires, never how long the fake slept. +STALL = 30 +SCALE = 0.005 +# A slow POST for the case ADDHON-400 was always right for. Far over APPLIANCE_LIST +# (40 * SCALE = 0.2s) so the budget is what fires, and short enough that DELETING that +# budget turns the reproduction into a fast failure instead of a hang. +SLOW_POST = 1.0 + + +def _run(coro): + return asyncio.run(coro) + + +class _StallingAuth: + """The Salesforce flow, reduced to its timing. Doubles the NETWORK, nothing else.""" + + def __init__( + self, + refresh_seconds: float = 0.0, + auth_seconds: float = 0.0, + *, + signed_in: bool = False, + ) -> None: + # `signed_in`: usable tokens already in RAM, so `_check_headers` opens NO scope + # of its own and whatever happens next is the 401 recovery ladder alone. + self.cognito_token = "cog" if signed_in else "" + self.id_token = "id" if signed_in else "" + self.refresh_token = "rt" + self.token_expires_soon = False + self.token_is_expired = False + self._refresh_seconds = refresh_seconds + self._auth_seconds = auth_seconds + self.calls: list[str] = [] + + async def refresh(self, refresh_token: str = "") -> bool: + self.calls.append("refresh") + if self._refresh_seconds: + await asyncio.sleep(self._refresh_seconds) + self.cognito_token = "cog" + self.id_token = "id" + return True + + async def authenticate(self) -> None: + self.calls.append("authenticate") + if self._auth_seconds: + await asyncio.sleep(self._auth_seconds) + self.cognito_token = "cog" + self.id_token = "id" + + +class _Resp: + """An appliance-list response with one appliance; `status`/`delay` script the wire.""" + + def __init__(self, status: int = 200, delay: float = 0.0) -> None: + self.status = status + self._delay = delay + + async def json(self, content_type=None): + return { + "modules": { + "applianceList": { + "payload": { + "appliances": [ + {"macAddress": "AA", "applianceTypeName": "WM"} + ] + } + } + } + } + + async def __aenter__(self): + # The stall belongs HERE: aiohttp hands back the response object once the + # headers are in, so a slow endpoint is slow to enter, not slow to decode. + if self._delay: + await asyncio.sleep(self._delay) + return self + + async def __aexit__(self, *a): + return False + + +class _Session: + """Fake aiohttp.ClientSession: the real boundary, and the only other double. + + `statuses` scripts the wire per request -- a 401 is what drives the recovery ladder + in `_intercept` (refresh, then re-login), the path a runtime token rejection takes. + """ + + def __init__(self, statuses: tuple[int, ...] = (), delay: float = 0.0) -> None: + self.requests: list[str] = [] + self._statuses = list(statuses) + self._delay = delay + + def _resp(self, url, **kw): + self.requests.append(str(url)) + status = self._statuses.pop(0) if self._statuses else 200 + return _Resp(status=status, delay=self._delay) + + def get(self, url, **kw): + return self._resp(url, **kw) + + def post(self, url, **kw): + return self._resp(url, **kw) + + +class _KeepsItsAuthOnCreate(HonConnection): + """A connection whose `create()` does not mint a real `HonAuth`. + + The re-login rung of the 401 ladder calls `create()`, which would replace the + injected double with a real `HonAuth` driving the fake session through a Salesforce + flow it does not script. Overriding it keeps the double where every other test in + this file puts it -- at the network -- while `_intercept`, the ladder, the phase + scopes and the budgets remain the shipped code. + """ + + async def create(self) -> "HonConnection": + return self + + +class SetupHarness: + """A REAL NativeHon over a real HonApi/HonConnection, with the network faked.""" + + def __init__( + self, + test: unittest.TestCase, + auth: _StallingAuth, + refresh_token: str, + *, + session: _Session | None = None, + connection_class: type = HonConnection, + ): + test.scale_budgets() + self.session = session if session is not None else _Session() + self.auth = auth + self.hon = NativeHon( + email="e@x", password="p", enable_mqtt=False, minimal=True + ) + connection = connection_class( + "e@x", "p", session=self.session, phase_tracker=self.hon._phase_tracker + ) + connection._auth = auth + connection._refresh_token = refresh_token + self.hon._connection = connection + self.hon._api = HonApi(connection) + + def setup(self): + return _run(self.hon.setup()) + + +class _ScaledBudgets(unittest.TestCase): + """Shrinks every budget by SCALE, in every module that imported one by name.""" + + def scale_budgets(self) -> None: + for module, names in ( + (conn_mod, ("AUTH_FULL", "AUTH_REFRESH", "MFA_RESUME")), + (session_mod, ("APPLIANCE_LIST", "APPLIANCE_ONE", "MQTT_START")), + ): + for name in names: + original = getattr(module, name) + setattr(module, name, original * SCALE) + self.addCleanup(setattr, module, name, original) + + +class BudgetModelTest(unittest.TestCase): + """Freeze the formula and the two-kinds-of-number model, not typed constants.""" + + def test_formula(self) -> None: + self.assertEqual(40, budget.budget(1)) + self.assertEqual(60, budget.budget(3)) + self.assertEqual(120, budget.budget(9)) + # The retry term is what keeps the budget from killing the retry just before + # it is needed (transport/retry.py shares these constants). + self.assertEqual( + budget.budget(9) + 2 * (budget.TOTAL_TIMEOUT + budget.RETRY_DELAY), + budget.AUTH_FULL, + ) + + def test_budget_never_fires_before_a_single_hop(self) -> None: + # The invariant the tail margin exists for: one stuck request must expire on + # its OWN aiohttp timeout (attributed, with a message), never on the budget. + for value in ( + budget.AUTH_FULL, + budget.AUTH_REFRESH, + budget.APPLIANCE_LIST, + budget.APPLIANCE_ONE, + budget.MFA_RESUME, + ): + self.assertGreater(value, budget.TOTAL_TIMEOUT) + + def test_lazy_auth_is_the_whole_sign_in_ladder(self) -> None: + # _check_headers tries the refresh and then falls back to the full login, in + # that order, so what a lazy sign-in can cost is their SUM. + self.assertEqual(budget.AUTH_REFRESH + budget.AUTH_FULL, budget.LAZY_AUTH) + + def test_every_cap_contains_one_lazy_sign_in(self) -> None: + # A cap is waited on from ANOTHER thread (a concurrent.futures.Future), so it + # cannot be suspended the way a scope budget is: it has to CONTAIN the sign-in + # a request may start, or it fires first and destroys the attribution -- the + # #76 failure mode, one level up. + for name in ("VALIDATION_CAP", "SETUP_CAP", "COMMAND", "APPLIANCE_POLL"): + with self.subTest(cap=name): + self.assertGreaterEqual( + getattr(budget, name), budget.LAZY_AUTH + budget.budget(1) + ) + # Teardown is the exception on purpose: it must never wait like a setup. + self.assertLess(budget.CLOSE, budget.VALIDATION_CAP) + + def test_the_command_cap_no_longer_truncates_the_refresh_it_waits_for(self) -> None: + # It was budget(1) = 40s, TIGHTER than the AUTH_REFRESH (50s) that a rejected + # token makes those very call sites open. A 45s refresh that completed under + # the old 60s run cap was being killed at 40s. + self.assertGreater(budget.COMMAND, budget.AUTH_REFRESH) + self.assertGreater(budget.COMMAND, budget.AUTH_FULL) + + def test_teardown_is_shorter_than_anything_it_can_interrupt(self) -> None: + # CLOSE is the ONE constant in the module that is invented rather than derived + # from budget(), so nothing but this fixes its VALUE: the call-site tests only + # check that `_close_sync` passes `budget.CLOSE`, never what it is worth, and a + # drift back to the legacy 60s left the whole suite green. What the call site + # claims is "teardown must never wait as long as a setup", and an unload that + # sits through even ONE full request is the slow-unload symptom the narrow + # lifecycle lock exists to remove. + self.assertLess(budget.CLOSE, budget.TOTAL_TIMEOUT) + for name in ( + "APPLIANCE_LIST", + "APPLIANCE_ONE", + "AUTH_REFRESH", + "AUTH_FULL", + "MFA_RESUME", + "MQTT_START", + "COMMAND", + "VALIDATION_CAP", + "SETUP_CAP", + "APPLIANCE_POLL", + ): + with self.subTest(budget=name): + self.assertLess(budget.CLOSE, getattr(budget, name)) + + def test_setup_cap_is_the_declared_sum(self) -> None: + # Arithmetic stated out loud, because it has been mis-stated before. + self.assertEqual(284, budget.VALIDATION_CAP) + self.assertEqual(574, budget.SETUP_CAP) + self.assertEqual( + budget.VALIDATION_CAP + budget.MQTT_START + 4 * budget.APPLIANCE_ONE, + budget.SETUP_CAP, + ) + + +class CallSiteWatchdogTest(unittest.TestCase): + """Freeze the site -> watchdog table, so adding a call site forces a choice.""" + + def _client(self, seen: list, **client_kwargs): + import custom_components.addhon.client.factory as factory + from custom_components.addhon.hon_client import HonClient + + class _FakeSession: + refresh_token = "rt" + + async def __aenter__(self): + return self + + def subscribe_updates(self, fn): + pass + + original = factory.create_session + factory.create_session = lambda email, password, **kw: _FakeSession() + self.addCleanup(setattr, factory, "create_session", original) + + client = HonClient(email="e@x", password="p", **client_kwargs) + client._start_hon_loop = lambda: None # type: ignore[assignment] + + def run(coro, timeout=None): + seen.append(timeout) + if hasattr(coro, "close"): + coro.close() + + client._run_on_hon_loop = run # type: ignore[assignment] + return client + + def test_validation_gets_the_tighter_watchdog(self) -> None: + # A human is waiting on the config-flow form, so the validation path must not + # inherit the runtime watchdog sized for N appliances plus MQTT. + seen: list = [] + self._client(seen, validation=True).setup_sync() + self.assertEqual(budget.VALIDATION_CAP, seen[0]) + + def test_runtime_setup_gets_the_wider_watchdog(self) -> None: + seen: list = [] + self._client(seen).setup_sync() + self.assertEqual(budget.SETUP_CAP, seen[0]) + + def test_a_user_command_gets_the_command_watchdog(self) -> None: + # A command is one POST, but a rejected token makes it sign in inline, and this + # cap is waited on from another thread so it cannot be suspended: handing this + # site a smaller constant truncates exactly the re-login it is waiting for. + seen: list = [] + client = self._client(seen) + + async def _send() -> None: + return None + + client.run_command_sync(_send()) + self.assertEqual(budget.COMMAND, seen[0]) + + def test_a_patch_dispatch_gets_the_command_watchdog(self) -> None: + from custom_components.addhon.command_dispatch import CommandPatch + + seen: list = [] + client = self._client(seen) + client.dispatch_patch_sync( + object(), CommandPatch(command_name="startProgram", values={}, action="send") + ) + self.assertEqual(budget.COMMAND, seen[0]) + + def test_the_otp_resend_gets_the_command_watchdog(self) -> None: + seen: list = [] + client = self._client(seen) + + class _Pending: + async def resend_mfa_code(self, context): + return None + + client._hon_instance = _Pending() + client.resend_mfa_code_sync(object()) + self.assertEqual(budget.COMMAND, seen[0]) + + def test_teardown_gets_the_short_watchdog(self) -> None: + # Teardown must never wait like a setup: on the wrong constant an unload would + # hold Home Assistant for minutes instead of seconds. + seen: list = [] + client = self._client(seen) + + class _Open: + async def __aexit__(self, *exc): + return False + + client._hon_instance = _Open() + client._close_sync() + self.assertEqual(budget.CLOSE, seen[0]) + + def test_a_polled_appliance_gets_the_poll_watchdog(self) -> None: + # Where the F8 regression actually lives: not in the arithmetic of the + # constants but in the site that spends them. APPLIANCE_ONE here (60s) would put + # the poll watchdog back UNDER the sign-in a rejected token starts inline -- + # the #76 shape, one level up, on the path that runs every minute. + seen: list = [] + client = self._client(seen) + client._update_appliance_sync(object()) + self.assertEqual(budget.APPLIANCE_POLL, seen[0]) + + def test_the_2fa_resume_follows_the_same_split_as_setup(self) -> None: + # The 2FA step of the CONFIG FLOW was handed the runtime watchdog (654s), which + # contradicts the reason the two were split in the first place. + for validation, expected in ( + (True, budget.MFA_RESUME + budget.VALIDATION_CAP), + (False, budget.MFA_RESUME + budget.SETUP_CAP), + ): + with self.subTest(validation=validation): + seen: list = [] + client = self._client(seen, validation=validation) + + class _Pending: + async def submit_mfa_code(self, context, code): + return None + + client._hon_instance = _Pending() + client.submit_mfa_code_sync(object(), "000000") + self.assertEqual(expected, seen[0]) + + +class CallSiteTableIsCompleteTest(unittest.TestCase): + """The other half of the promise above: a NEW call site cannot slip in unpinned. + + The tests above pin the constant each KNOWN site passes. Nothing pinned the SET of + sites, so `_run_on_hon_loop(coro)` with no watchdog at all -- which silently means + the legacy 60s, the single cumulative cap #76 is about -- would have been added + green. Reading the source is the point: a behavioural test can only cover the sites + someone remembered to write one for. + """ + + EXPECTED = { + "_close_sync": "budget.CLOSE", + "setup_sync": "budget.VALIDATION_CAP if self._validation else budget.SETUP_CAP", + "submit_mfa_code_sync": ( + "budget.MFA_RESUME + " + "(budget.VALIDATION_CAP if self._validation else budget.SETUP_CAP)" + ), + "resend_mfa_code_sync": "budget.COMMAND", + "run_command_sync": "budget.COMMAND", + "dispatch_patch_sync": "budget.COMMAND", + "_update_appliance_sync": "budget.APPLIANCE_POLL", + } + + @staticmethod + def _call_sites() -> dict: + import ast + + from custom_components.addhon import hon_client as hon_client_mod + + tree = ast.parse(Path(hon_client_mod.__file__).read_text(encoding="utf-8")) + sites: dict[str, list[ast.Call]] = {} + + def visit(node, owner: str) -> None: + for child in ast.iter_child_nodes(node): + if isinstance(child, (ast.FunctionDef, ast.AsyncFunctionDef)): + visit(child, child.name) + continue + if ( + isinstance(child, ast.Call) + and isinstance(child.func, ast.Attribute) + and child.func.attr == "_run_on_hon_loop" + ): + sites.setdefault(owner, []).append(child) + visit(child, owner) + + visit(tree, "") + return sites + + def test_every_call_site_passes_an_explicit_watchdog(self) -> None: + import ast + + sites = self._call_sites() + self.assertEqual(sorted(self.EXPECTED), sorted(sites)) + for owner, calls in sites.items(): + with self.subTest(call_site=owner): + self.assertEqual(1, len(calls)) + call = calls[0] + # A site that omits the argument inherits the legacy 60s cap, which is + # the single cumulative number #76 was filed against. + self.assertEqual(2, len(call.args), f"{owner} chose no watchdog") + expected = ast.unparse( + ast.parse(self.EXPECTED[owner], mode="eval").body + ) + self.assertEqual(expected, ast.unparse(call.args[1])) + + +class BudgetedScopeTableIsCompleteTest(unittest.TestCase): + """The same promise as the table above, for the SCOPES rather than the caps. + + Every phase inside a cap is supposed to bound itself -- that is the whole model: + "a cap only has to catch a loop that stopped progressing at all". Nothing verified + that the set of `budgeted()` scopes was complete, and it was not: the MQTT start was + SUMMED into SETUP_CAP while never opening a scope, so a stalled first connect ran for + the whole 574s cap instead of its own 50s. Nothing pinned which budget each scope + passes either, so a scope could quietly be given the teardown number. + + `transport/connection.py` is covered by AuthScopesSuspendTheCallerTest below, which + also pins the suspension flag those scopes need. + """ + + EXPECTED = { + # module basename -> innermost function -> budgets, in source order + "session.py": { + "setup": ["APPLIANCE_LIST", "MQTT_START"], + "_create_appliance": ["APPLIANCE_ONE"], + }, + "hon_client.py": { + # The first-poll rehydration, under the same pair `_build_appliance` opens. + "_do_update": ["budget.APPLIANCE_ONE"], + }, + } + + @staticmethod + def _scopes(module) -> dict: + import ast + + tree = ast.parse(Path(module.__file__).read_text(encoding="utf-8")) + found: dict[str, list[str]] = {} + + def visit(node, owner: str) -> None: + for child in ast.iter_child_nodes(node): + if isinstance(child, (ast.FunctionDef, ast.AsyncFunctionDef)): + visit(child, child.name) + continue + if isinstance(child, ast.Call) and ( + (isinstance(child.func, ast.Name) and child.func.id == "budgeted") + or ( + isinstance(child.func, ast.Attribute) + and child.func.attr == "budgeted" + ) + ): + found.setdefault(owner, []).append(ast.unparse(child.args[0])) + visit(child, owner) + + visit(tree, "") + return found + + def test_every_budgeted_scope_is_pinned_to_its_phase(self) -> None: + from custom_components.addhon import hon_client as hon_client_mod + + for module in (session_mod, hon_client_mod): + name = Path(module.__file__).name + with self.subTest(module=name): + self.assertEqual(self.EXPECTED[name], self._scopes(module)) + + +class AuthScopesSuspendTheCallerTest(unittest.TestCase): + """Every auth scope in the transport is work the CALLER never asked for. + + The sign-in is LAZY: it starts inside whatever request happened to need a token, + so its budget nests inside a caller's budget that is deliberately smaller. Each of + these scopes therefore has to suspend the scopes it interrupts, or the outer one + fires first and the login is reported as "load_appliances timed out" -- #76 itself. + Two of them are on the 401 recovery ladder and one is the 2FA resume, and a + behavioural test can only reach a scope the production nesting can build today: + the table is what makes DROPPING the flag at any of the five a test failure. + """ + + EXPECTED = { + "_check_headers": [("AUTH_REFRESH", True), ("AUTH_FULL", True)], + "_refresh_after_rejection": [("AUTH_REFRESH", True)], + "_reauth_after_rejection": [("AUTH_FULL", True)], + "submit_mfa_code": [("MFA_RESUME", True)], + } + + def test_every_transport_auth_scope_suspends_its_caller(self) -> None: + import ast + + tree = ast.parse(Path(conn_mod.__file__).read_text(encoding="utf-8")) + found: dict[str, list[tuple[str, bool]]] = {} + + def visit(node, owner: str) -> None: + for child in ast.iter_child_nodes(node): + if isinstance(child, (ast.FunctionDef, ast.AsyncFunctionDef)): + visit(child, child.name) + continue + if ( + isinstance(child, ast.Call) + and isinstance(child.func, ast.Name) + and child.func.id == "_budgeted" + ): + suspends = False + for keyword in child.keywords: + if keyword.arg == "suspends_caller": + suspends = getattr(keyword.value, "value", False) is True + found.setdefault(owner, []).append( + (ast.unparse(child.args[0]), suspends) + ) + visit(child, owner) + + visit(tree, "") + self.assertEqual(self.EXPECTED, found) + + +class SuspendedBudgetTest(unittest.IsolatedAsyncioTestCase): + """The mechanism the whole model rests on, exercised directly.""" + + async def test_a_nested_sign_in_does_not_spend_the_callers_budget(self) -> None: + # Enclosing 0.4s, nested "sign-in" budgeted 1.5s that really takes 0.5s. Under + # plain nested timeouts the outer one fires at 0.4s; suspended, it is charged + # only the 0.5s the interruption cost and still has its own work to do. + async with budgeted(0.4): + async with budgeted(1.5, suspends_caller=True): + await asyncio.sleep(0.5) + await asyncio.sleep(0.2) # the caller's OWN work, after the interruption + + async def test_the_caller_still_expires_on_its_own_work(self) -> None: + # The suspension gives back what the sign-in did not use, so it cannot be + # abused as an unlimited extension of the caller's budget. + # + # The numbers are DIFFERENTIAL on purpose. The caller has 0.4s and lends 1.5s; + # the sign-in returns after 0.05s, so with the give-back it is left with ~0.35s + # and 0.8s of own work must expire, while WITHOUT it the deadline would sit at + # 0.4+1.5=1.9s and 0.85s would sail through. With the 2s of own work this test + # used to do, both sides raised and deleting the give-back left the suite green + # -- the whole mechanism of the fix was unprotected. + loop = asyncio.get_running_loop() + started = loop.time() + with self.assertRaises(ec.HonCodedError): + async with budgeted(0.4): + async with budgeted(1.5, suspends_caller=True): + await asyncio.sleep(0.05) + await asyncio.sleep(0.8) + self.assertLess(loop.time() - started, 1.0) + + async def test_the_nested_budget_still_bounds_the_sign_in(self) -> None: + # Suspending the caller must not make the inner scope unbounded. The elapsed + # assertion is what makes this about the INNER scope: the 2.0s outer one raises + # the very same HonCodedError, one and a half seconds later. + loop = asyncio.get_running_loop() + started = loop.time() + with self.assertRaises(ec.HonCodedError): + async with budgeted(2.0): + async with budgeted(0.2, suspends_caller=True): + await asyncio.sleep(5) + self.assertLess(loop.time() - started, 1.0) + + async def test_a_closed_scope_leaves_no_deadline_behind(self) -> None: + # `budgeted()` is an @asynccontextmanager, so its `_ACTIVE.set()` lands in the + # CALLER's context (an async generator gets no context of its own). Drop the + # matching reset and a FINISHED asyncio.Timeout stays on the stack for the rest + # of the task: `current_deadline()` then answers an instant already in the PAST, + # and the login retry gate that reads it refuses every retry from then on -- + # round 1's F3 defect, in the opposite direction. + # + # Reachable in one straight line: setup() closes budgeted(APPLIANCE_LIST) and + # then awaits _create_appliance, which opens budgeted(APPLIANCE_ONE), in the + # very same coroutine. + async with budgeted(0.5): + self.assertEqual(1, len(budget._ACTIVE.get())) + self.assertEqual((), budget._ACTIVE.get()) + self.assertIsNone(budget.current_deadline()) + # ...and the NEXT scope's deadline is its own, not one inherited from a corpse. + async with budgeted(10): + remaining = budget.current_deadline() - time.monotonic() + self.assertGreater(remaining, 5) + + async def test_a_sign_in_suspends_every_enclosing_scope_not_just_its_parent( + self, + ) -> None: + # `_ACTIVE` is a STACK, and it has to be: a sign-in suspends the scopes it + # interrupts, plural. Collapse it to a single slot and only the immediate parent + # is suspended, so a grandparent truncates the caller exactly the way + # APPLIANCE_LIST truncated AUTH_FULL in #76. Every other suspension test here is + # two levels deep, and two levels cannot tell a stack from one slot. + # + # 0.60 outer / 0.55 middle; a sign-in budgeted 0.30 that really takes 0.25, then + # 0.45s of the caller's own work. Suspended properly both enclosing deadlines end + # at ~0.85/0.80 against 0.70 elapsed; with only the parent suspended the outer one + # still sits at 0.60 and fires. + async with budgeted(0.60): + self.assertEqual(1, len(budget._ACTIVE.get())) + async with budgeted(0.55): + # The shape, stated directly: the enclosing scope is still on the stack. + self.assertEqual(2, len(budget._ACTIVE.get())) + async with budgeted(0.30, suspends_caller=True): + await asyncio.sleep(0.25) + await asyncio.sleep(0.45) + + async def test_a_plain_nested_scope_does_not_suspend_its_caller(self) -> None: + # The default of `suspends_caller` IS the scope-budget/CAP distinction the whole + # fix rests on: "a scope budget does not suspend unless it is work the caller + # never asked for". Flipping it to True is inert TODAY only because the three + # sites that omit the flag happen to be outermost in their task -- so nothing + # noticed, and the invariant rested on nobody ever nesting a plain scope. + import inspect + + self.assertIs( + False, inspect.signature(budgeted).parameters["suspends_caller"].default + ) + async with budgeted(0.6): + enclosing = budget._ACTIVE.get()[0] + before = enclosing.when() + async with budgeted(0.2): + self.assertEqual(before, enclosing.when()) + self.assertEqual(before, enclosing.when()) + + async def test_current_deadline_reports_the_tightest_open_scope(self) -> None: + # This is what the login retry gate must read. Rebuilding it from AUTH_FULL + # made the gate compare against a deadline nobody enforced. + self.assertIsNone(budget.current_deadline()) + async with budgeted(10): + outer = budget.current_deadline() + self.assertIsNotNone(outer) + async with budgeted(0.5): + inner = budget.current_deadline() + self.assertLess(inner, outer) + + +class Issue76ReproductionTest(_ScaledBudgets): + """#76 driven through NativeHon.setup(), the way production builds the nesting.""" + + def test_slow_login_inside_setup_is_reported_as_a_sign_in_timeout(self) -> None: + # THE #76 REPRODUCTION. Before: the outer APPLIANCE_LIST scope fired at 40s, + # `current_phase()` had already unwound to "load_appliances", and the user was + # told the NETWORK had timed out while the LOGIN was still running. + harness = SetupHarness( + self, _StallingAuth(auth_seconds=STALL), refresh_token="" + ) + with self.assertRaises(ec.HonCodedError) as ctx: + harness.setup() + self.assertIs(ec.AUTH_TIMEOUT, ctx.exception.error_code) + self.assertEqual("load_appliances/auth", ctx.exception.phase) + # Not a credentials problem: it must stay retryable, never open a reauth. + self.assertFalse(ctx.exception.error_code.requires_reauth) + + def test_slow_refresh_inside_setup_is_reported_as_a_refresh_timeout(self) -> None: + harness = SetupHarness( + self, _StallingAuth(refresh_seconds=STALL), refresh_token="rt" + ) + with self.assertRaises(ec.HonCodedError) as ctx: + harness.setup() + self.assertIs(ec.REFRESH_TIMEOUT, ctx.exception.error_code) + self.assertEqual("load_appliances/auth/refresh", ctx.exception.phase) + + def test_a_login_slower_than_the_appliance_list_budget_still_completes(self) -> None: + # The REGRESSION the first attempt introduced: a 45s login fitted under the old + # single 60s cap and then stopped fitting under APPLIANCE_LIST=40s -- the same + # user, the same network, a NEW failure. A sign-in is entitled to the sign-in + # budget wherever it happens to start. + slow = 45 * SCALE + self.assertGreater(slow, budget.APPLIANCE_LIST * SCALE) + self.assertLess(slow, budget.AUTH_FULL * SCALE) + harness = SetupHarness(self, _StallingAuth(auth_seconds=slow), refresh_token="") + harness.setup() + self.assertEqual(1, len(harness.hon.appliances)) + + def test_no_bare_timeout_escapes_a_budgeted_scope(self) -> None: + # The conversion rule: a bare TimeoutError reaching the outer cap would carry + # no phase and collapse to the mute ADDHON-460. + harness = SetupHarness( + self, _StallingAuth(auth_seconds=STALL), refresh_token="" + ) + with self.assertRaises(ec.HonCodedError) as ctx: + harness.setup() + self.assertIsInstance(ctx.exception.__cause__, TimeoutError) + + def test_the_ledger_files_a_budget_expiry_as_a_timeout(self) -> None: + # `budgeted` converts the expiry into a coded error while still INSIDE the + # phase scope, so the ledger only ever saw a non-TimeoutError: the 'timeout' + # outcome that diagnostics documents was unreachable in production, and every + # expiry looked like an application error. + harness = SetupHarness( + self, _StallingAuth(refresh_seconds=STALL), refresh_token="rt" + ) + with self.assertRaises(ec.HonCodedError): + harness.setup() + outcomes = { + entry["phase"]: entry["outcome"] for entry in harness.hon.phase_ledger + } + self.assertEqual("timeout", outcomes["load_appliances/auth/refresh"]) + self.assertEqual("timeout", outcomes["load_appliances"]) + + def test_a_slow_appliance_list_still_reports_400(self) -> None: + # No regression on the case ADDHON-400 was always right for -- driven, not + # looked up. The tokens are already usable, so no sign-in is involved: the POST + # itself is slow, APPLIANCE_LIST is the budget that must fire and the phase must + # stay "load_appliances". This used to be `assertIs(NETWORK_TIMEOUT, + # phase_timeout_code("load_appliances"))`, a re-read of a table another file + # already covers, and deleting the APPLIANCE_LIST scope from setup() left the + # suite green. + harness = SetupHarness( + self, + _StallingAuth(signed_in=True), + refresh_token="", + session=_Session(delay=SLOW_POST), + ) + with self.assertRaises(ec.HonCodedError) as ctx: + harness.setup() + self.assertIs(ec.NETWORK_TIMEOUT, ctx.exception.error_code) + self.assertEqual("load_appliances", ctx.exception.phase) + self.assertEqual([], harness.auth.calls) + + def test_a_rejected_token_refreshing_inside_setup_is_a_refresh_timeout(self) -> None: + # The 401 RECOVERY LADDER, which is how a token gets rejected in the field: + # the refresh it opens is a sign-in like any other and must suspend the request + # that triggered it. Without the suspension the APPLIANCE_LIST scope (40s) cuts + # the AUTH_REFRESH (50s) short and the user is told the network timed out -- + # #76, on the recovery path. + harness = SetupHarness( + self, + _StallingAuth(refresh_seconds=STALL, signed_in=True), + refresh_token="", + session=_Session(statuses=(401,)), + ) + with self.assertRaises(ec.HonCodedError) as ctx: + harness.setup() + self.assertIs(ec.REFRESH_TIMEOUT, ctx.exception.error_code) + self.assertEqual("load_appliances/auth/refresh", ctx.exception.phase) + self.assertEqual(["refresh"], harness.auth.calls) + + def test_a_second_rejection_inside_setup_is_a_sign_in_timeout(self) -> None: + # One rung further: the refresh worked but the retry is rejected too, so the + # ladder re-logins. Same rule, the widest scope of the three (AUTH_FULL=184s + # inside an APPLIANCE_LIST of 40s), and the same #76 symptom if it does not + # suspend its caller. + harness = SetupHarness( + self, + _StallingAuth(auth_seconds=STALL, signed_in=True), + refresh_token="", + session=_Session(statuses=(401, 401)), + connection_class=_KeepsItsAuthOnCreate, + ) + with self.assertRaises(ec.HonCodedError) as ctx: + harness.setup() + self.assertIs(ec.AUTH_TIMEOUT, ctx.exception.error_code) + self.assertEqual("load_appliances/auth", ctx.exception.phase) + self.assertEqual(["refresh", "authenticate"], harness.auth.calls) + + def test_one_request_can_open_three_sign_ins(self) -> None: + # What `cap()` deliberately does NOT contain, stated by driving it. A single + # request signs in lazily, then the ladder refreshes and re-logins: three + # sign-ins, AUTH_FULL + AUTH_REFRESH + AUTH_FULL = 418s of allowance against + # COMMAND = 284s. Sizing every cap for that chain would put a user command at + # ~12 minutes and the setup watchdog past what Home Assistant waits for, to + # cover the case where the tokens are rejected twice in a row. + # + # The stop is safe because of WHERE the cap then fires: inside the sign-in, + # where the phase mirror reads "auth[/refresh]", so the user gets the attributed + # and retryable ADDHON-405/406 -- never the ADDHON-400 of #76. + harness = SetupHarness( + self, + _StallingAuth(), + refresh_token="", + session=_Session(statuses=(401, 401)), + connection_class=_KeepsItsAuthOnCreate, + ) + harness.setup() + self.assertEqual( + ["authenticate", "refresh", "authenticate"], harness.auth.calls + ) + self.assertGreater( + budget.AUTH_FULL + budget.AUTH_REFRESH + budget.AUTH_FULL, budget.COMMAND + ) + self.assertIs(ec.AUTH_TIMEOUT, ec.phase_timeout_code("auth")) + self.assertIs(ec.REFRESH_TIMEOUT, ec.phase_timeout_code("auth/refresh")) + self.assertFalse(ec.AUTH_TIMEOUT.requires_reauth) + + def test_a_stalled_mqtt_start_expires_on_its_own_budget(self) -> None: + # MQTT_START was SUMMED into SETUP_CAP and never applied as a scope: the one + # phase inside that cap with no budget of its own. A first connect that stalled + # was therefore bounded only by SETUP_CAP -- the config entry took ~10 minutes + # to fail on a phase whose own number says 50s -- and the model's premise ("a + # cap only has to catch a loop that stopped progressing at all") was false + # exactly here. Now it fails on its own budget, named and coded. + harness = SetupHarness(self, _StallingAuth(signed_in=True), "rt") + hon = harness.hon + hon._enable_mqtt = True + + async def _never_connects() -> None: + await asyncio.sleep(STALL) + + hon._make_mqtt = _never_connects # type: ignore[assignment] + with self.assertRaises(ec.HonCodedError) as ctx: + harness.setup() + self.assertIs(ec.MQTT_CONNECT_TIMEOUT, ctx.exception.error_code) + self.assertEqual("mqtt_start", ctx.exception.phase) + # ...and the ledger says which phase burned the time, which is the whole point + # of having a phase at all. + self.assertIn( + ("mqtt_start", "timeout"), + [(entry["phase"], entry["outcome"]) for entry in hon.phase_ledger], + ) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_transport_mqtt.py b/tests/test_transport_mqtt.py index 51112f5..aa72451 100644 --- a/tests/test_transport_mqtt.py +++ b/tests/test_transport_mqtt.py @@ -180,6 +180,48 @@ def stop(self) -> None: self.assertFalse(m._connection) +class SetupPhaseMirrorTest(unittest.TestCase): + """The MQTT step must survive the scope `NativeHon.setup()` wraps around it (#76). + + The start is now bounded by MQTT_START under a `phase("mqtt_start")` scope, and that + scope writes the HIERARCHICAL mirror -- the one `HonClient._run_on_hon_loop` reads + from another thread and PREFERS to the flat one. So the flat mirror this method has + always written is no longer enough on its own: without the refinement the outer name + would shield it and the connect/subscribe distinction (ADDHON-310 vs 320) would be + lost. `step()` does not push the ContextVar, so the enclosing scope still restores + everything on the way out. + """ + + def test_the_step_reaches_both_mirrors_and_does_not_outlive_the_scope(self) -> None: + from custom_components.addhon.client.phase import PhaseTracker, phase + + class _Hon(FakeHon): + """A session that exposes BOTH mirrors, the way NativeHon does.""" + + def __init__(self) -> None: + super().__init__([]) + self._setup_phase = "" + self._phase_tracker = PhaseTracker() + + hon = _Hon() + client = NativeMqttClient(hon, "MID") + with phase("mqtt_start", hon._phase_tracker): + client._set_setup_phase("mqtt_connect") + self.assertEqual("mqtt_connect", hon._setup_phase) + self.assertEqual("mqtt_start/mqtt_connect", hon._phase_tracker.current) + client._set_setup_phase("mqtt_subscribe") + self.assertEqual("mqtt_start/mqtt_subscribe", hon._phase_tracker.current) + # Restored: a refinement can never outlive the scope that framed it. + self.assertEqual("", hon._phase_tracker.current) + + def test_a_session_without_a_tracker_is_still_tolerated(self) -> None: + # Same defensive contract as the flat write above: a double (or an older + # session object) must not break the MQTT start. + client = NativeMqttClient(FakeHon([]), "MID") + client._set_setup_phase("mqtt_connect") + self.assertEqual("mqtt_connect", client._hon._setup_phase) + + class CreatePathTest(unittest.TestCase): """Drives the REAL path create()->_start->_subscribe->watchdog with richer awscrt stubs: catches a wiring error (builder/subscribe) invisible to the other tests