fix(policy): logger.info on silent decide-False; debug log on gt/lt type-mismatch; strengthen event-wake test (#966)

- ApprovalQueue.approve/deny: emit logger.info when the call returns
  False (unknown token or already decided) — was silent. Helps debug
  the case where the middleware's consume_and_maybe_remember races
  with an out-of-band decide.

- Evaluator gt/lt TypeError fallback now logs at debug so a user
  whose 'battery_level < 20' rule never fires can see that the arg
  came in as a string and tighten the rule.

- test_event_wakes_waiter now measures elapsed wait time and asserts
  < 200ms, ruling out a hidden poll-loop impl that would still pass
  the previous decision-only check.

Author: kingpanther13

src/ha_mcp/policy/approval_queue.py

@@ -4,13 +4,16 @@
 
 import hashlib
 import json
+import logging
 import secrets
 from dataclasses import dataclass, field
 from datetime import UTC, datetime, timedelta
 from typing import Any, Literal
 
 import anyio
 
+logger = logging.getLogger(__name__)
+
 Decision = Literal["pending", "approved", "denied"]
 
 
@@ -175,15 +178,31 @@ def approve(self, token: str) -> bool:
         """Mark the entry approved. Returns False if unknown or already decided."""
         entry = self._by_token.get(token)
         if entry is None:
+            logger.info("approval_queue.approve: unknown token %s", token)
             return False
-        return entry.decide("approved")
+        ok = entry.decide("approved")
+        if not ok:
+            logger.info(
+                "approval_queue.approve: token %s already decided as %s",
+                token,
+                entry.decision,
+            )
+        return ok
 
     def deny(self, token: str) -> bool:
         """Mark the entry denied. Returns False if unknown or already decided."""
         entry = self._by_token.get(token)
         if entry is None:
+            logger.info("approval_queue.deny: unknown token %s", token)
             return False
-        return entry.decide("denied")
+        ok = entry.decide("denied")
+        if not ok:
+            logger.info(
+                "approval_queue.deny: token %s already decided as %s",
+                token,
+                entry.decision,
+            )
+        return ok
 
     def remove(self, token: str) -> None:
         self._by_token.pop(token, None)

src/ha_mcp/policy/evaluator.py

@@ -1,12 +1,15 @@
 """Evaluate a tool call against a Policy. Pure functions — no I/O, no state."""
 
+import logging
 import re
 from collections.abc import Iterator
 from enum import StrEnum
 from typing import Any
 
 from .model import Policy, Predicate, Rule
 
+logger = logging.getLogger(__name__)
+
 
 class Verdict(StrEnum):
     ALLOW = "allow"
@@ -86,11 +89,20 @@ def _op_matches(val: Any, op: str, pv: Any) -> bool:
             try:
                 return bool(val > pv)
             except TypeError:
+                # Numeric rule against a non-numeric arg value — log so
+                # users can tell their "battery_level < 20" rule isn't
+                # silently never firing because the arg is a string.
+                logger.debug(
+                    "policy: gt type-mismatch (val=%r pv=%r) — predicate skipped", val, pv
+                )
                 return False
         case "lt":
             try:
                 return bool(val < pv)
             except TypeError:
+                logger.debug(
+                    "policy: lt type-mismatch (val=%r pv=%r) — predicate skipped", val, pv
+                )
                 return False
     return False
 

tests/src/unit/policy/test_approval_queue.py

@@ -169,11 +169,19 @@ async def approver():
         await anyio.sleep(0.05)
         q.approve(p.token)
 
+    elapsed: float = 0.0
     async with anyio.create_task_group() as tg:
         tg.start_soon(approver)
+        start = anyio.current_time()
         decision = await p.wait()
+        elapsed = anyio.current_time() - start
     assert decision == "approved"
     assert p.decision == "approved"
+    # Event-driven wake should land within ~50ms of the approver firing
+    # (plus scheduler jitter). A polling impl with a 1s tick would
+    # easily exceed 200ms here, so this asserts the event path actually
+    # runs and isn't a hidden poll loop.
+    assert elapsed < 0.2, f"wait() took {elapsed:.3f}s; expected event wake"
 
 
 # --- find_or_create + concurrency ---