GRM-15: fix: eliminate duplicate console output, restore GRM_LOG_LEVEL filtering
- 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
This commit is contained in:
@@ -172,16 +172,16 @@ sudo journalctl -u gitea-runner@<name> -f
|
|||||||
docker logs gitea-runner-<name> -f
|
docker logs gitea-runner-<name> -f
|
||||||
```
|
```
|
||||||
|
|
||||||
The GRM application writes two parallel log streams:
|
The GRM application writes to two destinations:
|
||||||
|
|
||||||
| Destination | Level | Content |
|
| 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 |
|
| `~/.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
|
## Architecture
|
||||||
|
|
||||||
|
|||||||
@@ -27,8 +27,8 @@ class AnsibleExecutor:
|
|||||||
log_file = self._prepare_log(cmd)
|
log_file = self._prepare_log(cmd)
|
||||||
desc = description or _("Running Ansible playbook")
|
desc = description or _("Running Ansible playbook")
|
||||||
|
|
||||||
say(f"[GRM] {desc}", color="cyan")
|
say(desc, color="cyan")
|
||||||
say(f"[GRM] {_('Full log: {log_file}', log_file=log_file)}")
|
say(_("Full log: {log_file}", log_file=log_file))
|
||||||
|
|
||||||
returncode = self._stream(cmd, log_file)
|
returncode = self._stream(cmd, log_file)
|
||||||
|
|
||||||
@@ -38,14 +38,14 @@ class AnsibleExecutor:
|
|||||||
code=returncode,
|
code=returncode,
|
||||||
log_file=log_file,
|
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)
|
raise AnsibleError(msg)
|
||||||
|
|
||||||
status = self._extract_status(log_file)
|
status = self._extract_status(log_file)
|
||||||
if status:
|
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:
|
def _prepare_log(self, cmd: list[str]) -> Path:
|
||||||
"""Create a log file with header."""
|
"""Create a log file with header."""
|
||||||
|
|||||||
@@ -3,15 +3,14 @@
|
|||||||
from __future__ import annotations
|
from __future__ import annotations
|
||||||
|
|
||||||
import logging
|
import logging
|
||||||
import os
|
|
||||||
from pathlib import Path
|
from pathlib import Path
|
||||||
|
|
||||||
|
|
||||||
def get_logger(name: str = "grm") -> logging.Logger:
|
def get_logger(name: str = "grm") -> logging.Logger:
|
||||||
"""Return a configured logger for GRM.
|
"""Return a configured logger for GRM.
|
||||||
|
|
||||||
Console output respects ``GRM_LOG_LEVEL`` (default: INFO).
|
All messages are written to ``~/.local/state/grm/logs/grm.log``.
|
||||||
All messages are also written to ``~/.local/state/grm/logs/grm.log``.
|
Console output is handled by ``ui.say()`` via ``click.echo``.
|
||||||
"""
|
"""
|
||||||
logger = logging.getLogger(name)
|
logger = logging.getLogger(name)
|
||||||
if logger.handlers:
|
if logger.handlers:
|
||||||
@@ -19,12 +18,6 @@ def get_logger(name: str = "grm") -> logging.Logger:
|
|||||||
|
|
||||||
logger.setLevel(logging.DEBUG)
|
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
|
# File handler — captures everything including DEBUG
|
||||||
log_dir = Path.home() / ".local" / "state" / "grm" / "logs"
|
log_dir = Path.home() / ".local" / "state" / "grm" / "logs"
|
||||||
log_dir.mkdir(parents=True, exist_ok=True)
|
log_dir.mkdir(parents=True, exist_ok=True)
|
||||||
@@ -34,13 +27,3 @@ def get_logger(name: str = "grm") -> logging.Logger:
|
|||||||
logger.addHandler(file_handler)
|
logger.addHandler(file_handler)
|
||||||
|
|
||||||
return logger
|
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
|
|
||||||
|
|||||||
@@ -63,7 +63,7 @@ def _print_report(steps: list[Step]) -> None:
|
|||||||
"pending": "○",
|
"pending": "○",
|
||||||
"in_progress": "◌",
|
"in_progress": "◌",
|
||||||
}
|
}
|
||||||
say(f"[GRM] {_('=== Operation Report ===')}", color="bright_cyan")
|
say(_("=== Operation Report ==="), color="bright_cyan")
|
||||||
for step in steps:
|
for step in steps:
|
||||||
icon = icons.get(step.status, "?")
|
icon = icons.get(step.status, "?")
|
||||||
status_label = _(step.status)
|
status_label = _(step.status)
|
||||||
@@ -73,4 +73,4 @@ def _print_report(steps: list[Step]) -> None:
|
|||||||
"in_progress": "yellow",
|
"in_progress": "yellow",
|
||||||
"pending": "white",
|
"pending": "white",
|
||||||
}.get(step.status)
|
}.get(step.status)
|
||||||
say(f"[GRM] {icon} {step.name} ({status_label})", color=color)
|
say(f" {icon} {step.name} ({status_label})", color=color)
|
||||||
|
|||||||
@@ -7,21 +7,33 @@ The persistent log file always receives plain text (no ANSI codes).
|
|||||||
from __future__ import annotations
|
from __future__ import annotations
|
||||||
|
|
||||||
import logging
|
import logging
|
||||||
|
import os
|
||||||
|
|
||||||
import click
|
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:
|
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.
|
"""Output a message to the user and also log it for auditing.
|
||||||
|
|
||||||
Console output goes via ``click.echo`` (handles encoding, CliRunner,
|
Console output goes via ``click.echo`` (handles encoding, CliRunner,
|
||||||
Windows colorama). The same message is also sent to the ``grm`` logger
|
Windows colorama) only when *level* is at least ``GRM_LOG_LEVEL``.
|
||||||
so it appears in the persistent log file.
|
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
|
The optional *color* parameter is passed to ``click.style`` so the
|
||||||
console line is tinted (e.g. ``color="green"``). The log file always
|
console line is tinted (e.g. ``color="green"``). The log file always
|
||||||
stores the raw plain text.
|
stores the raw plain text.
|
||||||
"""
|
"""
|
||||||
styled = click.style(msg, fg=color) if color else msg
|
if level >= _console_level():
|
||||||
click.echo(styled, err=err)
|
styled = click.style(msg, fg=color) if color else msg
|
||||||
|
click.echo(styled, err=err)
|
||||||
logging.getLogger("grm").log(level, msg)
|
logging.getLogger("grm").log(level, msg)
|
||||||
|
|||||||
@@ -9,7 +9,7 @@ from unittest.mock import patch
|
|||||||
|
|
||||||
import pytest
|
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)
|
@pytest.fixture(autouse=True)
|
||||||
@@ -23,25 +23,6 @@ def _cleanup_loggers() -> Generator[None, None, None]:
|
|||||||
del logging.Logger.manager.loggerDict[name]
|
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:
|
class TestGetLogger:
|
||||||
def test_returns_logger(self, tmp_path: Path) -> None:
|
def test_returns_logger(self, tmp_path: Path) -> None:
|
||||||
with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path):
|
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 isinstance(logger, logging.Logger)
|
||||||
assert logger.name == "test_returns_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:
|
def test_caches_same_instance(self, tmp_path: Path) -> None:
|
||||||
with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path):
|
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 "hello from test" in content
|
||||||
assert "INFO" in content
|
assert "INFO" in content
|
||||||
|
|
||||||
def test_respects_grm_log_level(self, monkeypatch: pytest.MonkeyPatch, tmp_path: Path) -> None:
|
def test_only_file_handler(self, tmp_path: Path) -> None:
|
||||||
monkeypatch.setenv("GRM_LOG_LEVEL", "DEBUG")
|
|
||||||
with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path):
|
with patch("gitea_runner_manager.logging_config.Path.home", return_value=tmp_path):
|
||||||
logger = get_logger("test_env_level")
|
logger = get_logger("test_only_file")
|
||||||
console = [h for h in logger.handlers if type(h) is logging.StreamHandler]
|
|
||||||
|
|
||||||
assert len(console) == 1
|
assert len(logger.handlers) == 1
|
||||||
assert console[0].level == logging.DEBUG
|
assert isinstance(logger.handlers[0], logging.FileHandler)
|
||||||
|
|
||||||
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
|
|
||||||
|
|||||||
+29
-1
@@ -5,7 +5,23 @@ from __future__ import annotations
|
|||||||
import logging
|
import logging
|
||||||
from unittest.mock import patch
|
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:
|
class TestSay:
|
||||||
@@ -35,3 +51,15 @@ class TestSay:
|
|||||||
|
|
||||||
mock_echo.assert_called_once_with("error msg", err=True)
|
mock_echo.assert_called_once_with("error msg", err=True)
|
||||||
mock_logger.log.assert_called_once_with(logging.ERROR, "error msg")
|
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")
|
||||||
|
|||||||
Reference in New Issue
Block a user