diff --git a/README.md b/README.md index 8af8774..d6d7a93 100644 --- a/README.md +++ b/README.md @@ -152,6 +152,18 @@ Optional: If `GITEA_ADMIN_TOKEN` is set, the installer will also query the Gitea ### View Logs +**GRM application logs** (Python CLI output): + +```bash +# Application log file (all messages including DEBUG) +cat ~/.local/state/grm/logs/grm.log + +# Enable debug logging in the current session +GRM_LOG_LEVEL=DEBUG grm install 192.168.1.10 --user ubuntu --name prod-runner +``` + +**Runner logs** (on the remote host): + ```bash # Binary mode logs (via systemd template unit) sudo journalctl -u gitea-runner@ -f @@ -160,6 +172,15 @@ sudo journalctl -u gitea-runner@ -f docker logs gitea-runner- -f ``` +The GRM application writes two parallel log streams: + +| Destination | Level | Content | +|-------------|-------|---------| +| Console (stderr) | `GRM_LOG_LEVEL` (default: INFO) | User-facing messages and operation reports | +| `~/.local/state/grm/logs/grm.log` | DEBUG | All messages with timestamps and severity | + +Set `GRM_LOG_LEVEL` to one of `DEBUG`, `INFO`, `WARNING`, `ERROR`, or `CRITICAL` to control console verbosity. The log file always captures everything at DEBUG level. + ## Architecture GRM consists of two layers: @@ -212,6 +233,7 @@ All tunable values are exposed as Ansible variables in `ansible/roles/gitea-runn | `gitea_runner_container_label` | `gitea-runner=true` | Container label | | `docker_gpg_key_path` | `/etc/apt/keyrings/docker.asc` | Docker GPG key path | | `GRM_LANG` | `en` | CLI language: `en`, `bg`, `de`, `ru`, `zh` | +| `GRM_LOG_LEVEL` | `INFO` | Console verbosity: `DEBUG`, `INFO`, `WARNING`, `ERROR`, `CRITICAL` | Override any variable by passing it to the CLI with `--extra-vars` or by setting it in your Ansible inventory. diff --git a/src/gitea_runner_manager/executor.py b/src/gitea_runner_manager/executor.py index c2791f7..d4b920f 100644 --- a/src/gitea_runner_manager/executor.py +++ b/src/gitea_runner_manager/executor.py @@ -10,6 +10,7 @@ from pathlib import Path from .exceptions import AnsibleError from .i18n import _ +from .logging_config import get_logger class AnsibleExecutor: @@ -17,31 +18,32 @@ class AnsibleExecutor: def __init__(self, log_dir: Path | None = None) -> None: self._log_dir = log_dir or Path.home() / ".local" / "state" / "grm" / "logs" + self._logger = get_logger() def run(self, cmd: list[str], description: str = "") -> None: """Run an Ansible command, redirecting output to a log file.""" log_file = self._prepare_log(cmd) desc = description or _("Running Ansible playbook") - print(f"[GRM] {desc}") - print(f"[GRM] {_('Full log: {log_file}', log_file=log_file)}") + self._logger.info(desc) + self._logger.info(_("Full log: {log_file}", log_file=log_file)) returncode = self._stream(cmd, log_file) if returncode != 0: - raise AnsibleError( - _( - "Ansible failed with exit code {code}. See full log: {log_file}", - code=returncode, - log_file=log_file, - ) + msg = _( + "Ansible failed with exit code {code}. See full log: {log_file}", + code=returncode, + log_file=log_file, ) + self._logger.error(msg) + raise AnsibleError(msg) status = self._extract_status(log_file) if status: - print(f"[GRM] {status}") + self._logger.info(status) - print(f"[GRM] {_('Done. See full log: {log_file}', log_file=log_file)}") + self._logger.info(_("Done. See full log: {log_file}", log_file=log_file)) def _prepare_log(self, cmd: list[str]) -> Path: """Create a log file with header.""" diff --git a/src/gitea_runner_manager/logging_config.py b/src/gitea_runner_manager/logging_config.py new file mode 100644 index 0000000..92096e9 --- /dev/null +++ b/src/gitea_runner_manager/logging_config.py @@ -0,0 +1,46 @@ +"""GRM logging configuration using the standard library.""" + +from __future__ import annotations + +import logging +import os +from pathlib import Path + + +def get_logger(name: str = "grm") -> logging.Logger: + """Return a configured logger for GRM. + + Console output respects ``GRM_LOG_LEVEL`` (default: INFO). + All messages are also written to ``~/.local/state/grm/logs/grm.log``. + """ + logger = logging.getLogger(name) + if logger.handlers: + return logger + + logger.setLevel(logging.DEBUG) + + # Console handler — user-controlled level + console = logging.StreamHandler() + console.setLevel(_level_from_env(os.getenv("GRM_LOG_LEVEL", "INFO"))) + console.setFormatter(logging.Formatter("[GRM] %(message)s")) + logger.addHandler(console) + + # File handler — captures everything including DEBUG + log_dir = Path.home() / ".local" / "state" / "grm" / "logs" + log_dir.mkdir(parents=True, exist_ok=True) + file_handler = logging.FileHandler(log_dir / "grm.log") + file_handler.setLevel(logging.DEBUG) + file_handler.setFormatter(logging.Formatter("%(asctime)s %(levelname)s %(name)s: %(message)s")) + logger.addHandler(file_handler) + + return logger + + +def _level_from_env(value: str | None) -> int: + """Map a level name to a logging level constant.""" + if not value: + return logging.INFO + try: + return getattr(logging, value.upper()) + except AttributeError: + return logging.INFO diff --git a/src/gitea_runner_manager/report.py b/src/gitea_runner_manager/report.py index 493cd1d..b3ffd45 100644 --- a/src/gitea_runner_manager/report.py +++ b/src/gitea_runner_manager/report.py @@ -6,6 +6,7 @@ from collections.abc import Generator from contextlib import contextmanager from .i18n import _ +from .logging_config import get_logger class Step: @@ -56,14 +57,15 @@ def track_steps() -> Generator[StepTracker, None, None]: def _print_report(steps: list[Step]) -> None: """Print a translated operation report to stdout.""" + logger = get_logger() icons = { "completed": "✓", "failed": "✗", "pending": "○", "in_progress": "◌", } - print(f"[GRM] {_('=== Operation Report ===')}") + logger.info(_("=== Operation Report ===")) for step in steps: icon = icons.get(step.status, "?") status_label = _(step.status) - print(f"[GRM] {icon} {step.name} ({status_label})") + logger.info(f" {icon} {step.name} ({status_label})") diff --git a/tests/unit/test_executor.py b/tests/unit/test_executor.py index 2d8585b..0ecbed7 100644 --- a/tests/unit/test_executor.py +++ b/tests/unit/test_executor.py @@ -20,31 +20,40 @@ def _mock_popen_process(returncode: int = 0) -> MagicMock: class TestAnsibleExecutorRun: - def test_run_success(self, tmp_path: Path, capsys: pytest.CaptureFixture[str]) -> None: - executor = AnsibleExecutor(log_dir=tmp_path) - with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open()): - mock_popen.return_value = _mock_popen_process(returncode=0) - executor.run(["echo", "hello"], description="Test run") + def test_run_success(self, tmp_path: Path) -> None: + mock_logger = MagicMock() + with patch("gitea_runner_manager.executor.get_logger", return_value=mock_logger): + executor = AnsibleExecutor(log_dir=tmp_path) + with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open()): + mock_popen.return_value = _mock_popen_process(returncode=0) + executor.run(["echo", "hello"], description="Test run") - captured = capsys.readouterr() - assert "[GRM] Test run" in captured.out - assert "[GRM] Done" in captured.out + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("Test run" in msg for msg in messages) + assert any("Done" in msg for msg in messages) def test_run_failure(self, tmp_path: Path) -> None: - executor = AnsibleExecutor(log_dir=tmp_path) - with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open()): - mock_popen.return_value = _mock_popen_process(returncode=1) - with pytest.raises(AnsibleError, match="exit code 1"): - executor.run(["false"], description="Test run") + mock_logger = MagicMock() + with patch("gitea_runner_manager.executor.get_logger", return_value=mock_logger): + executor = AnsibleExecutor(log_dir=tmp_path) + with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open()): + mock_popen.return_value = _mock_popen_process(returncode=1) + with pytest.raises(AnsibleError, match="exit code 1"): + executor.run(["false"], description="Test run") - def test_run_default_description(self, tmp_path: Path, capsys: pytest.CaptureFixture[str]) -> None: - executor = AnsibleExecutor(log_dir=tmp_path) - with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open()): - mock_popen.return_value = _mock_popen_process(returncode=0) - executor.run(["echo", "hello"]) + assert mock_logger.error.called + assert "exit code 1" in mock_logger.error.call_args[0][0] - captured = capsys.readouterr() - assert "[GRM] Running Ansible playbook" in captured.out + def test_run_default_description(self, tmp_path: Path) -> None: + mock_logger = MagicMock() + with patch("gitea_runner_manager.executor.get_logger", return_value=mock_logger): + executor = AnsibleExecutor(log_dir=tmp_path) + with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open()): + mock_popen.return_value = _mock_popen_process(returncode=0) + executor.run(["echo", "hello"]) + + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("Running Ansible playbook" in msg for msg in messages) def test_run_with_stdout_lines(self, tmp_path: Path) -> None: executor = AnsibleExecutor(log_dir=tmp_path) @@ -60,20 +69,22 @@ class TestAnsibleExecutorRun: handle.write.assert_any_call("line1\n") handle.write.assert_any_call("line2\n") - def test_run_extracts_status(self, tmp_path: Path, capsys: pytest.CaptureFixture[str]) -> None: - executor = AnsibleExecutor(log_dir=tmp_path) + def test_run_extracts_status(self, tmp_path: Path) -> None: + mock_logger = MagicMock() log_content = ( "TASK [gitea-runner : Report runner status]\n" "ok: [127.0.0.1] => {\n" ' "msg": "Runner \'127.0.0.1\' is installed and running."\n' "}\n" ) - with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open(read_data=log_content)): - mock_popen.return_value = _mock_popen_process(returncode=0) - executor.run(["echo", "hello"], description="Test run") + with patch("gitea_runner_manager.executor.get_logger", return_value=mock_logger): + executor = AnsibleExecutor(log_dir=tmp_path) + with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open(read_data=log_content)): + mock_popen.return_value = _mock_popen_process(returncode=0) + executor.run(["echo", "hello"], description="Test run") - captured = capsys.readouterr() - assert "Runner '127.0.0.1' is installed and running" in captured.out + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("Runner '127.0.0.1' is installed and running" in msg for msg in messages) class TestAnsibleExecutorExtractStatus: @@ -129,32 +140,34 @@ class TestAnsibleExecutorPrepareLog: class TestAnsibleExecutorTranslation: - def test_run_translated(self, tmp_path: Path, capsys: pytest.CaptureFixture[str]) -> None: - executor = AnsibleExecutor(log_dir=tmp_path) + def test_run_translated(self, tmp_path: Path) -> None: + mock_logger = MagicMock() with ( patch.dict(os.environ, {"GRM_LANG": "de"}), - patch("subprocess.Popen") as mock_popen, - patch("builtins.open", mock_open()), + patch("gitea_runner_manager.executor.get_logger", return_value=mock_logger), ): - mock_popen.return_value = _mock_popen_process(returncode=0) - executor.run(["echo", "hello"]) # use default description to test translation + executor = AnsibleExecutor(log_dir=tmp_path) + with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open()): + mock_popen.return_value = _mock_popen_process(returncode=0) + executor.run(["echo", "hello"]) # use default description to test translation - captured = capsys.readouterr() - assert "Ansible-Playbook wird ausgeführt" in captured.out - assert "Fertig" in captured.out + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("Ansible-Playbook wird ausgeführt" in msg for msg in messages) + assert any("Fertig" in msg for msg in messages) - def test_unsupported_lang_fallback(self, tmp_path: Path, capsys: pytest.CaptureFixture[str]) -> None: - executor = AnsibleExecutor(log_dir=tmp_path) + def test_unsupported_lang_fallback(self, tmp_path: Path) -> None: + mock_logger = MagicMock() with ( patch.dict(os.environ, {"GRM_LANG": "xx"}), - patch("subprocess.Popen") as mock_popen, - patch("builtins.open", mock_open()), + patch("gitea_runner_manager.executor.get_logger", return_value=mock_logger), ): - mock_popen.return_value = _mock_popen_process(returncode=0) - executor.run(["echo", "hello"]) + executor = AnsibleExecutor(log_dir=tmp_path) + with patch("subprocess.Popen") as mock_popen, patch("builtins.open", mock_open()): + mock_popen.return_value = _mock_popen_process(returncode=0) + executor.run(["echo", "hello"]) - captured = capsys.readouterr() - assert "[GRM] Running Ansible playbook" in captured.out # English fallback + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("Running Ansible playbook" in msg for msg in messages) # English fallback class TestAnsibleExecutorAdHoc: diff --git a/tests/unit/test_logging_config.py b/tests/unit/test_logging_config.py new file mode 100644 index 0000000..478fee6 --- /dev/null +++ b/tests/unit/test_logging_config.py @@ -0,0 +1,88 @@ +"""Unit tests for logging configuration.""" + +from __future__ import annotations + +import logging +from collections.abc import Generator +from pathlib import Path +from unittest.mock import patch + +import pytest + +from gitea_runner_manager.logging_config import _level_from_env, get_logger + + +@pytest.fixture(autouse=True) +def _cleanup_loggers() -> Generator[None, None, None]: + """Remove test loggers after each test to prevent state leakage.""" + yield + for name in list(logging.Logger.manager.loggerDict.keys()): + if name.startswith("test_"): + logger = logging.getLogger(name) + logger.handlers.clear() + del logging.Logger.manager.loggerDict[name] + + +class TestLevelFromEnv: + def test_none_defaults_to_info(self) -> None: + assert _level_from_env(None) == logging.INFO + + def test_empty_string_defaults_to_info(self) -> None: + assert _level_from_env("") == logging.INFO + + def test_valid_levels(self) -> None: + assert _level_from_env("debug") == logging.DEBUG + assert _level_from_env("DEBUG") == logging.DEBUG + assert _level_from_env("warning") == logging.WARNING + assert _level_from_env("error") == logging.ERROR + assert _level_from_env("critical") == logging.CRITICAL + + def test_invalid_fallback_to_info(self) -> None: + assert _level_from_env("foo") == logging.INFO + assert _level_from_env("VERBOSE") == logging.INFO + + +class TestGetLogger: + def test_returns_logger(self, tmp_path: Path) -> None: + with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path): + logger = get_logger("test_returns_logger") + + assert isinstance(logger, logging.Logger) + assert logger.name == "test_returns_logger" + assert len(logger.handlers) == 2 # console + file + + def test_caches_same_instance(self, tmp_path: Path) -> None: + with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path): + logger1 = get_logger("test_caches_same") + logger2 = get_logger("test_caches_same") + + assert logger1 is logger2 + + def test_file_handler_writes(self, tmp_path: Path) -> None: + with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path): + logger = get_logger("test_file_writes") + logger.info("hello from test") + + log_file = tmp_path / ".local" / "state" / "grm" / "logs" / "grm.log" + assert log_file.exists() + content = log_file.read_text() + assert "hello from test" in content + assert "INFO" in content + + def test_respects_grm_log_level(self, monkeypatch: pytest.MonkeyPatch, tmp_path: Path) -> None: + monkeypatch.setenv("GRM_LOG_LEVEL", "DEBUG") + with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path): + logger = get_logger("test_env_level") + console = [h for h in logger.handlers if type(h) is logging.StreamHandler] + + assert len(console) == 1 + assert console[0].level == logging.DEBUG + + def test_grm_log_level_warning(self, monkeypatch: pytest.MonkeyPatch, tmp_path: Path) -> None: + monkeypatch.setenv("GRM_LOG_LEVEL", "WARNING") + with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path): + logger = get_logger("test_env_warning") + console = [h for h in logger.handlers if type(h) is logging.StreamHandler] + + assert len(console) == 1 + assert console[0].level == logging.WARNING diff --git a/tests/unit/test_report.py b/tests/unit/test_report.py index 6520aa2..6840589 100644 --- a/tests/unit/test_report.py +++ b/tests/unit/test_report.py @@ -2,6 +2,8 @@ from __future__ import annotations +from unittest.mock import MagicMock, patch + import pytest from gitea_runner_manager.exceptions import AnsibleError @@ -43,60 +45,69 @@ class TestStepTracker: class TestTrackSteps: - def test_success(self, capsys: pytest.CaptureFixture[str]) -> None: - with track_steps() as tracker: - tracker.begin("step1") - tracker.done() - tracker.begin("step2") - tracker.done() - - captured = capsys.readouterr() - assert "Operation Report" in captured.out - assert "step1" in captured.out - assert "step2" in captured.out - assert "✓" in captured.out - assert "completed" in captured.out - - def test_failure_marks_step(self, capsys: pytest.CaptureFixture[str]) -> None: - with pytest.raises(AnsibleError, match="fail"): + def test_success(self) -> None: + mock_logger = MagicMock() + with patch("gitea_runner_manager.report.get_logger", return_value=mock_logger): with track_steps() as tracker: tracker.begin("step1") tracker.done() tracker.begin("step2") - raise AnsibleError("fail") + tracker.done() - captured = capsys.readouterr() - assert "Operation Report" in captured.out - assert "step1" in captured.out - assert "step2" in captured.out - assert "✓" in captured.out - assert "✗" in captured.out - assert "completed" in captured.out - assert "failed" in captured.out + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("Operation Report" in msg for msg in messages) + assert any("step1" in msg for msg in messages) + assert any("step2" in msg for msg in messages) + assert any("✓" in msg for msg in messages) + assert any("completed" in msg for msg in messages) - def test_pending_shown_on_failure(self, capsys: pytest.CaptureFixture[str]) -> None: + def test_failure_marks_step(self) -> None: + mock_logger = MagicMock() with pytest.raises(AnsibleError, match="fail"): + with patch("gitea_runner_manager.report.get_logger", return_value=mock_logger): + with track_steps() as tracker: + tracker.begin("step1") + tracker.done() + tracker.begin("step2") + raise AnsibleError("fail") + + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("step1" in msg for msg in messages) + assert any("step2" in msg for msg in messages) + assert any("✓" in msg for msg in messages) + assert any("✗" in msg for msg in messages) + assert any("completed" in msg for msg in messages) + assert any("failed" in msg for msg in messages) + + def test_pending_shown_on_failure(self) -> None: + mock_logger = MagicMock() + with pytest.raises(AnsibleError, match="fail"): + with patch("gitea_runner_manager.report.get_logger", return_value=mock_logger): + with track_steps() as tracker: + tracker.begin("step1") + raise AnsibleError("fail") + + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("✗" in msg for msg in messages) + assert any("failed" in msg for msg in messages) + + def test_empty_report(self) -> None: + mock_logger = MagicMock() + with patch("gitea_runner_manager.report.get_logger", return_value=mock_logger): + with track_steps(): + pass + + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("Operation Report" in msg for msg in messages) + + def test_translated_report(self, monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setenv("GRM_LANG", "bg") + mock_logger = MagicMock() + with patch("gitea_runner_manager.report.get_logger", return_value=mock_logger): with track_steps() as tracker: tracker.begin("step1") - raise AnsibleError("fail") + tracker.done() - captured = capsys.readouterr() - assert "✗" in captured.out - assert "failed" in captured.out - - def test_empty_report(self, capsys: pytest.CaptureFixture[str]) -> None: - with track_steps(): - pass - - captured = capsys.readouterr() - assert "Operation Report" in captured.out - - def test_translated_report(self, monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str]) -> None: - monkeypatch.setenv("GRM_LANG", "bg") - with track_steps() as tracker: - tracker.begin("step1") - tracker.done() - - captured = capsys.readouterr() - assert "Отчет за операцията" in captured.out - assert "завършено" in captured.out + messages = [call.args[0] for call in mock_logger.info.call_args_list] + assert any("Отчет за операцията" in msg for msg in messages) + assert any("завършено" in msg for msg in messages)