fix: address sidelined silent-failure findings + fix connection-drop test

Three findings I previously marked "out of scope" — wrongly, per
AGENTS.md § Boy Scout Rule which explicitly forbids that escape hatch:

1. WS dispatcher swallowed handler exceptions without a traceback
   (``websocket_client.py:403``). The bare ``logger.error(f"... {e}")``
   gave operators one line and no stack, so a handler bug
   (AttributeError on a malformed event, KeyError on schema drift)
   would silently stop nudging the waiter's ``asyncio.Event`` and the
   calling waiter would time out reporting "not found." Added
   ``exc_info=True`` so the traceback lands in logs. The dispatcher
   itself still swallows so one buggy handler can't kill the WS — but
   the bug is now visible.

2. ``wait_for_automation_entity_by_unique_id`` emitted a redundant
   "Automation with unique_id X was not found" warning at the same
   level as ``_ws_wait_for_condition``'s generic timeout warning.
   Replaced the redundant warning with a conditional one that fires
   only when REST sampling was wedged the entire budget, so operators
   can distinguish "automation truly not published" from "REST channel
   down."

3. Transient ``HomeAssistantAPIError`` from ``get_states()`` was
   debug-only with no signal at timeout time. Now tracked in the
   closure cell and surfaced in the new conditional warning above
   ("timed out with every REST sample failing; last error: ...").

Also fixes ``test_connection_drop_during_discovery_falls_back_to_rest``
which I wrote against the wrong nudge shape: the original noise event
didn't match the discovery filter so the wait timed out at the
backstop instead of dropping. Rewritten to mirror
``test_connection_drop_before_wait_loop_falls_back_to_rest`` — drop
``ws_client.is_connected`` inside the post-subscribe sample so the
connection-drop branch routes us straight to ``_legacy_poll_until``.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

Author: kingpanther13

src/ha_mcp/client/websocket_client.py

@@ -400,7 +400,18 @@ async def _handle_event_message(
                 try:
                     await handler(data["event"])
                 except Exception as e:
-                    logger.error(f"Error in event handler: {e}")
+                    # ``exc_info=True`` so handler bugs (AttributeError /
+                    # KeyError / TypeError from schema-drift on the
+                    # incoming event payload) leave a traceback rather
+                    # than a one-line obscured error. Without this the
+                    # dispatch loop keeps a single buggy handler from
+                    # killing the WS, but the bug itself becomes
+                    # invisible — handlers wired to ``asyncio.Event``
+                    # nudges (see ``util_helpers._ws_wait_for_condition``)
+                    # silently stop nudging and the calling waiter times
+                    # out reporting "not found." #1395 silent-failure
+                    # audit.
+                    logger.error("Error in event handler: %s", e, exc_info=True)
 
     def _ensure_send_lock(self) -> None:
         """Ensure the send lock belongs to the current event loop."""

src/ha_mcp/tools/util_helpers.py

@@ -1131,20 +1131,27 @@ async def wait_for_automation_entity_by_unique_id(
         The discovered entity_id (e.g. ``"automation.morning_routine"``)
         or ``None`` on timeout.
     """
-    # Mutable closure cell: when an event carries the match, the filter
-    # stashes the discovered entity_id so sample() can short-circuit the
-    # full get_states() scan on the next loop tick.
-    captured: dict[str, str | None] = {"entity_id": None}
+    # Mutable closure cells: ``entity_id`` stashes the discovered
+    # entity_id when the filter sees a matching event (sample() then
+    # short-circuits the full get_states() scan). ``last_api_error``
+    # tracks the most recent transient API failure during sampling so
+    # the final timeout warning can distinguish "automation truly not
+    # found" from "REST channel wedged the whole budget."
+    captured: dict[str, str | None] = {"entity_id": None, "last_api_error": None}
 
     async def sample() -> str | None:
         if captured["entity_id"] is not None:
             return captured["entity_id"]
         try:
             states = await client.get_states()
         except HomeAssistantAPIError as e:
+            # Debug-level here is intentional — the waiter retries on
+            # transient errors. The wedged-channel signal goes in the
+            # final timeout warning via ``captured["last_api_error"]``.
             logger.debug(
                 f"API error sampling get_states() for unique_id {unique_id}: {e}"
             )
+            captured["last_api_error"] = str(e)
             return None
         for state in states:
             entity_id = state.get("entity_id")
@@ -1207,9 +1214,18 @@ def event_filter(event: dict[str, Any]) -> bool:
     )
     if isinstance(result, str):
         return result
-    logger.warning(
-        f"Automation with unique_id {unique_id} was not found in HA state after creation"
-    )
+    # `_ws_wait_for_condition` / `_legacy_poll_until` already logged the
+    # generic "timed out" warning before returning None; just surface the
+    # discovery-specific signal when REST sampling was wedged the whole
+    # budget so operators can distinguish "automation never published"
+    # from "REST channel down."
+    if captured["last_api_error"] is not None:
+        logger.warning(
+            "Automation discovery for unique_id %s timed out with every "
+            "REST sample failing; last error: %s",
+            unique_id,
+            captured["last_api_error"],
+        )
     return None
 
 

tests/src/unit/test_wait_helpers.py

@@ -1022,46 +1022,42 @@ async def fire_after_subscribe():
     async def test_connection_drop_during_discovery_falls_back_to_rest(
         self, ws_client, mock_client
     ):
-        """If the WS drops mid-wait during a discovery wait, the helper
+        """If the WS drops while a discovery wait is in flight, the helper
         must fall back to REST polling using the discovery-shaped
-        ``get_states()`` sample — not the entity-id-shaped sample used by
-        the other waiters. Mirrors ``TestWsPathConnectionDrop`` coverage
-        for the entity_id wait path; this pins the discovery path against
-        a regression that wires the wrong fallback sample."""
-        # Post-subscribe sample returns nothing; after the noise event
-        # nudges the loop, the WS goes dead and the helper falls back to
-        # REST polling, which then resolves the match.
-        mock_client.get_states = AsyncMock(
-            side_effect=[
-                [],  # post-subscribe sample: empty
-                [],  # nudge re-sample after noise event: empty (WS now dead)
-                [  # REST fallback path resolves
-                    {
-                        "entity_id": "automation.found_via_rest",
-                        "attributes": {"id": "uid_drop"},
-                    }
-                ],
+        ``get_states()`` sample — not the entity-id-shaped
+        ``get_entity_state()`` used by sibling waiters. Mirrors
+        ``TestWsPathConnectionDrop::test_connection_drop_before_wait_loop_falls_back_to_rest``
+        for the discovery path; pins against a regression that wires
+        the wrong fallback sample."""
+        call_count = {"n": 0}
+
+        async def get_states_dropping_ws():
+            call_count["n"] += 1
+            if call_count["n"] == 1:
+                # Post-subscribe sample: empty AND drops the WS so the
+                # connection-drop-before-wait-loop branch runs (the
+                # ``is_connected`` check between sample and wait loop
+                # routes us to ``_legacy_poll_until`` for the remaining
+                # budget — no backstop interval wasted).
+                ws_client.is_connected = False
+                return []
+            # REST fallback calls find the matching automation.
+            return [
+                {
+                    "entity_id": "automation.found_via_rest",
+                    "attributes": {"id": "uid_drop"},
+                }
             ]
-        )
 
-        async def drop_after_noise():
-            await asyncio.sleep(0.05)
-            # Fire a noise event so the wait loop wakes and re-samples,
-            # THEN drop the WS so the next loop tick takes the REST
-            # fallback path.
-            await ws_client.fire_state_changed(
-                "automation.unrelated",
-                new_state={"attributes": {"id": "uid_other"}},
-            )
-            ws_client.is_connected = False
+        mock_client.get_states = AsyncMock(side_effect=get_states_dropping_ws)
 
-        drop_task = asyncio.create_task(drop_after_noise())
         result = await wait_for_automation_entity_by_unique_id(
             mock_client, "uid_drop", timeout=2.0, poll_interval=0.05
         )
-        await drop_task
 
         assert result == "automation.found_via_rest"
-        # REST fallback was actually exercised — at least one
-        # ``get_states()`` call past the initial post-subscribe sample.
-        assert mock_client.get_states.call_count >= 2
+        # At least one extra REST sample happened after the drop —
+        # proves the fallback path actually ran the discovery sample.
+        assert call_count["n"] >= 2
+        # Cleanup of the subscription we did establish still ran.
+        assert len(ws_client.unsubscribed) == 1