From 6ede871054684cc762ff1db30c7a22dbff9b5bc1 Mon Sep 17 00:00:00 2001 From: Emil Simeonov Date: Fri, 19 Jun 2026 01:54:05 +0200 Subject: [PATCH] GRM-15: fix: eliminate duplicate console output, restore GRM_LOG_LEVEL filtering MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Remove console StreamHandler from get_logger() — say() already handles console output via click.echo(); having both caused every message to appear twice - Move GRM_LOG_LEVEL filtering into ui.say() via _console_level() so console verbosity is still user-controllable while the log file always captures everything at DEBUG - Remove [GRM] prefix from say() calls — no longer needed without duplicate logger output, giving cleaner user-facing messages - Update test_logging_config.py: remove console handler tests and _level_from_env tests (now in test_ui.py), expect 1 handler only - Add test_ui.py coverage for _console_level and say() level filtering - Update README to document single-path console output via click.echo - 116 tests, 100% coverage, pyright clean, ruff clean --- README.md | 8 ++--- src/gitea_runner_manager/executor.py | 10 +++--- src/gitea_runner_manager/logging_config.py | 21 ++--------- src/gitea_runner_manager/report.py | 4 +-- src/gitea_runner_manager/ui.py | 20 ++++++++--- tests/unit/test_logging_config.py | 42 ++++------------------ tests/unit/test_ui.py | 30 +++++++++++++++- 7 files changed, 64 insertions(+), 71 deletions(-) diff --git a/README.md b/README.md index 6839c8c..2795708 100644 --- a/README.md +++ b/README.md @@ -172,16 +172,16 @@ sudo journalctl -u gitea-runner@ -f docker logs gitea-runner- -f ``` -The GRM application writes two parallel log streams: +The GRM application writes to two destinations: | Destination | Level | Content | |-------------|-------|---------| -| Console (stderr) | `GRM_LOG_LEVEL` (default: INFO) | User-facing messages and operation reports | +| Console (stdout) | `GRM_LOG_LEVEL` (default: INFO) | Colorised 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. +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 regardless of the console setting. -Console output is automatically colorised: operation headers in bright cyan, completed steps in green, failures in red, and status updates in yellow. +Console output is automatically colorised via ``click.echo``: operation headers in bright cyan, completed steps in green, failures in red, and status updates in yellow. ## Architecture diff --git a/src/gitea_runner_manager/executor.py b/src/gitea_runner_manager/executor.py index 5f2d00f..3c910f9 100644 --- a/src/gitea_runner_manager/executor.py +++ b/src/gitea_runner_manager/executor.py @@ -27,8 +27,8 @@ class AnsibleExecutor: log_file = self._prepare_log(cmd) desc = description or _("Running Ansible playbook") - say(f"[GRM] {desc}", color="cyan") - say(f"[GRM] {_('Full log: {log_file}', log_file=log_file)}") + say(desc, color="cyan") + say(_("Full log: {log_file}", log_file=log_file)) returncode = self._stream(cmd, log_file) @@ -38,14 +38,14 @@ class AnsibleExecutor: code=returncode, log_file=log_file, ) - say(f"[GRM] {msg}", level=logging.ERROR, err=True, color="red") + say(msg, level=logging.ERROR, err=True, color="red") raise AnsibleError(msg) status = self._extract_status(log_file) if status: - say(f"[GRM] {status}", color="yellow") + say(status, color="yellow") - say(f"[GRM] {_('Done. See full log: {log_file}', log_file=log_file)}", color="green") + say(_("Done. See full log: {log_file}", log_file=log_file), color="green") 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 index 92096e9..1600881 100644 --- a/src/gitea_runner_manager/logging_config.py +++ b/src/gitea_runner_manager/logging_config.py @@ -3,15 +3,14 @@ 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``. + All messages are written to ``~/.local/state/grm/logs/grm.log``. + Console output is handled by ``ui.say()`` via ``click.echo``. """ logger = logging.getLogger(name) if logger.handlers: @@ -19,12 +18,6 @@ def get_logger(name: str = "grm") -> logging.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) @@ -34,13 +27,3 @@ def get_logger(name: str = "grm") -> logging.Logger: 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 48e40d1..571460d 100644 --- a/src/gitea_runner_manager/report.py +++ b/src/gitea_runner_manager/report.py @@ -63,7 +63,7 @@ def _print_report(steps: list[Step]) -> None: "pending": "○", "in_progress": "◌", } - say(f"[GRM] {_('=== Operation Report ===')}", color="bright_cyan") + say(_("=== Operation Report ==="), color="bright_cyan") for step in steps: icon = icons.get(step.status, "?") status_label = _(step.status) @@ -73,4 +73,4 @@ def _print_report(steps: list[Step]) -> None: "in_progress": "yellow", "pending": "white", }.get(step.status) - say(f"[GRM] {icon} {step.name} ({status_label})", color=color) + say(f" {icon} {step.name} ({status_label})", color=color) diff --git a/src/gitea_runner_manager/ui.py b/src/gitea_runner_manager/ui.py index 3f76f92..ae7a416 100644 --- a/src/gitea_runner_manager/ui.py +++ b/src/gitea_runner_manager/ui.py @@ -7,21 +7,33 @@ The persistent log file always receives plain text (no ANSI codes). from __future__ import annotations import logging +import os import click +def _console_level() -> int: + """Return the minimum level for console output from ``GRM_LOG_LEVEL``.""" + value = os.getenv("GRM_LOG_LEVEL", "INFO") + try: + return getattr(logging, value.upper()) + except AttributeError: + return logging.INFO + + def say(msg: str, level: int = logging.INFO, err: bool = False, color: str | None = None) -> None: """Output a message to the user and also log it for auditing. Console output goes via ``click.echo`` (handles encoding, CliRunner, - Windows colorama). The same message is also sent to the ``grm`` logger - so it appears in the persistent log file. + Windows colorama) only when *level* is at least ``GRM_LOG_LEVEL``. + The same message is always sent to the ``grm`` logger so it appears + in the persistent log file regardless of console verbosity. The optional *color* parameter is passed to ``click.style`` so the console line is tinted (e.g. ``color="green"``). The log file always stores the raw plain text. """ - styled = click.style(msg, fg=color) if color else msg - click.echo(styled, err=err) + if level >= _console_level(): + styled = click.style(msg, fg=color) if color else msg + click.echo(styled, err=err) logging.getLogger("grm").log(level, msg) diff --git a/tests/unit/test_logging_config.py b/tests/unit/test_logging_config.py index 478fee6..057ab0d 100644 --- a/tests/unit/test_logging_config.py +++ b/tests/unit/test_logging_config.py @@ -9,7 +9,7 @@ from unittest.mock import patch import pytest -from gitea_runner_manager.logging_config import _level_from_env, get_logger +from gitea_runner_manager.logging_config import get_logger @pytest.fixture(autouse=True) @@ -23,25 +23,6 @@ def _cleanup_loggers() -> Generator[None, None, None]: 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): @@ -49,7 +30,7 @@ class TestGetLogger: assert isinstance(logger, logging.Logger) assert logger.name == "test_returns_logger" - assert len(logger.handlers) == 2 # console + file + assert len(logger.handlers) == 1 # file only def test_caches_same_instance(self, tmp_path: Path) -> None: with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path): @@ -69,20 +50,9 @@ class TestGetLogger: 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") + def test_only_file_handler(self, tmp_path: Path) -> None: 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] + logger = get_logger("test_only_file") - 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 + assert len(logger.handlers) == 1 + assert isinstance(logger.handlers[0], logging.FileHandler) diff --git a/tests/unit/test_ui.py b/tests/unit/test_ui.py index cf37ec9..9c8bb49 100644 --- a/tests/unit/test_ui.py +++ b/tests/unit/test_ui.py @@ -5,7 +5,23 @@ from __future__ import annotations import logging from unittest.mock import patch -from gitea_runner_manager.ui import say +import pytest + +from gitea_runner_manager.ui import _console_level, say + + +class TestConsoleLevel: + def test_default_is_info(self) -> None: + with patch.dict("os.environ", {}, clear=True): + assert _console_level() == logging.INFO + + def test_env_override(self, monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setenv("GRM_LOG_LEVEL", "DEBUG") + assert _console_level() == logging.DEBUG + + def test_invalid_fallback(self, monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setenv("GRM_LOG_LEVEL", "VERBOSE") + assert _console_level() == logging.INFO class TestSay: @@ -35,3 +51,15 @@ class TestSay: mock_echo.assert_called_once_with("error msg", err=True) mock_logger.log.assert_called_once_with(logging.ERROR, "error msg") + + def test_suppresses_console_below_level(self, monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setenv("GRM_LOG_LEVEL", "WARNING") + with ( + patch("gitea_runner_manager.ui.click.echo") as mock_echo, + patch("gitea_runner_manager.ui.logging.getLogger") as mock_get_logger, + ): + mock_logger = mock_get_logger.return_value + say("debug msg", level=logging.DEBUG) + + mock_echo.assert_not_called() + mock_logger.log.assert_called_once_with(logging.DEBUG, "debug msg")