From bdc16fc448e1a340d8064c19a0d917582427e1ad Mon Sep 17 00:00:00 2001 From: Jean-Pierre Martineau Date: Mon, 7 Sep 2026 14:42:47 -0400 Subject: [PATCH] The log is a text file that records what went wrong MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three things were true of the log at once: it was JSON Lines, it never rotated, and it almost never recorded a failure. Of the last twenty thousand records in a real one, nine were warnings and three were errors. It faithfully kept the boring parts and missed the interesting ones, which is exactly backwards for the only job it has. It is plain text now, `~/.meshterm/meshterm.log`, one line per record with the traceback indented under the line that raised it. JSON Lines was there in case something replayed it; nothing ever did, and the actual reader is a person who has hit a problem and is about to paste the last twenty lines into an issue. That reader has a text editor. It rotates, at 2MB across three files. The old handler grew without limit and a real one reached 11MB over ten weeks — a lot of disk on a handheld, and an unreasonable thing to ask someone to attach. How much it keeps is a preference, `log_level` under a new Diagnostics group, defaulting to WARNING. That is what makes the file useful rather than large: it holds the problems, and turning it up to DEBUG for one run is how you chase something. Loaded before logging is configured, since it decides how logging is configured, and handed to the context afterwards so the file is not read twice. And failures are written down at last. Every unhandled error reaches the log with its traceback and the terminal says where to find it; expected errors — an ambiguous device, a bad preference — go in as warnings, because a log that only holds crashes cannot answer "what happened just before". The bug form now asks for the file, which it had no reason to before. Co-Authored-By: Claude Opus 5 (1M context) --- .github/ISSUE_TEMPLATE/bug.yml | 11 ++++ CHANGELOG.md | 18 ++++++ meshterm/cli.py | 52 +++++++++++---- meshterm/core/preferences.py | 25 ++++++++ meshterm/persistence/logging.py | 99 +++++++++++++++++++++-------- tests/test_logging.py | 109 ++++++++++++++++++++++++++++++++ 6 files changed, 274 insertions(+), 40 deletions(-) create mode 100644 tests/test_logging.py diff --git a/.github/ISSUE_TEMPLATE/bug.yml b/.github/ISSUE_TEMPLATE/bug.yml index bc62e5a..2be92a9 100644 --- a/.github/ISSUE_TEMPLATE/bug.yml +++ b/.github/ISSUE_TEMPLATE/bug.yml @@ -163,6 +163,17 @@ body: a photo of a terminal is hard to read. Paste the whole traceback if it crashed. render: text + - type: textarea + id: log + attributes: + label: The log file + description: > + MeshTerm keeps one at `~/.meshterm/meshterm.log` (or wherever `MESHTERM_HOME` + points). Attach it, or paste the last twenty lines. If the problem is hard to + catch, set **Log detail** to `DEBUG` on the Preferences page, do it once more, + and send that instead — it records a great deal more. + render: text + - type: textarea id: extra attributes: diff --git a/CHANGELOG.md b/CHANGELOG.md index 5f49c93..c41c8bc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,12 +17,30 @@ allowed to change behaviour, not just add to it. ## [Unreleased] +### Changed + +- The log is a plain text file, `~/.meshterm/meshterm.log`, one readable line per record + with the traceback under the line that raised it. It was JSON Lines on the theory that + something would replay it; nothing ever did, and the job it actually has is being opened + by a person who has hit a problem. +- It rotates, at 2 MB across three files. It used to grow without limit — a real one + reached 11 MB in ten weeks, which is a lot of disk on a handheld and an unreasonable + thing to attach to an issue. +- **How much it keeps is a preference** — `log_level`, under a new Diagnostics group, + defaulting to `WARNING`. The file now holds the problems rather than a narration of a + working session: of the last twenty thousand records in a real log, twelve were a + warning or an error. + ### Added - One interactive MeshTerm per data directory. A second one is turned away with the way out in the message, rather than quietly overwriting the first one's contacts and settings. The lock is held by the operating system, so a crash releases it — a process id in a file would leave a lock nobody could explain. +- Failures are written down. Every unhandled error reaches the log with its traceback and + the terminal says where to find it; expected errors go in as warnings, because a log + that only holds crashes cannot answer "what happened just before". The bug report form + asks for the file. - A readable answer when there is no Windows console. Git Bash, MSYS and Cygwin are not Windows consoles, and prompt_toolkit's own error says so in the language of its internals, arriving as a traceback that reads like a broken app rather than the diff --git a/meshterm/cli.py b/meshterm/cli.py index b1acee1..cab370e 100644 --- a/meshterm/cli.py +++ b/meshterm/cli.py @@ -22,9 +22,9 @@ from .core.connection import DeviceCommandError, is_connection_lost from .core.device_config import DeviceConfigError from .core.device_store import DeviceStore from .core.instancelock import InstanceBusy, hold_instance_lock -from .core.preferences import PreferenceError +from .core.preferences import PreferenceError, Preferences from .core.selection import DeviceSelectionError -from .persistence.logging import configure_logging +from .persistence.logging import configure_logging, get_logger, level_from_name, log_path from .persistence.repository import Repository from .platforms import Resolution, resolve, set_platform from .tools import all_tools @@ -143,9 +143,19 @@ def main_callback( settings.db_path = db_path console = make_console() - configure_logging(console, settings.config_dir, level=logging.INFO, quiet=quiet or json_output) + # Loaded before logging is configured, because how much goes in the file is one of + # them — and handed to the context afterwards so the file is not read twice. + prefs = Preferences.load(settings.config_dir / "preferences.yaml") + configure_logging( + console, + settings.config_dir, + level=logging.INFO, + file_level=level_from_name(prefs.log_level), + quiet=quiet or json_output, + ) app_ctx = AppContext( + preferences=prefs, console=console, settings=settings, repo=Repository(settings.db_path), @@ -188,6 +198,14 @@ def main_callback( raise typer.Exit(code=1) from None +def _report_log_location(console: Console, config_dir: Path) -> None: + """Point at the log after a fault, since it is the copy that outlives the terminal.""" + console.print() + console.print(f"[muted]The details are in {log_path(config_dir)}[/muted]") + console.print("[muted]Attach it to a bug report. For more detail next time, raise[/muted]") + console.print("[muted]'Log detail' on the Preferences page.[/muted]") + + def _report_no_windows_console(console: Console) -> None: """Explain a console MeshTerm cannot draw in, and how to get one it can. @@ -258,20 +276,30 @@ def run_tool_command(tool: Tool, params: dict) -> None: asyncio.run(_drive(_execute_and_render(tool, params, _state), _state)) except (DeviceSelectionError, DeviceConfigError, DeviceCommandError, PreferenceError) as exc: # Expected user-facing error (ambiguous/absent device, a bad config or preference - # value, or a transient command failure): show the message, not a traceback. + # value, or a transient command failure): show the message, not a traceback. Logged + # at warning because it is a thing that went wrong, even though it is an ordinary + # one — a log that only holds crashes cannot answer "what happened before it". + get_logger().warning("%s failed: %s", tool.name, exc) _state.console.print(f"[err]✗[/err] {exc}") raise typer.Exit(1) from exc except Exception as exc: # A dropped serial link (device unplugged/powered off mid-command) can't be recovered # from in a one-shot scripted run the way the interactive menu offers — but it should - # still read as a clean message, not a traceback. Anything else propagates as before. - if not is_connection_lost(exc): - raise - _state.console.print( - "[err]✗[/err] the connection to your device was lost " - "(it may have been unplugged or powered off)." - ) - raise typer.Exit(1) from exc + # still read as a clean message, not a traceback. + if is_connection_lost(exc): + get_logger().warning("%s lost the device connection: %s", tool.name, exc) + _state.console.print( + "[err]✗[/err] the connection to your device was lost " + "(it may have been unplugged or powered off)." + ) + raise typer.Exit(1) from exc + # Anything else is a real fault. It still reaches the terminal as a traceback, + # because a person looking at one wants to see it — but it also lands in the log, + # which is the copy that survives the terminal being closed and is the one thing + # worth attaching to a bug report. + get_logger().exception("%s raised an unhandled error", tool.name) + _report_log_location(_state.console, _state.settings.config_dir) + raise async def _drive(coro, ctx: AppContext) -> None: diff --git a/meshterm/core/preferences.py b/meshterm/core/preferences.py index 817fe65..163251d 100644 --- a/meshterm/core/preferences.py +++ b/meshterm/core/preferences.py @@ -57,6 +57,7 @@ GROUPS: tuple[str, ...] = ( "Map", "History", "Display", + "Diagnostics", ) @@ -124,6 +125,16 @@ _WIDTH_CHOICES: dict[str, str] = {"auto": "auto", "yes": "yes", "no": "no"} #: Every preference MeshTerm has, in page order. Adding one here gives it a row on the #: Preferences page, a key in the YAML file, a ``preferences get``/``set`` CLI face, and a #: default — nothing else has to follow. +#: What the log file keeps. Named rather than numeric, because those names are what every +#: other tool calls these and the reader is often being talked through it by someone else. +_LOG_LEVEL_CHOICES: dict[str, str] = { + "ERROR": "Errors only", + "WARNING": "Warnings and errors", + "INFO": "Also what the app is doing", + "DEBUG": "Everything, for chasing a bug", +} + + PREFERENCES: tuple[PrefSpec, ...] = ( # --- Sending ----------------------------------------------------------------- PrefSpec( @@ -283,6 +294,20 @@ PREFERENCES: tuple[PrefSpec, ...] = ( default="auto", choices=_WIDTH_CHOICES, ), + # --- Diagnostics --------------------------------------------------------------- + PrefSpec( + key="log_level", + label="Log detail", + help="How much MeshTerm writes to its log file", + group="Diagnostics", + value_type="enum", + # Problems, not a narration of a working session. The file used to take + # everything, which buried the dozen interesting lines under twenty thousand + # dull ones and made it awkward to attach to a bug report. + default="WARNING", + choices=_LOG_LEVEL_CHOICES, + relaunch=True, + ), ) _BY_KEY: dict[str, PrefSpec] = {spec.key: spec for spec in PREFERENCES} diff --git a/meshterm/persistence/logging.py b/meshterm/persistence/logging.py index 870da8a..e4c8263 100644 --- a/meshterm/persistence/logging.py +++ b/meshterm/persistence/logging.py @@ -1,13 +1,28 @@ -"""Structured logging setup. +"""Logging setup: a plain text file you can open, and a console that stays out of the way. -Two sinks are configured: a Rich-formatted console handler for human-readable output, -and a JSON-lines file handler that captures every record for later replay/analysis. +Two sinks. The console handler is Rich-formatted and shows what a person watching the +terminal should see. The file handler writes ordinary log lines to +``/meshterm.log`` — one record per line, timestamp, level, logger, message, +with a traceback indented under the line that raised it. + +Plain text on purpose. The file used to be JSON Lines, on the theory that something might +replay it; nothing ever did, and the one job it actually has is being opened by a person +who has hit a problem — often the person reporting it, who then pastes the last twenty +lines into an issue. That reader has a text editor, not a JSON parser. + +The file rotates. It used to be a single :class:`~logging.FileHandler`, which grows +without limit: a real one reached 11MB over ten weeks, which is both a lot of disk on a +handheld and an unreasonable thing to attach to a bug report. + +How much is written is a preference — ``log_level``, defaulting to ``WARNING``, so the +file holds the problems rather than a narration of a working session. Turn it down to +``INFO`` or ``DEBUG`` when chasing something. """ from __future__ import annotations -import json import logging +from logging.handlers import RotatingFileHandler from pathlib import Path from rich.console import Console @@ -15,28 +30,49 @@ from rich.logging import RichHandler _LOGGER_NAME = "meshterm" +#: The log file, in the config directory beside the data it describes. +LOG_FILENAME = "meshterm.log" -class JsonlFormatter(logging.Formatter): - """Format log records as one JSON object per line.""" +#: Keep this much before rolling over, and this many rolled files. Roughly a fortnight of +#: a chatty session at DEBUG, and small enough that the whole set can be attached to an +#: issue without apology. +_MAX_BYTES = 2 * 1024 * 1024 +_BACKUP_COUNT = 3 - def format(self, record: logging.LogRecord) -> str: - """Serialize a log record to a compact JSON string. +#: ``2026-09-07 14:23:11 WARNING meshterm.core.connection: link lost, retrying`` +#: Level is padded so the messages line up; the logger name says which part spoke. +_LINE_FORMAT = "%(asctime)s %(levelname)-8s %(name)s: %(message)s" +_TIME_FORMAT = "%Y-%m-%d %H:%M:%S" - Args: - record: The record to format. - Returns: - A single-line JSON document. - """ - payload = { - "ts": self.formatTime(record, "%Y-%m-%dT%H:%M:%S"), - "level": record.levelname, - "logger": record.name, - "msg": record.getMessage(), - } - if record.exc_info: - payload["exc"] = self.formatException(record.exc_info) - return json.dumps(payload) +#: The levels the ``log_level`` preference offers, by their own names. Spelled out rather +#: than taken from ``logging.getLevelName``, whose string-to-number direction is deprecated, +#: or ``getLevelNamesMapping``, which arrived in 3.11 and this package supports 3.10. +_LEVELS: dict[str, int] = { + "ERROR": logging.ERROR, + "WARNING": logging.WARNING, + "INFO": logging.INFO, + "DEBUG": logging.DEBUG, +} + + +def level_from_name(name: str, *, fallback: int = logging.WARNING) -> int: + """Turn a ``log_level`` preference value into a level number. + + Args: + name: A level name, in any case. + fallback: Used when the name is unrecognised — a hand-edited ``preferences.yaml`` + with a typo in it should lose some log detail, not stop the app from starting. + + Returns: + The matching level number. + """ + return _LEVELS.get(name.strip().upper(), fallback) + + +def log_path(log_dir: Path) -> Path: + """Return the log file's path, for an error message that wants to name it.""" + return log_dir / LOG_FILENAME def configure_logging( @@ -44,14 +80,16 @@ def configure_logging( log_dir: Path, *, level: int = logging.INFO, + file_level: int = logging.WARNING, quiet: bool = False, ) -> logging.Logger: """Configure and return the application logger. Args: console: The Rich console the handler should render to. - log_dir: Directory for the ``meshterm.log.jsonl`` event file. + log_dir: Directory for the ``meshterm.log`` file. level: Console log level. + file_level: File log level, from the ``log_level`` preference. quiet: When ``True``, suppress console output (file logging continues). Returns: @@ -70,9 +108,14 @@ def configure_logging( logger.addHandler(rich_handler) log_dir.mkdir(parents=True, exist_ok=True) - file_handler = logging.FileHandler(log_dir / "meshterm.log.jsonl", encoding="utf-8") - file_handler.setLevel(logging.DEBUG) - file_handler.setFormatter(JsonlFormatter()) + file_handler = RotatingFileHandler( + log_path(log_dir), + maxBytes=_MAX_BYTES, + backupCount=_BACKUP_COUNT, + encoding="utf-8", + ) + file_handler.setLevel(file_level) + file_handler.setFormatter(logging.Formatter(_LINE_FORMAT, datefmt=_TIME_FORMAT)) logger.addHandler(file_handler) _quiet_library_console(file_handler) @@ -100,8 +143,8 @@ def _quiet_library_console(file_handler: logging.Handler) -> None: 1. Give the root logger a :class:`~logging.NullHandler` so ``basicConfig`` — which only acts when the root has no handlers — becomes a no-op and never adds its stream handler. 2. Take each known library logger off propagation and attach only ``file_handler``, so - its records are still captured to the JSON-lines log but never reach the console, even - if some other code path installs a root stream handler anyway. + its records are still captured to the log but never reach the console, even if some + other code path installs a root stream handler anyway. Args: file_handler: The application's file handler to also capture library records to. diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..60f4132 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,109 @@ +"""Tests for the log file: plain text, bounded, and holding the things that went wrong. + +The log's one real job is being opened by a person who has hit a problem — often the +person reporting it. Every assertion here is about that reader. +""" + +from __future__ import annotations + +import logging +from pathlib import Path + +from rich.console import Console + +from meshterm.persistence.logging import ( + LOG_FILENAME, + configure_logging, + get_logger, + level_from_name, + log_path, +) + + +def _read(log_dir: Path) -> str: + for handler in get_logger().handlers: + handler.flush() + return log_path(log_dir).read_text(encoding="utf-8") + + +def test_the_log_is_plain_text(tmp_path: Path) -> None: + """One readable line per record: when, how bad, who said it, and what.""" + configure_logging(Console(quiet=True), tmp_path, file_level=logging.WARNING, quiet=True) + get_logger("core.connection").warning("link lost, retrying") + line = _read(tmp_path).splitlines()[0] + assert "WARNING" in line + assert "meshterm.core.connection" in line + assert "link lost, retrying" in line + # A date as well as a time. "it happened at 14:40" is useless a week later. + assert line.startswith("20") + + +def test_the_file_is_named_plainly(tmp_path: Path) -> None: + """``meshterm.log`` — an extension every text editor already opens.""" + assert log_path(tmp_path).name == LOG_FILENAME == "meshterm.log" + + +def test_the_level_keeps_the_quiet_records_out(tmp_path: Path) -> None: + """At the default, the file holds problems rather than a narration of a working run. + + This is the whole point of the default being WARNING: a log where the dozen useful + lines sit under twenty thousand dull ones is one nobody reads. + """ + configure_logging(Console(quiet=True), tmp_path, file_level=logging.WARNING, quiet=True) + log = get_logger() + log.debug("opened a screen") + log.info("connected to a radio") + log.warning("something went wrong") + written = _read(tmp_path) + assert "something went wrong" in written + assert "opened a screen" not in written + assert "connected to a radio" not in written + + +def test_turning_it_up_lets_everything_through(tmp_path: Path) -> None: + """DEBUG is there for chasing something, and keeps what WARNING drops.""" + configure_logging(Console(quiet=True), tmp_path, file_level=logging.DEBUG, quiet=True) + get_logger().debug("opened a screen") + assert "opened a screen" in _read(tmp_path) + + +def test_a_traceback_goes_in_with_the_record(tmp_path: Path) -> None: + """An exception's traceback is written under the record that reports it. + + This is most of why the file is worth attaching to a bug report: the terminal scrolls + away and gets closed, and this copy does not. + """ + configure_logging(Console(quiet=True), tmp_path, file_level=logging.WARNING, quiet=True) + try: + raise ValueError("the device said something impossible") + except ValueError: + get_logger().exception("tool raised") + written = _read(tmp_path) + assert "tool raised" in written + assert "ValueError: the device said something impossible" in written + assert "Traceback (most recent call last)" in written + + +def test_the_file_is_bounded(tmp_path: Path) -> None: + """It rotates. An unbounded log reached 11MB in ten weeks on a real install.""" + configure_logging(Console(quiet=True), tmp_path, file_level=logging.WARNING, quiet=True) + handler = next(h for h in get_logger().handlers if hasattr(h, "maxBytes")) + assert handler.maxBytes > 0 + assert handler.backupCount > 0 + + +def test_a_level_name_becomes_a_level(tmp_path: Path) -> None: + """The preference stores a name; the handler needs a number.""" + assert level_from_name("DEBUG") == logging.DEBUG + assert level_from_name("warning") == logging.WARNING + assert level_from_name(" Error ") == logging.ERROR + + +def test_a_nonsense_level_still_starts_the_app() -> None: + """A typo in a hand-edited preferences file loses log detail, not the app. + + Someone editing YAML by hand and writing ``WARN`` should get a slightly quieter log, + not a program that refuses to launch. + """ + assert level_from_name("WARN") == logging.WARNING + assert level_from_name("") == logging.WARNING