slaguru666/AIPass
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix(prax): hook events render styled in monitor — regex required phantom action= field (td-007)

Browse Source 
Root cause: _HOOK_PATTERN required an action= key that cadence never
emits — it logs the action as the bare second word (fired/skipped).
Extraction failed, so events never reached the styled print_hook_event
renderer (bold-green lightning / dim dot). Pipeline was already correct.

- _HOOK_PATTERN -> bare-word capture: r'\[HOOKS\]\s+(\w+)\s+(\w+)'
- enriched hook event detail (period, offset, short session id)
- corrected docstring that documented the phantom action= format
- tests updated to real production format + real-pipeline test added
- type:ignore on watchdog imports (repo convention)

Verified: 914/914 prax suite green (90 log_watcher). @prax dispatched
for full-pipeline trace; stale monitor process explained the no-show.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
AIOSAI
2026-06-09 20:16:16 -07:00
co-authored by Claude Fable 5
parent fc4b263504
commit 73aedef20f
2 changed files with 66 additions and 17 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/aipass/prax/apps/handlers/monitoring/log_watcher.py
+19 -8
View File
@@ -28,8 +28,8 @@ from typing import Optional, Dict, Any
import re
from aipass.prax.apps.modules.logger import get_direct_logger
from watchdog.observers import Observer as WatchdogObserver
from watchdog.events import FileSystemEventHandler
from watchdog.observers import Observer as WatchdogObserver # type: ignore
from watchdog.events import FileSystemEventHandler # type: ignore
# Import from prax config
from aipass.prax.apps.handlers.config.load import get_system_logs_dir
@@ -163,14 +163,16 @@ class LogFileWatcher(FileSystemEventHandler):
except Exception as e:
logger.info(f"Error reading log file {file_path}: {e}")
_HOOK_PATTERN = re.compile(r"\[HOOKS\]\s+(\w+)\s+.*?action=(\w+)")
_HOOK_PATTERN = re.compile(r"\[HOOKS\]\s+(\w+)\s+(\w+)")
def _extract_hook_info(self, log_line: str) -> Optional[Dict[str, str]]:
"""Extract hook event info from structured [HOOKS] log lines.
Matches lines like:
[HOOKS] cadence fired loader=global action=fired turn=35 period=5 ...
[HOOKS] cadence skipped loader=branch action=skipped turn=37 period=5 ...
The action is the bare second word (matches what hooks emits), e.g.:
[HOOKS] cadence fired loader=global turn=35 period=5 offset=0 session=...
[HOOKS] cadence skipped loader=branch turn=37 period=5 offset=0 session=...
group(1)=name (cadence), group(2)=action (fired/skipped). Remaining
key=value fields are parsed by the finditer loop below.
"""
match = self._HOOK_PATTERN.search(log_line)
if not match:
@@ -188,12 +190,21 @@ class LogFileWatcher(FileSystemEventHandler):
name = hook_info.get("name", "hook")
loader = hook_info.get("loader", "")
turn = hook_info.get("turn", "")
period = hook_info.get("period", "")
offset = hook_info.get("offset", "")
session = hook_info.get("session", "")
parts = [f"{name}:{action}"]
if loader:
parts.append(f"loader={loader}")
if turn:
parts.append(f"turn={turn}")
parts.append(f"t={turn}")
if period:
parts.append(f"p={period}")
if offset and offset != "0":
parts.append(f"off={offset}")
if session:
parts.append(f"s={session[:8]}")
message = " ".join(parts)
level = "success" if action == "fired" else "info"
@@ -533,7 +544,7 @@ def start_log_watcher(event_queue: MonitoringQueue, use_polling: bool = False) -
# Create observer — polling fallback when inotify unavailable
if use_polling:
from watchdog.observers.polling import PollingObserver
from watchdog.observers.polling import PollingObserver # type: ignore
observer = PollingObserver(timeout=1)
logger.info("Log watcher using polling observer (1s interval)")
src/aipass/prax/tests/test_log_watcher.py
+47 -9
View File
@@ -1073,7 +1073,8 @@ class TestExtractHookInfo:
mod = _import_log_watcher()
watcher, _ = _make_watcher(mod)
line = "[HOOKS] cadence fired loader=global action=fired turn=35 period=5 offset=0 session=abc12345"
# Real format hooks emits: action is the bare second word, no action= field.
line = "[HOOKS] cadence fired loader=global turn=35 period=5 offset=0 session=abc12345"
result = watcher._extract_hook_info(line)
assert result is not None
assert result["name"] == "cadence"
@@ -1086,7 +1087,7 @@ class TestExtractHookInfo:
mod = _import_log_watcher()
watcher, _ = _make_watcher(mod)
line = "[HOOKS] cadence skipped loader=branch action=skipped turn=37 period=5 offset=0 session=abc12345"
line = "[HOOKS] cadence skipped loader=branch turn=37 period=5 offset=0 session=abc12345"
result = watcher._extract_hook_info(line)
assert result is not None
assert result["name"] == "cadence"
@@ -1101,13 +1102,14 @@ class TestExtractHookInfo:
result = watcher._extract_hook_info("[FLOW] Creating plan FPLAN-0099")
assert result is None
def test_hook_line_without_action_returns_none(self):
"""A [HOOKS] line without action= should return None."""
def test_hook_info_line_returns_none(self):
"""A [HOOKS] info/error line (colon after the name) is not a fire/skip event → None."""
mod = _import_log_watcher()
watcher, _ = _make_watcher(mod)
result = watcher._extract_hook_info("[HOOKS] something happened no structured data")
assert result is None
# These are real cadence info lines; the colon stops the action capture.
assert watcher._extract_hook_info("[HOOKS] cadence: config load failed, using defaults") is None
assert watcher._extract_hook_info("[HOOKS] cadence: counter reset for post-compact re-injection") is None
class TestEmitHookEvent:
@@ -1120,7 +1122,15 @@ class TestEmitHookEvent:
mock_event_cls = MagicMock()
with patch.object(mod, "MonitoringEvent", mock_event_cls):
hook_info = {"name": "cadence", "action": "fired", "loader": "global", "turn": "35"}
hook_info = {
"name": "cadence",
"action": "fired",
"loader": "global",
"turn": "35",
"period": "5",
"offset": "0",
"session": "abc12345",
}
watcher._emit_hook_event("HOOKS", hook_info)
mock_event_cls.assert_called_once()
@@ -1130,7 +1140,9 @@ class TestEmitHookEvent:
assert kwargs["level"] == "success"
assert "cadence:fired" in kwargs["message"]
assert "loader=global" in kwargs["message"]
assert "turn=35" in kwargs["message"]
assert "t=35" in kwargs["message"]
assert "p=5" in kwargs["message"]
assert "s=abc12345" in kwargs["message"]
def test_skipped_event_queued_with_info_level(self):
"""Skipped hook events should pass level=info to MonitoringEvent."""
@@ -1158,10 +1170,36 @@ class TestEmitHookEvent:
):
watcher._process_log_line(
"HOOKS",
"[HOOKS] cadence fired loader=global action=fired turn=35 period=5 offset=0 session=abc",
"[HOOKS] cadence fired loader=global turn=35 period=5 offset=0 session=abc",
"/fake/file.log",
)
mock_hook.assert_called_once()
mock_cmd.assert_not_called()
mock_log.assert_not_called()
def test_process_real_pipe_delimited_hook_line(self):
"""Real log lines are pipe-delimited — hook detection must match through the prefix."""
mod = _import_log_watcher()
watcher, mock_queue = _make_watcher(mod)
real_line = (
"2026-06-09 19:56:04 | captured_cadence | INFO | "
"[HOOKS] cadence skipped loader=branch turn=18 period=5 offset=0 session=c98a722b"
)
with (
patch.object(watcher, "_emit_hook_event") as mock_hook,
patch.object(watcher, "_emit_command_separator") as mock_cmd,
patch.object(watcher, "_emit_log_event") as mock_log,
):
watcher._process_log_line("HOOKS", real_line, "/fake/hooks_cadence.log")
mock_hook.assert_called_once()
hook_info = mock_hook.call_args[0][1]
assert hook_info["name"] == "cadence"
assert hook_info["action"] == "skipped"
assert hook_info["loader"] == "branch"
assert hook_info["turn"] == "18"
mock_cmd.assert_not_called()
mock_log.assert_not_called()