diff --git a/src/specify_cli/events/__init__.py b/src/specify_cli/events/__init__.py index 613dba5702..2fdfffede7 100644 --- a/src/specify_cli/events/__init__.py +++ b/src/specify_cli/events/__init__.py @@ -95,6 +95,7 @@ directly, without requiring a persistent `specify` executable on PATH. """ import json +import logging import os import re import shlex @@ -103,6 +104,8 @@ import sys from pathlib import Path, PurePosixPath, PureWindowsPath +logger = logging.getLogger("specify.events.dispatcher") + def _script_under_base(base, token, project_root): """Return token resolved under base, or None if it leaves the project.""" @@ -316,10 +319,10 @@ def _run_inline(command_name, payload, project_root, timeout, envelope="plain", return result.returncode return 0 except subprocess.TimeoutExpired: - print(f"Event {command_name} timed out", file=sys.stderr) + logger.error("Event %s timed out", command_name) return 2 except Exception as e: - print(f"Event {command_name} error: {e}", file=sys.stderr) + logger.error("Event %s error: %s", command_name, e) return 2 @@ -1371,9 +1374,8 @@ def install_integration_events( if ev in canonical_to_native: filtered[ev] = handlers else: - print( - f"\u26a0\ufe0f {integration.key} does not support '{ev}' events; skipping", - file=sys.stderr, + logger.warning( + "%s does not support '%s' events; skipping", integration.key, ev, ) # #3: an empty resolved map (--events false, or override disabling events) diff --git a/tests/integrations/test_integration_vibe.py b/tests/integrations/test_integration_vibe.py index c2189a4b84..6be90136f6 100644 --- a/tests/integrations/test_integration_vibe.py +++ b/tests/integrations/test_integration_vibe.py @@ -217,14 +217,14 @@ def test_wildcard_matcher_omitted(self, tmp_path): (hook,) = self._parse(tmp_path)["hooks"] assert "match" not in hook - def test_unsupported_events_are_skipped(self, tmp_path, capsys): + def test_unsupported_events_are_skipped(self, tmp_path, caplog): self._install(tmp_path, { "session_start": [{"command": "speckit.agent-context.update"}], "pre_tool_use": [{"command": "speckit.tdd.validate"}], }) hooks = self._parse(tmp_path)["hooks"] assert [h["type"] for h in hooks] == ["pre_tool"] - assert "does not support 'session_start'" in capsys.readouterr().err + assert "does not support 'session_start'" in caplog.text def test_multiple_handlers_get_unique_names(self, tmp_path): """Vibe drops duplicate hook names, so shared command stems must not collide.""" diff --git a/tests/specify_cli/events/test_events.py b/tests/specify_cli/events/test_events.py index c92e9e30ad..9379295b5d 100644 --- a/tests/specify_cli/events/test_events.py +++ b/tests/specify_cli/events/test_events.py @@ -3,9 +3,12 @@ from __future__ import annotations import json +import logging import os import platform import shlex +import subprocess +import sys from pathlib import Path, PurePath from unittest.mock import MagicMock, patch @@ -3194,3 +3197,65 @@ def test_refresh_failure_preserves_existing_config(self, tmp_path): # The pre-existing config was NOT destroyed before the failure # (install handles cleanup atomically; refresh no longer pre-strips). assert config_path.read_text() == original + + +class TestGeneratedDispatcherLogger: + """The generated dispatcher is standalone: it must define its own logger. + + Regression for the logger conversion that reached into + ``_EVENTS_DISPATCHER_TEMPLATE`` without adding a logger to the generated + script, turning every timeout or launch failure into a ``NameError``. + """ + + def _exec_dispatcher(self, tmp_path): + from specify_cli.events import _EVENTS_DISPATCHER_TEMPLATE + + namespace = {"__name__": "generated_events_dispatcher"} + exec(compile(_EVENTS_DISPATCHER_TEMPLATE, "events.py", "exec"), namespace) + namespace["_find_command_template"] = lambda name, root: ( + tmp_path / "noop.md", + None, + ) + namespace["_resolve_argv"] = lambda path, root, ext: [ + sys.executable, + "-c", + "pass", + ] + return namespace + + def test_dispatcher_defines_logger(self): + from specify_cli.events import _EVENTS_DISPATCHER_TEMPLATE + + namespace = {"__name__": "generated_events_dispatcher"} + exec(compile(_EVENTS_DISPATCHER_TEMPLATE, "events.py", "exec"), namespace) + + assert namespace["logger"].name == "specify.events.dispatcher" + + def test_dispatcher_logs_timeout_through_logger( + self, tmp_path, monkeypatch, caplog + ): + namespace = self._exec_dispatcher(tmp_path) + + def _timeout(*args, **kwargs): + raise subprocess.TimeoutExpired(cmd="demo", timeout=1) + + monkeypatch.setattr(namespace["subprocess"], "run", _timeout) + caplog.set_level(logging.ERROR, logger="specify.events.dispatcher") + + assert namespace["_run_inline"]("demo", "{}", str(tmp_path), 5) == 2 + assert "Event demo timed out" in caplog.text + + def test_dispatcher_logs_launch_error_through_logger( + self, tmp_path, monkeypatch, caplog + ): + namespace = self._exec_dispatcher(tmp_path) + + def _fails(*args, **kwargs): + raise OSError("executable not found") + + monkeypatch.setattr(namespace["subprocess"], "run", _fails) + caplog.set_level(logging.ERROR, logger="specify.events.dispatcher") + + assert namespace["_run_inline"]("demo", "{}", str(tmp_path), 5) == 2 + assert "Event demo error: executable not found" in caplog.text +