test(e2e): measure _POLL_CADENCE p50/p99 to validate or retune (closes #1389) (#1398)

* test(e2e): measure _POLL_CADENCE p50/p99 to validate or retune (closes #1389)

#1389's pre-committed decision rule needs empirical p50/p99 numbers for
automation-entity-registration latency on the post-#1384 cadence
``_POLL_CADENCE = (0.1, 1.0, 4.9)``. Two pieces:

1. ``rest_client._poll_for_automation_entity`` now emits a DEBUG line
   ``entity-registration-elapsed: %.1fms`` measuring cumulative time from
   function entry (right after the automation POST returns) to the first
   successful ``get_states()`` match. Always-on instrumentation, near-zero
   cost (one ``time.monotonic()`` pair per registration).

2. New e2e test ``TestPollCadenceMeasurement1389`` creates N=10 automations
   cold-start, captures the DEBUG records via ``caplog``, computes p50 /
   p90 / p99, and reports the table at INFO so it surfaces in CI logs
   (default ``log_cli_level=INFO``). The decision-rule outcome
   (``VALIDATED`` vs ``RETUNE NEEDED``) is logged as a machine-greppable
   ``VERDICT`` line.

The test is report-only — no threshold assertion. CI latency variance from
parallel pytest-xdist workers sharing one HA testcontainer makes a strict
threshold assertion flaky. The decision rule is applied to the reported
numbers via a PR comment after CI runs.

Cumulative not-verified iterations (``_poll_for_automation_entity``
returning ``None`` after exhausting the 6.0s cadence) are themselves
``p99 ≥ 6000ms`` evidence and flip ``VERDICT`` to ``RETUNE`` regardless
of the measured samples.

* test(e2e): address Gemini findings + skip inaddon on poll-cadence measurement

Three fixes on the new ``test_poll_cadence_measurement.py``:

1. **Comment accuracy** (Gemini ``:51``). The prior comment claimed
   cross-test pollution was bounded by "registrations matched against
   the unique ID prefix below", but the parsing loop never filters by
   unique_id. The actual protection is that ``caplog`` is per-test-
   method-scoped — other tests' records don't appear in
   ``caplog.records`` here. Comment now describes the real mechanism.

2. **Percentile calculation** (Gemini ``:104``). For ``N=10``,
   ``int(0.99 * (n-1)) == 8`` collapses to the same index as p90,
   silently dropping the worst-case sample. ``p99`` is now
   ``samples[-1]`` so an outlier can't violate the decision-rule
   threshold without surfacing. ``p90`` formula simplified to
   ``int(0.9 * n) - 1`` (numerically identical for both ``N=10`` and
   typical larger N, just clearer reading).

3. **HAOS-inaddon skip**. Class now carries ``@pytest.mark.external_only``
   because ``caplog`` only captures DEBUG records emitted in pytest's
   own process; on the HAOS-inaddon tier the rest_client lives in the
   addon's separate process and the records never reach ``caplog``.
   Without this marker the test fires its
   "No 'entity-registration-elapsed' DEBUG records captured" assertion
   as a false-negative — observed on the first CI run.

* test(e2e): surface #1389 measurement via terminal-summary hook

``logger.info`` from a test method is captured by pytest-xdist's per-worker
buffer and only surfaces on FAILURE — the prior commit's PASSED run
dropped the measurement table silently. Without the data, the #1389
pre-committed decision rule (p50 < 100ms ∧ p99 < 1.0s → close vs.
retune) cannot be applied, defeating the PR's stated purpose.

Mirrors the established ``Readiness gate timings`` pattern in
``tests/src/e2e/conftest.py`` (introduced for #1310, consolidated for
#366): worker-side list → ``pytest_sessionfinish`` ships via
``workeroutput`` → ``pytest_testnodedown`` aggregates on master →
``pytest_terminal_summary`` renders a ``#1389 _POLL_CADENCE measurement``
section outside the per-worker capture buffer.

- New ``tests/src/e2e/workflows/automation/conftest.py`` with the 3-hook
  pattern and a public ``record_poll_cadence_measurement(dict)`` helper.
- Test method now calls the helper alongside the existing ``logger.info``
  calls (kept for local-without-xdist runs).
- CI logs will surface ``[POLL_CADENCE_1389] N=X/10 p50=… p99=… VERDICT=…``
  lines that the IS / closing comment on #1389 cite directly.

* fix(test): move #1389 measurement hooks to root e2e conftest

The prior fold placed the ``pytest_sessionfinish`` / ``pytest_testnodedown``
/ ``pytest_terminal_summary`` hooks at
``tests/src/e2e/workflows/automation/conftest.py``. CI re-ran cleanly,
test passed, but the measurement section still didn't surface — the
xdist master only loads conftests up to where tests are collected, and
``pytest_terminal_summary`` (which writes to the visible terminal) is a
master-only hook. Deep subdir conftests don't get their hooks invoked
on the master.

The Readiness gate timings pattern works because its hooks live at
``tests/src/e2e/conftest.py`` (the root e2e conftest the master always
loads). Same fix here: move the storage, the
``record_poll_cadence_measurement`` helper, and the three hook
extensions to the root conftest alongside the readiness ones. The deep
``workflows/automation/conftest.py`` is removed; the measurement test
imports the helper from the root.

* refactor: address PR #1398 KP13 review (8 of 9 items + retune)

- entity_not_verified detection via warnings-substring scan
  (#1297-popped flag was dead — VERDICT=VALIDATED could leak silently)
- sample-count invariant: len(samples) + not_verified == N_SAMPLES
- rename "p99" -> "worst" (at N=10 the percentile collapses to max;
  the threshold-check name now reflects what it measures)
- per-test try/finally cleanup: cleanup_tracker is a logging-only no-op,
  so 10 automations were leaking into the next worker run
- caplog.at_level context manager (set_level mutated worker-wide level
  and leaked DEBUG-on-rest_client into every later test)
- 6 comment subtractions per Boy-Scout

Boy-Scout retune from #1389 measurement (RETUNE NEEDED p50>=100ms):

- _POLL_CADENCE: (0.1, 1.0, 4.9) -> (0.025, 1.0, 4.975) — first-poll
  pulled to a 5x cushion above the measured ~4ms HA-Core
  entity-registration latency
- unit-test pins updated to the new cadence values

The HAOS proxy-header flake item from KP13's review landed
independently on master via #1402 (_wait_addon_running guard);
intentionally not duplicated here.

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

* refactor: address PR #1398 KP13 second-pass review (3 items)

1. Narrow cleanup-loop exception in test_poll_cadence_measurement.py from
   `except Exception` to `except _POLLING_TRANSIENT_ERRORS` (the canonical
   tuple from wait_helpers.py). Programmer bugs (TypeError, AttributeError,
   KeyError, AssertionError) now propagate with their stack trace instead
   of being downgraded to a `logger.warning` line across 10 iterations.
   Aligns per-entity cleanup with the polling-helper pattern established
   for AGENTS.md "Exception handling in polling helpers" (#1266).

2. Lift the soft-failure warning prefix out of tools_config_automations.py
   as module-level `NOT_VERIFIED_WARNING_PREFIX` and import it in the test.
   The literal coupling becomes a compile-time edge instead of a runtime
   puzzle — rewording the source warning now breaks the test import,
   replacing the previous "9 samples + 0 not-verified != 10 attempts"
   indirect signal with a clear ModuleNotFoundError-style failure.

3. Replace the stale `session-scoped` label in the cleanup-block comment
   with `logging-only` (matches the commit-message framing for the
   ``cleanup_tracker`` fixture, which is function-scoped per its
   `@pytest.fixture` decorator in tests/src/e2e/conftest.py:1951).

* chore: apply ruff format to PR-touched files (refs #1318)

Pre-existing format-debt on ``src/ha_mcp/tools/tools_config_automations.py``
became blocking once 4fd2852 added it to the PR's changed-files set —
``.github/workflows/pr.yml`` runs ``ruff format --check`` whole-file on
every Python file in the PR diff, with the "grandfathered for untouched
files" gate per the maintainer call on #1318.

The 230-line diff on ``tools_config_automations.py`` is pure mechanical
``ruff format`` output: line-break placement on ``raise_tool_error(...)``
wrappers, multi-line argument splits, and dict-literal expansion. No
logic, no semantic, no behavior change. Belongs to the #1318 sweep but
has to land in this PR because the file is now in the touched set.

The 1-line diff on ``test_poll_cadence_measurement.py`` (``isinstance(w,
str) and w.startswith(...)`` collapsed to a single line) is the natural
follow-on to the constant rename in 4fd2852 — the shorter name fits
within 88 chars.

---------

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

Author: Patch76

src/ha_mcp/client/rest_client.py

@@ -7,6 +7,7 @@
 import logging
 import os
 import ssl
+import time
 from typing import Any
 
 import httpx
@@ -963,12 +964,18 @@ async def upsert_automation_config(
                 ) from e
             raise
 
-    # 3-attempt × 6s upper-bound budget; first poll 0.1s catches the
-    # typical sub-1s entity-publish window.
-    _POLL_CADENCE: tuple[float, ...] = (0.1, 1.0, 4.9)
+    # 3-attempt × 6s upper-bound budget; first poll 0.025s is a 5×
+    # cushion above the ~4ms HA-Core entity-registration latency
+    # measured by ``test_poll_cadence_measurement.py`` (#1389 — p50
+    # 104.1-104.8 ms on the prior 0.1s first-poll, all from the sleep
+    # itself with ~4 ms of real registration work).
+    _POLL_CADENCE: tuple[float, ...] = (0.025, 1.0, 4.975)
 
     async def _poll_for_automation_entity(self, unique_id: str) -> str | None:
         """Poll HA state to find the entity_id assigned to a newly created automation."""
+        # Measure cumulative elapsed from function entry to first successful match.
+        # Feeds the #1389 p50/p99 validation of `_POLL_CADENCE`.
+        start_monotonic = time.monotonic()
         try:
             for sleep_time in self._POLL_CADENCE:
                 await asyncio.sleep(sleep_time)
@@ -978,8 +985,13 @@ async def _poll_for_automation_entity(self, unique_id: str) -> str | None:
                         continue
                     if state.get("attributes", {}).get("id") == unique_id:
                         entity_id = state.get("entity_id")
+                        elapsed_ms = (time.monotonic() - start_monotonic) * 1000.0
                         logger.debug(
-                            f"Found actual entity_id for unique_id {unique_id}: {entity_id}"
+                            "entity-registration-elapsed: %.1fms "
+                            "(unique_id=%s, entity_id=%s)",
+                            elapsed_ms,
+                            unique_id,
+                            entity_id,
                         )
                         return entity_id
         except HomeAssistantError as e: