The log is a text file that records what went wrong

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) <noreply@anthropic.com>
This commit is contained in:
Jean-Pierre MartineauandClaude Opus 5 committed 2026-09-07 14:43:13 -04:00
1 parent e2161fd191
commit bdc16fc448
6 files changed
+274 -40

No files matched your search

+11
View File
@@ -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:
+18
View File
@@ -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
+40 -12
View File
@@ -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:
+25
View File
@@ -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}
+71 -28
View File
@@ -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
``<config_dir>/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.
+109
View File
@@ -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