From bada8267a5f4359cd341be397a6fe518e601722b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Patryk=20W=C3=B3jtowicz?= Date: Thu, 12 Nov 2026 12:10:25 +0100 Subject: [PATCH] feat(cli): write a log in the project when a command has a problem --- CHANGELOG.md | 2 + src/miniops/__init__.py | 4 + src/miniops/adapters/local/schema.py | 5 + src/miniops/cli/__init__.py | 38 ++++- src/miniops/cli/log.py | 95 ++++++++++++ src/miniops/config/project.py | 10 +- tests/adapters/local/test_schema.py | 9 +- tests/cli/test_log.py | 224 +++++++++++++++++++++++++++ tests/config/test_project.py | 11 +- tests/test_main.py | 111 ++++++++++++- 10 files changed, 491 insertions(+), 18 deletions(-) create mode 100644 src/miniops/cli/log.py create mode 100644 tests/cli/test_log.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 4e9844e..b7e11ff 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,10 +13,12 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), - Local metadata store in SQLite, the first implementation of the metadata port. Its schema is versioned and upgrades itself when a store is opened, after making a backup. - `miniops init` creates a project in the current directory: it writes `miniops.toml` and adds `.miniops/` to `.gitignore`. - `miniops config show` prints the configuration of the project that the current directory belongs to. +- A command that has a problem inside a project leaves its log in `.miniops/logs/miniops.log`: what it did and the full traceback of the error. A command without warnings or errors writes nothing there. ### Changed - An error that miniOPs reports ends with a short message and exit code 1 instead of a traceback. +- An unexpected error inside a project shows a short message with the path of the log instead of a traceback. Outside a project, where there is no log, the traceback is still shown. - pydantic is now a dependency. It validates the configuration files. ## [0.1.0a1] - 2026-11-11 diff --git a/src/miniops/__init__.py b/src/miniops/__init__.py index 72ab812..54d9f39 100644 --- a/src/miniops/__init__.py +++ b/src/miniops/__init__.py @@ -1,7 +1,11 @@ """miniOPs: a lightweight, polars-native MLOps CLI.""" +import logging from importlib.metadata import version __version__ = version("miniops-ml") __all__ = ["__version__"] + +# Without any handler, Python prints the warnings and errors of a library to stderr itself. +logging.getLogger(__name__).addHandler(logging.NullHandler()) diff --git a/src/miniops/adapters/local/schema.py b/src/miniops/adapters/local/schema.py index 7585fcc..9cb4a4a 100644 --- a/src/miniops/adapters/local/schema.py +++ b/src/miniops/adapters/local/schema.py @@ -1,9 +1,12 @@ +import logging import sqlite3 from contextlib import closing from pathlib import Path from miniops.core.errors import IncompatibleStoreError +logger = logging.getLogger(__name__) + # A released script never changes: a change to the schema is a new script at the end. MIGRATIONS: tuple[str, ...] = ( """ @@ -102,9 +105,11 @@ def migrate(connection: sqlite3.Connection, path: Path) -> None: except BaseException: connection.execute("ROLLBACK") raise + logger.info("The store %s now has schema version %d", path, newest) def _back_up(connection: sqlite3.Connection, path: Path, version: int) -> None: backup = path.with_name(f"{path.name}.v{version}.bak") with closing(sqlite3.connect(backup)) as copy: connection.backup(copy) + logger.info("Copied the store %s to %s before upgrading its schema", path, backup) diff --git a/src/miniops/cli/__init__.py b/src/miniops/cli/__init__.py index b2873db..2fd0d03 100644 --- a/src/miniops/cli/__init__.py +++ b/src/miniops/cli/__init__.py @@ -1,15 +1,41 @@ +import logging +import shlex +import sys + import typer +from miniops import __version__ from miniops.cli.app import app +from miniops.cli.log import project_log from miniops.core.errors import MiniopsError __all__ = ["app", "main"] +logger = logging.getLogger(__name__) + def main() -> None: - """Run the command line. An error that miniOPs reports ends with a message, not a traceback.""" - try: - app(prog_name="miniops") - except MiniopsError as error: - typer.secho(f"Error: {error}", fg=typer.colors.RED, err=True) - raise SystemExit(1) from None + """Run the command line. + + An error ends with a short message, and its traceback goes to the log of the project. + """ + with project_log() as command_log: + logger.info("miniops %s: %s", __version__, shlex.join(sys.argv[1:])) + try: + app(prog_name="miniops") + except MiniopsError as error: + logger.error("Command failed: %s", error, exc_info=True) + typer.secho(f"Error: {error}", fg=typer.colors.RED, err=True) + raise SystemExit(1) from None + except Exception as error: + logger.critical("Unexpected error", exc_info=True) + if command_log is None or not command_log.saved: + raise + typer.secho( + f"Error: miniOPs hit an unexpected error ({type(error).__name__}: {error}). " + "This is a bug.", + fg=typer.colors.RED, + err=True, + ) + typer.echo(f"Details: {command_log.file}", err=True) + raise SystemExit(1) from None diff --git a/src/miniops/cli/log.py b/src/miniops/cli/log.py new file mode 100644 index 0000000..935a0d5 --- /dev/null +++ b/src/miniops/cli/log.py @@ -0,0 +1,95 @@ +import logging +from collections import deque +from collections.abc import Generator +from contextlib import contextmanager, suppress +from pathlib import Path +from typing import override + +from miniops.config.project import STATE_DIR, find_root + +MAX_BYTES = 1_000_000 +KEPT_RECORDS = 1000 + +_FORMAT = "%(asctime)s %(levelname)s [%(process)d] %(name)s: %(message)s" + + +class CommandLog(logging.Handler): + """The log of one command. It reaches the log file only if something goes wrong. + + Records wait in memory. The first warning or error writes them to the file, and after + that every record goes there directly. A command without problems leaves the file alone. + """ + + def __init__(self, file: Path) -> None: + """Create a log that writes to ``file`` once it has a reason to.""" + super().__init__() + self.setFormatter(logging.Formatter(_FORMAT)) + self.file = file + self.saved = False + self._waiting: deque[logging.LogRecord] = deque(maxlen=KEPT_RECORDS) + self._writing = False + + @override + def emit(self, record: logging.LogRecord) -> None: + self._waiting.append(record) + if not self._writing and record.levelno >= logging.WARNING: + self._writing = True + self._set_aside_a_full_file() + if self._writing: + self._write() + + def _set_aside_a_full_file(self) -> None: + # The rename fails when there is no file yet, or when another miniOPs process is + # writing to it (Windows). This command then adds to the file that is there. + with suppress(OSError): + if self.file.stat().st_size > MAX_BYTES: + self.file.replace(self.file.with_name(f"{self.file.name}.1")) + + def _write(self) -> None: + lines = [] + while self._waiting: + record = self._waiting.popleft() + try: + lines.append(self.format(record)) + except Exception: + self.handleError(record) + if not lines: + return + # A command never fails because of its log. + with suppress(OSError): + self.file.parent.mkdir(parents=True, exist_ok=True) + with self.file.open("a", encoding="utf-8", errors="backslashreplace") as file: + file.writelines(f"{line}\n" for line in lines) + self.saved = True + + +@contextmanager +def project_log(start: Path | None = None) -> Generator[CommandLog | None]: + """Collect what miniOPs logs during a command, for the project that ``start`` is in. + + ``start`` is the current directory unless given. Yields None when there is no project. + """ + file = _log_file(start) + if file is None: + yield None + return + command_log = CommandLog(file) + logger = logging.getLogger("miniops") + level = logger.level + logger.addHandler(command_log) + logger.setLevel(logging.DEBUG) + try: + yield command_log + finally: + logger.setLevel(level) + logger.removeHandler(command_log) + command_log.close() + + +def _log_file(start: Path | None) -> Path | None: + # Path.cwd() fails when the current directory was removed. + with suppress(OSError): + root = find_root(start or Path.cwd()) + if root is not None: + return root / STATE_DIR / "logs" / "miniops.log" + return None diff --git a/src/miniops/config/project.py b/src/miniops/config/project.py index f7a6efe..7c33460 100644 --- a/src/miniops/config/project.py +++ b/src/miniops/config/project.py @@ -50,7 +50,7 @@ def find_project(start: Path) -> Project: Raises: ConfigError: If there is no project, or its ``miniops.toml`` is not valid. """ - root = _find_root(start) + root = find_root(start) if root is None: raise ConfigError( f"No miniOPs project in {start} or above it. Create one with `miniops init`." @@ -67,7 +67,7 @@ def init_project(root: Path, name: str | None = None) -> Project: AlreadyExistsError: If the directory is a project already, or lies inside one. ConfigError: If the project would have no name. """ - existing = _find_root(root) + existing = find_root(root) if existing is not None: raise AlreadyExistsError(f"There is already a miniOPs project in {existing}.") name = (name or root.name).strip() @@ -84,7 +84,11 @@ def init_project(root: Path, name: str | None = None) -> Project: return Project(root=root, config=_load(config_file)) -def _find_root(start: Path) -> Path | None: +def find_root(start: Path) -> Path | None: + """Return the directory of the project that ``start`` is in, or None. + + It only looks for ``miniops.toml`` and does not read it. + """ start = start.resolve() for directory in (start, *start.parents): if (directory / CONFIG_FILE).is_file(): diff --git a/tests/adapters/local/test_schema.py b/tests/adapters/local/test_schema.py index ff9118a..6b3dc03 100644 --- a/tests/adapters/local/test_schema.py +++ b/tests/adapters/local/test_schema.py @@ -1,3 +1,4 @@ +import logging import sqlite3 from contextlib import closing from datetime import UTC, datetime @@ -42,7 +43,7 @@ def test_a_new_store_gets_the_newest_schema(tmp_path: Path) -> None: def test_an_older_store_is_upgraded_after_a_backup( - tmp_path: Path, monkeypatch: pytest.MonkeyPatch + tmp_path: Path, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture ) -> None: path = tmp_path / "metadata.db" with SqliteMetadataStore(path) as store: @@ -52,10 +53,14 @@ def test_an_older_store_is_upgraded_after_a_backup( schema, "MIGRATIONS", (*schema.MIGRATIONS, "CREATE TABLE deployments (id TEXT);") ) - with SqliteMetadataStore(path) as store: + with caplog.at_level(logging.INFO, logger="miniops"), SqliteMetadataStore(path) as store: assert store.list_models() == [MODEL] backup = tmp_path / f"metadata.db.v{older}.bak" + assert caplog.messages == [ + f"Copied the store {path} to {backup} before upgrading its schema", + f"The store {path} now has schema version {older + 1}", + ] assert version_of(path) == older + 1 assert "deployments" in tables_of(path) assert version_of(backup) == older diff --git a/tests/cli/test_log.py b/tests/cli/test_log.py new file mode 100644 index 0000000..3579f3e --- /dev/null +++ b/tests/cli/test_log.py @@ -0,0 +1,224 @@ +import logging +import os +from pathlib import Path + +import pytest + +from miniops.cli import log +from miniops.cli.log import project_log +from miniops.config.project import init_project + +logger = logging.getLogger("miniops.somewhere") + + +def log_file_of(root: Path) -> Path: + return root / ".miniops" / "logs" / "miniops.log" + + +def messages_in(root: Path) -> list[str]: + lines = log_file_of(root).read_text(encoding="utf-8").splitlines() + return [line.split("miniops.somewhere: ", 1)[1] for line in lines] + + +def test_a_command_without_problems_leaves_no_log(tmp_path: Path) -> None: + init_project(tmp_path) + + with project_log(tmp_path) as command_log: + logger.debug("looking for the lock file") + logger.info("trained churn") + + assert command_log is not None + assert not command_log.saved + assert not (tmp_path / ".miniops").exists() + + +def test_the_first_problem_writes_what_the_command_logged_so_far(tmp_path: Path) -> None: + init_project(tmp_path) + + with project_log(tmp_path) as command_log: + logger.debug("looking for the lock file") + logger.info("training churn") + logger.warning("the lock file is older than pyproject.toml") + assert messages_in(tmp_path) == [ + "looking for the lock file", + "training churn", + "the lock file is older than pyproject.toml", + ] + logger.info("trained churn") + + assert command_log is not None + assert command_log.saved + assert command_log.file == log_file_of(tmp_path) + assert messages_in(tmp_path)[-1] == "trained churn" + + +def test_a_line_shows_its_level_and_its_process(tmp_path: Path) -> None: + init_project(tmp_path) + + with project_log(tmp_path): + logger.warning("something is off") + + line = log_file_of(tmp_path).read_text(encoding="utf-8") + assert f" WARNING [{os.getpid()}] miniops.somewhere: something is off\n" in line + + +def test_an_error_is_written_with_its_traceback(tmp_path: Path) -> None: + init_project(tmp_path) + + with project_log(tmp_path): + try: + raise ValueError("not a number") + except ValueError: + logger.exception("training failed") + + text = log_file_of(tmp_path).read_text(encoding="utf-8") + assert "miniops.somewhere: training failed\n" in text + assert "Traceback (most recent call last)" in text + assert "ValueError: not a number" in text + + +def test_every_command_with_a_problem_adds_to_the_same_file(tmp_path: Path) -> None: + init_project(tmp_path) + + with project_log(tmp_path): + logger.error("first") + with project_log(tmp_path): + logger.error("second") + + assert messages_in(tmp_path) == ["first", "second"] + + +def test_the_log_is_found_from_a_directory_inside_the_project(tmp_path: Path) -> None: + init_project(tmp_path) + inside = tmp_path / "models" / "churn" + inside.mkdir(parents=True) + + with project_log(inside): + logger.error("something broke") + + assert messages_in(tmp_path) == ["something broke"] + + +def test_outside_a_project_nothing_is_kept(tmp_path: Path) -> None: + with project_log(tmp_path) as command_log: + logger.error("nobody keeps this") + + assert command_log is None + assert list(tmp_path.iterdir()) == [] + + +def test_a_log_that_cannot_be_written_does_not_stop_the_command(tmp_path: Path) -> None: + init_project(tmp_path) + (tmp_path / ".miniops").write_text("a file where the directory should be", encoding="utf-8") + + with project_log(tmp_path) as command_log: + logger.error("something broke") + + assert command_log is not None + assert not command_log.saved + + +def test_a_current_directory_that_is_gone_does_not_stop_the_command( + monkeypatch: pytest.MonkeyPatch, +) -> None: + def gone() -> Path: + raise FileNotFoundError("The current directory was removed") + + monkeypatch.setattr(Path, "cwd", staticmethod(gone)) + + with project_log() as command_log: + logger.error("something broke") + + assert command_log is None + + +def test_a_log_call_that_cannot_be_formatted_does_not_stop_the_command( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str] +) -> None: + init_project(tmp_path) + # pytest listens on the root logger and fails a test on a broken log call. + monkeypatch.setattr(logging.getLogger("miniops"), "propagate", False) + + with project_log(tmp_path) as command_log: + logger.warning("%s and %s", "only one") + assert command_log is not None + assert not command_log.saved + logger.warning("a line that works") + + assert "Logging error" in capsys.readouterr().err + assert messages_in(tmp_path) == ["a line that works"] + + +def test_text_that_cannot_be_encoded_is_written_with_escapes(tmp_path: Path) -> None: + init_project(tmp_path) + + with project_log(tmp_path) as command_log: + logger.error("cannot read %s", "data/\udcff.parquet") + + assert command_log is not None + assert command_log.saved + assert messages_in(tmp_path) == ["cannot read data/\\udcff.parquet"] + + +def test_logging_is_as_before_afterwards(tmp_path: Path) -> None: + init_project(tmp_path) + miniops_logger = logging.getLogger("miniops") + handlers, level = list(miniops_logger.handlers), miniops_logger.level + + with project_log(tmp_path): + logger.error("something broke") + + assert miniops_logger.handlers == handlers + assert miniops_logger.level == level + + +def test_only_the_latest_lines_before_a_problem_are_kept( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + init_project(tmp_path) + monkeypatch.setattr(log, "KEPT_RECORDS", 3) + + with project_log(tmp_path): + for number in range(1, 6): + logger.info("step %d", number) + logger.error("step 6 failed") + + assert messages_in(tmp_path) == ["step 4", "step 5", "step 6 failed"] + + +def test_a_full_log_is_set_aside_when_a_command_has_a_problem( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + init_project(tmp_path) + monkeypatch.setattr(log, "MAX_BYTES", 20) + with project_log(tmp_path): + logger.error("an old problem, in a line that is longer than the limit") + + with project_log(tmp_path): + logger.error("a new problem") + logger.error("and another one in the same command") + + previous = log_file_of(tmp_path).with_name("miniops.log.1") + assert "an old problem" in previous.read_text(encoding="utf-8") + assert messages_in(tmp_path) == ["a new problem", "and another one in the same command"] + + +def test_a_full_log_that_another_process_holds_keeps_growing( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + init_project(tmp_path) + monkeypatch.setattr(log, "MAX_BYTES", 20) + with project_log(tmp_path): + logger.error("an old problem, in a line that is longer than the limit") + + def refuse(self: Path, target: Path) -> Path: + raise PermissionError("The process cannot access the file") + + monkeypatch.setattr(Path, "replace", refuse) + with project_log(tmp_path): + logger.error("a new problem") + + assert messages_in(tmp_path) == [ + "an old problem, in a line that is longer than the limit", + "a new problem", + ] diff --git a/tests/config/test_project.py b/tests/config/test_project.py index f3893e6..43c2fe1 100644 --- a/tests/config/test_project.py +++ b/tests/config/test_project.py @@ -2,7 +2,7 @@ import pytest -from miniops.config.project import Target, find_project, init_project +from miniops.config.project import Target, find_project, find_root, init_project from miniops.core.errors import AlreadyExistsError, ConfigError @@ -109,6 +109,15 @@ def test_a_project_is_found_from_a_directory_inside_it(tmp_path: Path) -> None: assert find_project(inside).root == tmp_path +def test_the_root_is_found_without_reading_the_config(tmp_path: Path) -> None: + write_config(tmp_path, "[project\nname = ") + inside = tmp_path / "models" + inside.mkdir() + + assert find_root(inside) == tmp_path + assert find_root(tmp_path.parent) is None + + def test_outside_a_project_the_error_says_how_to_start(tmp_path: Path) -> None: with pytest.raises(ConfigError, match="miniops init"): find_project(tmp_path) diff --git a/tests/test_main.py b/tests/test_main.py index b2a858d..80f073c 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -5,7 +5,25 @@ import pytest from miniops import __version__ -from miniops.cli import main +from miniops.cli import config, main +from miniops.config.project import init_project + + +def run(monkeypatch: pytest.MonkeyPatch, directory: Path, *arguments: str) -> int: + monkeypatch.chdir(directory) + monkeypatch.setattr(sys, "argv", ["miniops", *arguments]) + with pytest.raises(SystemExit) as exit_info: + main() + assert isinstance(exit_info.value.code, int) + return exit_info.value.code + + +def log_of(project: Path) -> str: + return (project / ".miniops" / "logs" / "miniops.log").read_text(encoding="utf-8") + + +def boom(start: Path) -> None: + raise RuntimeError("boom") def test_module_entry_point_runs_the_cli( @@ -20,17 +38,98 @@ def test_module_entry_point_runs_the_cli( assert capsys.readouterr().out.strip() == f"miniops {__version__}" -def test_an_error_that_miniops_reports_ends_with_a_message_not_a_traceback( - tmp_path: Path, monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str] +def test_a_command_that_needs_no_directory_works_when_the_current_one_is_gone( + monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str] ) -> None: - monkeypatch.chdir(tmp_path) - monkeypatch.setattr(sys, "argv", ["miniops", "config", "show"]) + def gone() -> Path: + raise FileNotFoundError("The current directory was removed") + + monkeypatch.setattr(Path, "cwd", staticmethod(gone)) + monkeypatch.setattr(sys, "argv", ["miniops", "--version"]) with pytest.raises(SystemExit) as exit_info: main() - assert exit_info.value.code == 1 + assert exit_info.value.code == 0 + assert capsys.readouterr().out.strip() == f"miniops {__version__}" + + +def test_a_command_that_succeeds_leaves_no_log( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + init_project(tmp_path) + + assert run(monkeypatch, tmp_path, "config", "show") == 0 + + assert not (tmp_path / ".miniops").exists() + + +def test_an_error_that_miniops_reports_ends_with_a_message_not_a_traceback( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str] +) -> None: + assert run(monkeypatch, tmp_path, "config", "show") == 1 + captured = capsys.readouterr() assert captured.err.startswith("Error: No miniOPs project") assert "Traceback" not in captured.err assert captured.out == "" + + +def test_the_traceback_of_a_reported_error_is_in_the_log( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str] +) -> None: + init_project(tmp_path) + + assert run(monkeypatch, tmp_path, "init") == 1 + + assert capsys.readouterr().err.startswith("Error: There is already a miniOPs project") + log = log_of(tmp_path) + assert f"miniops.cli: miniops {__version__}: init\n" in log + assert " ERROR " in log + assert "Command failed: There is already a miniOPs project" in log + assert "Traceback (most recent call last)" in log + assert "AlreadyExistsError" in log + + +def test_an_unexpected_error_shows_where_the_details_are( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str] +) -> None: + init_project(tmp_path) + monkeypatch.setattr(config, "find_project", boom) + + assert run(monkeypatch, tmp_path, "config", "show") == 1 + + log_file = tmp_path / ".miniops" / "logs" / "miniops.log" + assert capsys.readouterr().err.splitlines() == [ + "Error: miniOPs hit an unexpected error (RuntimeError: boom). This is a bug.", + f"Details: {log_file}", + ] + log = log_of(tmp_path) + assert f"miniops.cli: miniops {__version__}: config show\n" in log + assert " CRITICAL " in log + assert "Traceback (most recent call last)" in log + assert "RuntimeError: boom" in log + + +def test_an_unexpected_error_is_not_hidden_when_the_log_cannot_be_written( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + init_project(tmp_path) + (tmp_path / ".miniops").write_text("a file where the directory should be", encoding="utf-8") + monkeypatch.chdir(tmp_path) + monkeypatch.setattr(sys, "argv", ["miniops", "config", "show"]) + monkeypatch.setattr(config, "find_project", boom) + + with pytest.raises(RuntimeError, match="boom"): + main() + + +def test_an_unexpected_error_outside_a_project_is_not_hidden( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + monkeypatch.chdir(tmp_path) + monkeypatch.setattr(sys, "argv", ["miniops", "config", "show"]) + monkeypatch.setattr(config, "find_project", boom) + + with pytest.raises(RuntimeError, match="boom"): + main()