diff --git a/src/aipass/prax/apps/handlers/monitoring/log_watcher.py b/src/aipass/prax/apps/handlers/monitoring/log_watcher.py index 1507116b..a67f4026 100644 --- a/src/aipass/prax/apps/handlers/monitoring/log_watcher.py +++ b/src/aipass/prax/apps/handlers/monitoring/log_watcher.py @@ -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)") diff --git a/src/aipass/prax/tests/test_log_watcher.py b/src/aipass/prax/tests/test_log_watcher.py index 48c1f3cf..0a58d3c8 100644 --- a/src/aipass/prax/tests/test_log_watcher.py +++ b/src/aipass/prax/tests/test_log_watcher.py @@ -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()