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>

Author: Patch76

src/ha_mcp/client/rest_client.py

@@ -964,9 +964,12 @@ 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."""

tests/src/e2e/conftest.py

@@ -89,22 +89,18 @@
 _READINESS_TIMINGS: list[dict[str, Any]] = []
 _ALL_READINESS_TIMINGS: list[dict[str, Any]] = []
 
-# Same shape as ``_READINESS_TIMINGS``, parallel channel for the #1389
-# ``_POLL_CADENCE`` measurement. Lives at this conftest level (not deeper)
-# because pytest-xdist's master only loads conftests up to where tests
-# are collected; deeper subdir conftests don't get their hooks invoked
-# on the master, which is where ``pytest_terminal_summary`` writes to
-# the visible terminal output. See ``record_poll_cadence_measurement``
-# call site in ``workflows/automation/test_poll_cadence_measurement.py``.
+# Parallel channel for the #1389 ``_POLL_CADENCE`` measurement —
+# mirrors the xdist round-trip used by ``_READINESS_TIMINGS`` above.
 _POLL_CADENCE_MEASUREMENTS: list[dict[str, Any]] = []
 _ALL_POLL_CADENCE_MEASUREMENTS: list[dict[str, Any]] = []
 
 
 def record_poll_cadence_measurement(measurement: dict[str, Any]) -> None:
     """Record a single #1389 measurement run from a test method.
 
-    Expected keys: ``n``, ``attempts``, ``p50``, ``p90``, ``p99``, ``min``,
-    ``max``, ``not_verified``, ``verdict``, ``samples``.
+    See the call site in
+    ``workflows/automation/test_poll_cadence_measurement.py`` for the
+    measurement dict shape — that file owns the schema.
     """
     _POLL_CADENCE_MEASUREMENTS.append(measurement)
 
@@ -264,7 +260,8 @@ def pytest_terminal_summary(terminalreporter, exitstatus, config):
         for m in poll_measurements:
             terminalreporter.write_line(
                 f"[POLL_CADENCE_1389] N={m['n']}/{m.get('attempts', m['n'])} "
-                f"p50={m['p50']:.1f}ms p90={m['p90']:.1f}ms p99={m['p99']:.1f}ms "
+                f"p50={m['p50']:.1f}ms p90={m['p90']:.1f}ms "
+                f"worst={m['worst']:.1f}ms "
                 f"min={m['min']:.1f}ms max={m['max']:.1f}ms "
                 f"not_verified={m['not_verified']} VERDICT={m['verdict']}"
             )

tests/src/e2e/workflows/automation/test_poll_cadence_measurement.py

@@ -1,4 +1,4 @@
-"""Measurement test for issue #1389 — _POLL_CADENCE p50/p99 validation.
+"""Measurement test for issue #1389 — _POLL_CADENCE p50/worst validation.
 
 This test creates ``N=10`` automations cold-start, captures the
 ``entity-registration-elapsed`` DEBUG log line emitted by
@@ -12,9 +12,11 @@
 sharing one HA testcontainer would make a strict threshold-assert
 flaky). The "VERDICT" line in the output makes the result machine-greppable.
 
-Decision rule (per #1389):
-- ``p50 < 100 ms`` AND ``p99 < 1.0 s`` → cadence validated, close #1389
-- otherwise → open follow-up retune PR with the measurement table
+The headline metric is ``worst`` (highest observed sample) rather than
+a true statistical p99: at N=10 the 99th-percentile index collapses to
+the same bucket as p90, so the field would silently drop the
+outlier-detection role it was named for. ``worst`` reflects what the
+threshold-check actually measures.
 """
 
 import logging
@@ -32,6 +34,15 @@
 # on every successful registration. Format owned by that function.
 _ELAPSED_RE = re.compile(r"entity-registration-elapsed:\s*([\d.]+)ms")
 
+# Distinctive substring of the soft-failure warning ``ha_config_set_automation``
+# emits when ``_poll_for_automation_entity`` exhausts ``_POLL_CADENCE`` without
+# matching the new automation. The tool pops ``entity_not_verified`` from the
+# response, so this warning is the only reliable signal that a registration
+# missed. Mirrors the literal in ``tools_config_automations.py``.
+_NOT_VERIFIED_WARNING_PREFIX = (
+    "Automation was submitted to Home Assistant but the entity was not found"
+)
+
 
 @pytest.mark.automation
 @pytest.mark.cleanup
@@ -51,128 +62,151 @@ class TestPollCadenceMeasurement1389:
 
     N_SAMPLES = 10
 
-    async def test_poll_cadence_p50_p99(
+    async def test_poll_cadence_p50_worst(
         self, mcp_client, cleanup_tracker, test_data_factory, caplog
     ):
-        # Capture the DEBUG records emitted by ``_poll_for_automation_entity``
-        # during this test only. ``caplog`` is per-test-method-scoped, so
-        # records emitted by other tests in the same worker (before or
-        # after this one) don't appear in ``caplog.records`` here. The
-        # rest_client logger-name filter + regex below narrow to the
-        # elapsed-ms records specifically, and ``caplog.clear()`` at entry
-        # is belt-and-suspenders for any setup-phase noise.
-        caplog.set_level(logging.DEBUG, logger="ha_mcp.client.rest_client")
-
-        # Clear any pre-existing matching records so a long-running worker's
-        # earlier automation creates don't leak into our sample set.
-        caplog.clear()
-
-        not_verified_count = 0
-        for i in range(self.N_SAMPLES):
-            config = test_data_factory.automation_config(
-                f"Poll Cadence Measurement 1389-{i:02d}",
+        # ``caplog.at_level`` saves+restores the logger level on exit;
+        # ``caplog.set_level`` would leave DEBUG-on-rest_client sticky
+        # for every later test on the same xdist worker. Wraps only the
+        # create-loop so unrelated DEBUG noise from teardown stays out.
+        created_entity_ids: list[str] = []
+        try:
+            with caplog.at_level(logging.DEBUG, logger="ha_mcp.client.rest_client"):
+                caplog.clear()
+                not_verified_count = 0
+                for i in range(self.N_SAMPLES):
+                    config = test_data_factory.automation_config(
+                        f"Poll Cadence Measurement 1389-{i:02d}",
+                    )
+                    create_data = await safe_call_tool(
+                        mcp_client, "ha_config_set_automation", {"config": config}
+                    )
+                    assert create_data.get("success"), (
+                        f"automation creation #{i} failed: {create_data}"
+                    )
+                    entity_id = create_data.get("entity_id")
+                    if (
+                        entity_id
+                        and isinstance(entity_id, str)
+                        and entity_id.startswith("automation.")
+                    ):
+                        cleanup_tracker.track("automation", entity_id)
+                        created_entity_ids.append(entity_id)
+                    # ``ha_config_set_automation`` pops ``entity_not_verified``
+                    # off the response before returning and translates the
+                    # miss into a ``warnings`` entry — scan that instead.
+                    # Missing this signal would let a "RETUNE NEEDED" run
+                    # silently print VERDICT=VALIDATED.
+                    warnings = create_data.get("warnings") or []
+                    if any(
+                        isinstance(w, str)
+                        and w.startswith(_NOT_VERIFIED_WARNING_PREFIX)
+                        for w in warnings
+                    ):
+                        not_verified_count += 1
+
+            # Parse elapsed-ms values out of captured DEBUG records.
+            samples: list[float] = []
+            for record in caplog.records:
+                if record.name != "ha_mcp.client.rest_client":
+                    continue
+                match = _ELAPSED_RE.search(record.getMessage())
+                if match:
+                    samples.append(float(match.group(1)))
+
+            assert samples, (
+                f"No 'entity-registration-elapsed' DEBUG records captured after "
+                f"{self.N_SAMPLES} automation creations. Either the instrumentation "
+                f"is missing, the logger name changed, or the format regex drifted."
+            )
+
+            # Sample-count invariant pairs with the miss detection above:
+            # every successful iteration must contribute exactly one elapsed
+            # record. A partial capture (9 samples + 1 miss not detected by
+            # the warning scan) would silently skew percentiles otherwise.
+            assert len(samples) + not_verified_count == self.N_SAMPLES, (
+                f"sample-count invariant violated: {len(samples)} samples + "
+                f"{not_verified_count} not-verified != {self.N_SAMPLES} attempts"
+            )
+
+            samples.sort()
+            n = len(samples)
+            p50 = statistics.median(samples)
+            p90 = samples[max(0, int(0.9 * n) - 1)]
+            # At N=10, ``int(0.99 * (n-1))`` collapses to the same index as
+            # p90 — a real statistical p99 needs more samples. Use the
+            # highest observed sample under the name ``worst`` so the
+            # decision-rule threshold reflects what it actually checks.
+            worst = samples[-1]
+            s_min = samples[0]
+            s_max = samples[-1]
+
+            p50_ok = p50 < 100.0
+            worst_ok = worst < 1000.0
+            no_misses = not_verified_count == 0
+            verdict = (
+                "VALIDATED" if (p50_ok and worst_ok and no_misses) else "RETUNE NEEDED"
+            )
+
+            # ``logger.info`` from a test method is captured by pytest-xdist's
+            # per-worker buffer and only surfaces on FAILURE — PASSED tests
+            # silently drop the INFO output. Route through the conftest
+            # recorder so ``pytest_terminal_summary`` renders the table on
+            # the master, outside the capture buffer.
+            record_poll_cadence_measurement(
+                {
+                    "n": n,
+                    "attempts": self.N_SAMPLES,
+                    "p50": p50,
+                    "p90": p90,
+                    "worst": worst,
+                    "min": s_min,
+                    "max": s_max,
+                    "not_verified": not_verified_count,
+                    "verdict": verdict,
+                    "samples": [round(s, 1) for s in samples],
+                }
+            )
+
+            sep = "=" * 70
+            logger.info(sep)
+            logger.info(
+                "#1389 _POLL_CADENCE measurement (N=%d successful samples / %d attempts, "
+                "%d not-verified)",
+                n,
+                self.N_SAMPLES,
+                not_verified_count,
             )
-            create_data = await safe_call_tool(
-                mcp_client, "ha_config_set_automation", {"config": config}
+            logger.info(sep)
+            logger.info(
+                "p50   = %6.1f ms  (rule: < 100ms  → %s)",
+                p50,
+                "PASS" if p50_ok else "RETUNE",
             )
-            assert create_data.get("success"), (
-                f"automation creation #{i} failed: {create_data}"
+            logger.info("p90   = %6.1f ms", p90)
+            logger.info(
+                "worst = %6.1f ms  (rule: < 1000ms → %s)",
+                worst,
+                "PASS" if worst_ok else "RETUNE",
             )
-            entity_id = create_data.get("entity_id")
-            if (
-                entity_id
-                and isinstance(entity_id, str)
-                and entity_id.startswith("automation.")
-            ):
-                cleanup_tracker.track("automation", entity_id)
-            # Track misses — when _poll_for_automation_entity returns None
-            # after exhausting _POLL_CADENCE, the create_data carries this
-            # flag and no elapsed-ms record is emitted for that iteration.
-            # Such misses are themselves evidence that the cadence is too
-            # short (p99 >= sum(_POLL_CADENCE) = 6.0s), so a high miss
-            # rate flips the decision toward RETUNE.
-            if create_data.get("entity_not_verified"):
-                not_verified_count += 1
-
-        # Parse elapsed-ms values out of captured DEBUG records.
-        samples: list[float] = []
-        for record in caplog.records:
-            if record.name != "ha_mcp.client.rest_client":
-                continue
-            match = _ELAPSED_RE.search(record.getMessage())
-            if match:
-                samples.append(float(match.group(1)))
-
-        assert samples, (
-            f"No 'entity-registration-elapsed' DEBUG records captured after "
-            f"{self.N_SAMPLES} automation creations. Either the instrumentation "
-            f"is missing, the logger name changed, or the format regex drifted."
-        )
-
-        samples.sort()
-        n = len(samples)
-        p50 = statistics.median(samples)
-        p90 = samples[max(0, int(0.9 * n) - 1)]
-        # For small ``N_SAMPLES`` (=10), ``int(0.99 * (n-1))`` collapses to
-        # the same index as p90 (both → 8 for n=10), silently dropping the
-        # worst-case sample. Use the maximum as p99 so an outlier can't
-        # violate the decision-rule threshold without surfacing.
-        p99 = samples[-1]
-        s_min = samples[0]
-        s_max = samples[-1]
-
-        # Decision rule per #1389 body. Any not-verified iteration is itself
-        # a p99 ≥ 6.0s signal (cadence exhausted without match) and flips to
-        # RETUNE regardless of the measured samples.
-        p50_ok = p50 < 100.0
-        p99_ok = p99 < 1000.0
-        no_misses = not_verified_count == 0
-        verdict = "VALIDATED" if (p50_ok and p99_ok and no_misses) else "RETUNE NEEDED"
-
-        # ``logger.info`` from a test method is captured by pytest-xdist's
-        # per-worker buffer and only surfaces on FAILURE — PASSED tests
-        # silently drop the INFO output. Route through the conftest
-        # recorder so ``pytest_terminal_summary`` renders the table on
-        # the master, outside the capture buffer. Logger calls below
-        # remain for local ad-hoc runs (where xdist is off and INFO
-        # streams to the terminal directly).
-        record_poll_cadence_measurement(
-            {
-                "n": n,
-                "attempts": self.N_SAMPLES,
-                "p50": p50,
-                "p90": p90,
-                "p99": p99,
-                "min": s_min,
-                "max": s_max,
-                "not_verified": not_verified_count,
-                "verdict": verdict,
-                "samples": [round(s, 1) for s in samples],
-            }
-        )
-
-        sep = "=" * 70
-        logger.info(sep)
-        logger.info(
-            "#1389 _POLL_CADENCE measurement (N=%d successful samples / %d attempts, "
-            "%d not-verified)",
-            n,
-            self.N_SAMPLES,
-            not_verified_count,
-        )
-        logger.info(sep)
-        logger.info(
-            "p50 = %6.1f ms  (rule: < 100ms  → %s)",
-            p50,
-            "PASS" if p50_ok else "RETUNE",
-        )
-        logger.info("p90 = %6.1f ms", p90)
-        logger.info(
-            "p99 = %6.1f ms  (rule: < 1000ms → %s)",
-            p99,
-            "PASS" if p99_ok else "RETUNE",
-        )
-        logger.info("min = %6.1f ms  / max = %6.1f ms", s_min, s_max)
-        logger.info("samples (sorted, ms): %s", [round(s, 1) for s in samples])
-        logger.info("VERDICT: %s", verdict)
-        logger.info(sep)
+            logger.info("min   = %6.1f ms  / max = %6.1f ms", s_min, s_max)
+            logger.info("samples (sorted, ms): %s", [round(s, 1) for s in samples])
+            logger.info("VERDICT: %s", verdict)
+            logger.info(sep)
+        finally:
+            # The session-scoped ``cleanup_tracker`` fixture only logs what
+            # it tracked; without an explicit delete here this test would
+            # leak 10 automations into the next worker run on a loadscope
+            # split. Best-effort: per-entity remove, swallow individual
+            # failures so cleanup doesn't mask the real assertion outcome.
+            for ent_id in created_entity_ids:
+                try:
+                    await safe_call_tool(
+                        mcp_client,
+                        "ha_config_remove_automation",
+                        {"identifier": ent_id},
+                    )
+                except Exception as cleanup_err:
+                    logger.warning(
+                        "cleanup: failed to remove %s: %s", ent_id, cleanup_err
+                    )