From df2c84775a804276ff91865a8c8dbd8d160ea8c2 Mon Sep 17 00:00:00 2001 From: tis24dev Date: Mon, 10 Aug 2026 07:06:14 +0200 Subject: [PATCH 1/9] feat: report what the model declares, not only what it reports The diagnostics dump described an appliance purely through its shadow: the telemetry it happens to publish. That cannot answer what the appliance IS. A fridge that reports `tempZ3` may simply not have that zone, and the dump gave no way to tell the two apart, so a zone-indexing report needed a round trip to the reporter before it could even be diagnosed (issue #75). The cloud already sends the answer in `applianceModel.attributes`: `zones`, `seriesVersion`, `vtRoom1`/`vtRoom2`, `doorNumber`. We were fetching it and keeping only `options`. The hOn app itself treats those rows as authoritative where the shadow is not - it decides which fridge zones exist from `zones`.split("|"), never from which `tempZ*` keys the shadow carries. Expose them as `HonAppliance.model_attributes`, flattened parName -> parValue the same way __init__ already flattens the appliance-level attributes, and emit them as a `model_attributes` block ahead of `attributes`: what the model is, then what it is doing. Read off the appliance rather than the coordinator entry, since it is per-model and immutable for the session. Redaction is unchanged - the block goes through _redact like every other section. --- .../addhon/client/engine/appliance.py | 27 +++++++ custom_components/addhon/diagnostics.py | 30 +++++++- tests/test_diagnostics.py | 72 ++++++++++++++++++- tests/test_engine_appliance_root.py | 44 ++++++++++++ 4 files changed, 169 insertions(+), 4 deletions(-) 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/diagnostics.py b/custom_components/addhon/diagnostics.py index 3cb5428..4c2c118 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; @@ -282,6 +290,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 +565,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 +589,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, diff --git a/tests/test_diagnostics.py b/tests/test_diagnostics.py index f9f664a..4fb5f19 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 @@ -399,6 +419,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() 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() From 09cf4f8dbe3f47290306c2c984ca545fbd874b6f Mon Sep 17 00:00:00 2001 From: tis24dev Date: Mon, 10 Aug 2026 20:39:02 +0200 Subject: [PATCH 2/9] feat: say why a purifier toggle was rejected, not just which were built A field report has been open for two weeks: an HHP50CA011 shows every purifier control except Child Lock and Sounds. Neither artifact we ask for could answer it, and that is a hole in this integration, not bad luck. The AP branch of the switch platform gated on two conditions and did a bare `continue` on each, while the summary line named only what it DID build. So a purifier missing a toggle looked exactly like a purifier that never reached the branch. The sibling platforms have always logged their skips: light.py names the capability, the live values and the reported state, and select.py does the same for the aroma and panel-light selects. The AP switches now match them, and the line separates the two gates, so "the schema does not declare it" and "the device does not report it" stop looking alike. The dump had the matching hole. `_param_schema` emits min/max/step for a range, but param_range() casts through float(), so a schema spelling its bounds "0"/"1" and one spelling them "0.0"/"1.0" print identically -- while the materialised grid differs, and the capability gates compare exactly those strings (`lock_values == {"0", "1"}`). A single decimal-spelled bound removes a control and left no trace anywhere. Small grids now carry their values. The bound is what keeps the standing rule intact: a setpoint range is still never enumerated, because the point count is computed arithmetically from min/max/step and `.values` is never read for a grid over the cap. A test proves that by making `.values` raise. Deliberately NOT changed: the gates themselves. They compare strings, which is the trap described above, but for this reporter they are not the cause -- the same funnel feeds the fan, both selects and both timing numbers, and all of those exist on his unit, so his schema is spelled with integers and the gate passes. Fixing the comparison without also canonicalising the write path would be worse than the trap: `_checked_value` validates an outgoing value against the same set, so the switch would exist and refuse every write. Mutation evidence: restoring the silent `continue` fails 4 tests, emitting the grid unconditionally fails 3, never emitting it fails 3. --- custom_components/addhon/diagnostics.py | 32 ++++++++++- custom_components/addhon/switch.py | 33 ++++++++++-- tests/test_air_purifier_entities.py | 70 +++++++++++++++++++++++++ tests/test_diagnostics.py | 57 ++++++++++++++++++++ 4 files changed, 187 insertions(+), 5 deletions(-) diff --git a/custom_components/addhon/diagnostics.py b/custom_components/addhon/diagnostics.py index 4c2c118..cb44027 100644 --- a/custom_components/addhon/diagnostics.py +++ b/custom_components/addhon/diagnostics.py @@ -184,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 @@ -266,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), @@ -282,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: 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/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_diagnostics.py b/tests/test_diagnostics.py index 4fb5f19..77d9e09 100644 --- a/tests/test_diagnostics.py +++ b/tests/test_diagnostics.py @@ -395,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 From e3ef4021c9271819b85725dc7d5f934bd73b6a77 Mon Sep 17 00:00:00 2001 From: tis24dev Date: Tue, 11 Aug 2026 06:58:16 +0200 Subject: [PATCH 3/9] feat(client): add per-phase time budgets with a shared suspending deadline The whole setup used to run under one 60s cap. A cold sign-in alone is nine sequential round-trips, and each appliance adds more, so a working but slow account blew the cap and surfaced as a network timeout it never was. Budgets are now per phase and share one absolute deadline through a ContextVar stack of the live asyncio.Timeout scopes. A sign-in scope SUSPENDS the scopes it interrupts -- it pushes their deadline out on entry and gives the unused remainder back on exit -- so a lazy login nested inside a caller's scope can no longer be killed by the shorter budget wrapping it. Two kinds of number, kept apart on purpose: scope budgets (own work, suspendable) and caps awaited across the thread boundary on a concurrent.futures.Future (not suspendable, so each must contain a sign-in). --- custom_components/addhon/client/budget.py | 234 ++++++ custom_components/addhon/client/phase.py | 130 ++++ tests/test_phase_context.py | 337 ++++++++ tests/test_setup_budgets.py | 892 ++++++++++++++++++++++ 4 files changed, 1593 insertions(+) create mode 100644 custom_components/addhon/client/budget.py create mode 100644 custom_components/addhon/client/phase.py create mode 100644 tests/test_phase_context.py create mode 100644 tests/test_setup_budgets.py 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/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/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_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() From 81b0cfd6479f84ff36d3434c5e8587d192759300 Mon Sep 17 00:00:00 2001 From: tis24dev Date: Tue, 11 Aug 2026 06:58:30 +0200 Subject: [PATCH 4/9] feat(errors): add ADDHON-405/406/480 and resolve the phase hierarchically ADDHON-400 could not tell a slow sign-in from a slow appliance list: the lazy login runs inside the load_appliances phase, so every login timeout was filed against the list. phase_timeout_code now resolves composed phases leaf first, so load_appliances/auth/refresh reports 406 and load_appliances/auth reports 405 while every flat phase resolves exactly as before. 480 covers the call that was still in flight when the dedicated loop was torn down. classify() gains a structural layer -- exception type and response status are read before the text of the message, which stays as the fallback it always should have been. --- custom_components/addhon/error_codes.py | 194 +++++++++++++++++- custom_components/addhon/translations/en.json | 2 + custom_components/addhon/translations/it.json | 2 + tests/test_error_codes.py | 150 +++++++++++++- 4 files changed, 343 insertions(+), 5 deletions(-) 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/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/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))) From c211fb807e083700af5c3f190e9eab07001bba27 Mon Sep 17 00:00:00 2001 From: tis24dev Date: Tue, 11 Aug 2026 06:58:41 +0200 Subject: [PATCH 5/9] feat(transport): retry the idempotent sign-in steps within the caller's deadline A single network blip during validation was a final error: the login path had no retry at all, while the runtime poll had three attempts. Retry is by explicit inclusion and covers only the five round-trips that can be replayed safely; the steps that mint an OTP or advance the Salesforce session are deliberately left out, so a retry can never multiply a verification code. The delay is fixed, not exponential. The gate measures the deadline of the scope actually in force rather than rebuilding one from AUTH_FULL, so a retry cannot be the reason its own budget expires. Each auth scope suspends its caller. --- .../addhon/client/transport/auth.py | 87 +++- .../addhon/client/transport/connection.py | 76 +++- .../addhon/client/transport/retry.py | 115 +++++ tests/test_auth_retry_policy.py | 394 ++++++++++++++++++ 4 files changed, 642 insertions(+), 30 deletions(-) create mode 100644 custom_components/addhon/client/transport/retry.py create mode 100644 tests/test_auth_retry_policy.py 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/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/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() From aa5c530ccedcabc3d6cd58b2161d93c5c4b1017f Mon Sep 17 00:00:00 2001 From: tis24dev Date: Tue, 11 Aug 2026 06:58:55 +0200 Subject: [PATCH 6/9] fix(setup): attribute a setup timeout to the phase that burned the time The watchdog read the phase after cancelling and draining the task, by which point the scope had already unwound and the mirror was empty, so it fell back to the flat phase and reported ADDHON-400 again. It now samples the phase before scheduling the cancellation, and keeps the real cause when the coroutine loses the race with the watchdog. Since 3.11 concurrent.futures.TimeoutError IS TimeoutError, so the cap expiry can no longer be told from a timeout raised BY the task by type. It is now told apart by state, through future.done(). A transport fault on one appliance no longer fails the whole entry: the appliance is queued for rehydration and reloaded before the first poll decides which entities exist, and a second failure is not contained a second time. Statistics move to the first poll, which reloads them anyway. MQTT startup gets the scope its budget was already summed into, and the wait no longer holds the lifecycle lock across the thread boundary. --- custom_components/addhon/client/session.py | 209 +++++++- .../addhon/client/transport/mqtt.py | 17 +- custom_components/addhon/hon_client.py | 328 +++++++++--- tests/test_coordinator_resilience.py | 27 + tests/test_hon_client_realtime.py | 504 +++++++++++++++++- tests/test_native_session.py | 199 ++++++- tests/test_transport_mqtt.py | 42 ++ 7 files changed, 1218 insertions(+), 108 deletions(-) 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/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/hon_client.py b/custom_components/addhon/hon_client.py index d5bf5bb..96359d7 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,42 @@ 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._build_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", + getattr(self._hon_instance, "_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 +929,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 +1142,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 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_hon_client_realtime.py b/tests/test_hon_client_realtime.py index f4302bb..9e9b7e2 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 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_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 From e2bfacc876469d251a0c1e46c44d465dfe6ad5af Mon Sep 17 00:00:00 2001 From: tis24dev Date: Tue, 11 Aug 2026 06:59:05 +0200 Subject: [PATCH 7/9] feat(diagnostics): expose the phase ledger and print the code once Download Diagnostics now carries a per-phase ledger of duration and outcome, so the next report like #76 says which phase burned the time without needing a live probe. The log line used to read "Validation failed [ADDHON-400]: ADDHON-400: ..." -- the label was formatted next to an error whose message already began with it. The code appears once now, in the config flow and in the ConfigEntryNotReady and UpdateFailed messages alike. --- custom_components/addhon/__init__.py | 17 ++++++---- custom_components/addhon/config_flow.py | 17 ++++++++-- custom_components/addhon/diagnostics.py | 7 +++++ tests/_aiohttp_contract.py | 28 +++++++++++++++++ tests/test_auth_error_classification.py | 19 +++++++++++ tests/test_config_flow_error_codes.py | 12 +++++++ tests/test_diagnostics.py | 42 +++++++++++++++++++++++++ tests/test_program_select.py | 2 +- 8 files changed, 134 insertions(+), 10 deletions(-) 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/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 cb44027..78a1739 100644 --- a/custom_components/addhon/diagnostics.py +++ b/custom_components/addhon/diagnostics.py @@ -877,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/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_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_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_diagnostics.py b/tests/test_diagnostics.py index 77d9e09..3459483 100644 --- a/tests/test_diagnostics.py +++ b/tests/test_diagnostics.py @@ -870,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_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) From 62d64e5d6b4d02782bae57a40bdeaed6bfa3e8d3 Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" <41898282+github-actions[bot]@users.noreply.github.com> Date: Tue, 11 Aug 2026 04:59:51 +0000 Subject: [PATCH 8/9] chore: set manifest version 5.12.0 --- custom_components/addhon/manifest.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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" } From 5d12cb2a2990ce100bc3dd60458db5e67ce16982 Mon Sep 17 00:00:00 2001 From: tis24dev Date: Tue, 11 Aug 2026 07:22:30 +0200 Subject: [PATCH 9/9] fix(diagnostics): forward the phase through the all-failed update wrapper A steady-state cycle where every appliance fails wraps the representative cause in a HonCodedError, and __init__.py reads `phase` off THAT object without ever walking the __cause__ chain. The wrapper passed no phase, so Download Diagnostics filed phase=null for causes that knew exactly where they died -- the first-poll twin already forwarded it. Also read the phase tracker from the same session attribute the rehydration guard asks (both names hold the one NativeHon), and correct a comment that pointed at NativeHon._build_appliance, which does not exist; the method is _create_appliance. --- custom_components/addhon/hon_client.py | 12 ++++++++-- tests/test_hon_client_realtime.py | 31 ++++++++++++++++++++++++++ 2 files changed, 41 insertions(+), 2 deletions(-) diff --git a/custom_components/addhon/hon_client.py b/custom_components/addhon/hon_client.py index 96359d7..3db7fb1 100644 --- a/custom_components/addhon/hon_client.py +++ b/custom_components/addhon/hon_client.py @@ -833,7 +833,7 @@ async def _do_update(): # the whole setup, the only path that can still produce a COMPLETE # entity inventory. # - # Under the SAME scope pair `NativeHon._build_appliance` opens for + # 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 @@ -844,7 +844,10 @@ async def _do_update(): # request that already failed once from spending the whole cap. with phase_scope( "load_appliance", - getattr(self._hon_instance, "_phase_tracker", None), + # 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() @@ -1183,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/tests/test_hon_client_realtime.py b/tests/test_hon_client_realtime.py index 9e9b7e2..8200a80 100644 --- a/tests/test_hon_client_realtime.py +++ b/tests/test_hon_client_realtime.py @@ -1107,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