fix: tighten HAOS cache guards and visibility logs (#2240)

* fix: tighten HAOS cache guards and visibility logs

* fix: address follow-up review findings

* Test HAOS cache keys per workflow job

Author: kingpanther13

src/ha_mcp/visibility/enforcement.py

@@ -49,6 +49,7 @@
 import re
 import time
 from collections.abc import Callable
+from contextvars import ContextVar
 from typing import TYPE_CHECKING, Any, NoReturn
 
 from fastmcp.exceptions import ToolError
@@ -72,6 +73,10 @@
 
 logger = logging.getLogger(__name__)
 
+_config_load_warning_emitted: ContextVar[bool | None] = ContextVar(
+    "visibility_config_load_warning_emitted", default=None
+)
+
 # The resolved hidden set is cached with a short TTL so a burst of tool calls
 # does not re-fetch the registry each time; a config edit invalidates it sooner
 # (the cache is keyed on the hide dimensions), so the ~30s window only applies to
@@ -353,6 +358,10 @@ async def _active_config(
         loaded successfully — for the common non-enforce install that preserves
         availability, and for an enforce install it preserves the boundary.
         With no good load ever, fail CLOSED like PolicyMiddleware does.
+
+        Each half diagnoses a distinct config-load failure. A context-local
+        marker suppresses only the second traceback when both halves fail during
+        the same call.
         """
         config: VisibilityConfig | None
         try:
@@ -369,12 +378,15 @@ async def _active_config(
                 )
             else:
                 outcome = "failing closed"
-            if tool_name != _REPORT_ISSUE_TOOL or emit_report_issue_diagnostic:
+            warning_emitted = _config_load_warning_emitted.get()
+            if warning_emitted is not True:
                 logger.warning(
                     "visibility enforce: config load failed; %s",
                     outcome,
                     exc_info=True,
                 )
+                if warning_emitted is not None:
+                    _config_load_warning_emitted.set(True)
         # ``ha_report_issue`` is an unconditional diagnostic escape hatch while
         # the toggle is off, not only a registry-failure fallback. A missing or
         # corrupt first config load follows that safe default; a last-known-good
@@ -423,6 +435,15 @@ class VisibilityInboundEnforcement(_VisibilityEnforcementBase):
 
     async def on_call_tool(
         self, context: MiddlewareContext, call_next: CallNext
+    ) -> Any:
+        token = _config_load_warning_emitted.set(False)
+        try:
+            return await self._on_call_tool(context, call_next)
+        finally:
+            _config_load_warning_emitted.reset(token)
+
+    async def _on_call_tool(
+        self, context: MiddlewareContext, call_next: CallNext
     ) -> Any:
         name = context.message.name
         args = context.message.arguments or {}

tests/src/unit/test_haos_image_workflow_shape.py

@@ -7,13 +7,14 @@
 
 _REPO_ROOT = Path(__file__).resolve().parents[3]
 _WORKFLOW_DIR = _REPO_ROOT / ".github" / "workflows"
-_CACHE_KEY_CONSUMERS = (
-    "build-haos-test-image.yml",
-    "haos-e2e-tests.yml",
-    "haos-e2e-embedded-tests.yml",
-    "haos-e2e-inaddon-tests.yml",
-    "haos-e2e-stdio-tests.yml",
-)
+_CACHE_KEY_CONSUMER_FLOOR = 5
+_CACHE_KEY_OUTPUT_MARKER = "cache-key=haos-image-"
+_HAOS_IMAGE_CACHE_PATH = "/tmp/haos-test-image.qcow2"
+_CACHE_ACTIONS = {
+    "actions/cache",
+    "actions/cache/restore",
+    "actions/cache/save",
+}
 _CACHE_KEY_COMMAND = """hash=$(git ls-tree -r HEAD \\
   tests/haos_image_build \\
   tests/initial_test_state \\
@@ -28,30 +29,106 @@ def _workflow(path: Path) -> dict[str, Any]:
     return yaml.safe_load(path.read_text(encoding="utf-8"))
 
 
-def _cache_key_command(path: Path) -> str:
-    workflow = _workflow(path)
-    steps = [
+def _job_steps(job: dict[str, Any]) -> list[dict[str, Any]]:
+    return [step for step in job.get("steps", []) if isinstance(step, dict)]
+
+
+def _cache_key_steps(job: dict[str, Any]) -> list[dict[str, Any]]:
+    return [
         step
-        for job in workflow["jobs"].values()
-        for step in job.get("steps", [])
-        if "image cache key" in str(step.get("name", "")).lower()
+        for step in _job_steps(job)
+        if _CACHE_KEY_OUTPUT_MARKER in str(step.get("run", ""))
+    ]
+
+
+def _uses_haos_image_cache(job: dict[str, Any]) -> bool:
+    return any(
+        str(step.get("uses", "")).partition("@")[0] in _CACHE_ACTIONS
+        and _HAOS_IMAGE_CACHE_PATH
+        in str(step.get("with", {}).get("path", "")).splitlines()
+        for step in _job_steps(job)
+    )
+
+
+def _cache_key_consumers(
+    workflow_dir: Path = _WORKFLOW_DIR,
+) -> list[tuple[Path, str]]:
+    workflow_paths = sorted((*workflow_dir.glob("*.yml"), *workflow_dir.glob("*.yaml")))
+    consumers = [
+        (path, str(job_id))
+        for path in workflow_paths
+        for job_id, job in _workflow(path)["jobs"].items()
+        if isinstance(job, dict) and _uses_haos_image_cache(job)
     ]
-    assert len(steps) == 1, f"{path.name} must have one image cache-key step"
+    assert len(consumers) >= _CACHE_KEY_CONSUMER_FLOOR, (
+        "expected at least "
+        f"{_CACHE_KEY_CONSUMER_FLOOR} HAOS image cache-key consumers, found "
+        f"{[(path.name, job_id) for path, job_id in consumers]}"
+    )
+    return consumers
+
+
+def _cache_key_command(path: Path, job_id: str) -> str:
+    consumer = f"{path.name}:{job_id}"
+    job = _workflow(path)["jobs"][job_id]
+    assert isinstance(job, dict), f"{consumer} must be a job mapping"
+    steps = _cache_key_steps(job)
+    assert len(steps) == 1, f"{consumer} must have one image cache-key step"
     script = str(steps[0]["run"])
     start_marker = "hash=$(git ls-tree -r HEAD"
     end_marker = 'echo "cache-key=haos-image-$hash" >> "$GITHUB_OUTPUT"\n'
     assert script.count(start_marker) == 1, (
-        f"{path.name} must have one cache-key command"
+        f"{consumer} must have one cache-key command"
     )
     assert script.count(end_marker) == 1, (
-        f"{path.name} must emit one HAOS image cache key"
+        f"{consumer} must emit one HAOS image cache key"
     )
     start = script.index(start_marker)
     end = script.index(end_marker, start) + len(end_marker)
     return script[start:end]
 
 
 def test_haos_image_cache_key_command_matches_every_consumer() -> None:
-    for filename in _CACHE_KEY_CONSUMERS:
-        path = _WORKFLOW_DIR / filename
-        assert _cache_key_command(path) == _CACHE_KEY_COMMAND, filename
+    for path, job_id in _cache_key_consumers():
+        consumer = f"{path.name}:{job_id}"
+        assert _cache_key_command(path, job_id) == _CACHE_KEY_COMMAND, consumer
+
+
+def test_cache_key_consumer_discovery_is_marker_independent(tmp_path: Path) -> None:
+    workflow = """jobs:
+  lane:
+    steps:
+      - uses: actions/cache/restore@pinned
+        with:
+          path: /tmp/haos-test-image.qcow2
+          key: shared
+"""
+    expected = []
+    for index in range(_CACHE_KEY_CONSUMER_FLOOR):
+        path = tmp_path / f"lane-{index}.yaml"
+        path.write_text(workflow, encoding="utf-8")
+        expected.append((path, "lane"))
+
+    assert _cache_key_consumers(tmp_path) == expected
+
+
+def test_cache_key_consumer_discovery_tracks_jobs_individually(
+    tmp_path: Path,
+) -> None:
+    path = tmp_path / "multi-lane.yaml"
+    jobs = {
+        f"lane-{index}": {
+            "steps": [
+                {
+                    "uses": "actions/cache/restore@pinned",
+                    "with": {"path": _HAOS_IMAGE_CACHE_PATH, "key": "shared"},
+                }
+            ]
+        }
+        for index in range(_CACHE_KEY_CONSUMER_FLOOR)
+    }
+    path.write_text(yaml.safe_dump({"jobs": jobs}), encoding="utf-8")
+
+    assert _cache_key_consumers(tmp_path) == [
+        (path, f"lane-{index}") for index in range(_CACHE_KEY_CONSUMER_FLOOR)
+    ]

tests/src/unit/visibility/test_enforcement.py

@@ -469,7 +469,7 @@ async def test_corrupt_config_with_no_prior_load_keeps_report_issue_available(
         assert not any("failing closed" in message for message in messages), messages
 
     async def test_corrupt_config_after_enforce_off_load_passes_through(
-        self, breakable_config
+        self, breakable_config, caplog
     ):
         # Availability: a non-enforce install whose file corrupts mid-session
         # keeps working on the last-known-good (enforce-off) config.
@@ -480,11 +480,58 @@ async def test_corrupt_config_after_enforce_off_load_passes_through(
         )
         assert result.content[0].text == "first"
         breakable_config["broken"] = True
-        result = await mw.on_call_tool(
+        caplog.clear()
+        with caplog.at_level("WARNING", logger="ha_mcp.visibility.enforcement"):
+            result = await mw.on_call_tool(
+                make_context("ha_get_state", {"entity_id": "light.any"}),
+                _returns(text_result("second")),
+            )
+        assert result.content[0].text == "second"
+        warnings = [
+            record
+            for record in caplog.records
+            if "config load failed" in record.message
+        ]
+        assert [record.message for record in warnings] == [
+            "visibility enforce: config load failed; using last-known-good config"
+        ]
+        assert warnings[0].exc_info is not None
+
+    async def test_outbound_only_config_load_failure_logs(
+        self, breakable_config, monkeypatch, caplog
+    ):
+        mw = make_mw(get_client=FakeClient)
+        await mw.on_call_tool(
             make_context("ha_get_state", {"entity_id": "light.any"}),
-            _returns(text_result("second")),
+            _returns(text_result("prime")),
         )
+        calls = 0
+
+        def _load(_d):
+            nonlocal calls
+            calls += 1
+            if calls == 1:
+                return breakable_config["config"]
+            raise ValueError("entity_visibility.json changed during the call")
+
+        monkeypatch.setattr(resolver, "load_visibility_config", _load)
+        caplog.clear()
+        with caplog.at_level("WARNING", logger="ha_mcp.visibility.enforcement"):
+            result = await mw.on_call_tool(
+                make_context("ha_get_state", {"entity_id": "light.any"}),
+                _returns(text_result("second")),
+            )
+
         assert result.content[0].text == "second"
+        warnings = [
+            record
+            for record in caplog.records
+            if "config load failed" in record.message
+        ]
+        assert [record.message for record in warnings] == [
+            "visibility enforce: config load failed; using last-known-good config"
+        ]
+        assert warnings[0].exc_info is not None
 
     async def test_corrupt_config_after_enforce_on_load_stays_enforced(
         self, breakable_config