Files
MeshTerm/meshterm/persistence/logging.py
T
Jean-Pierre MartineauandClaude Opus 5 369e29e44a Five ways the scripted output lied, and the name that crashed it
The review pass found the CLI breaking its own written rules.

A node broadcasts its own name, so every name the CLI prints is remote
data — and Rich read `[...]` in it as a style tag. A node called
`[bold]Loud` printed as `Loud`, silently no longer the string that
identifies it; a node called `[/]Bob` raised MarkupError and took the
command down. The log handler then failed the same way while reporting
it, replacing the diagnostic with a traceback about the diagnostic. No
log line and no scripted line is ever marked up, so all three consoles
now say so.

`right=` never right-aligned anything. Rich's `Text.wrap` returns early
on `overflow="ignore"`, above the justify step, so asking for one threw
the other away — every numeric lane in the CLI was left-aligned while
CLAUDE.md, script.py's own docstring and the manual all said otherwise.
"crop" refuses to elide just as firmly and still aligns.

`config show` printed an empty string as `""` and `config set` read
those two characters literally, so feeding a dump back in replaced every
empty setting with a pair of quote marks — and the next dump looked
identical, so nothing ever said so. It also masked an *unreported* PIN
behind six bullets, telling the reader the radio was PIN-locked when it
was not: `conceal` already declined to mask the menu's absence token and
had simply never been shown the CLI's.

`meshterm about` drew the `---` above its colophon as a rule sized to
the console, which on a 16384-cell console is one 48KB line in a 4KB
page. A rule is a frame; the scripted copy drops it with the QR.

The contract fixture set only `--db`, which moves the history and
nothing else — so the suite read whatever was in the developer's own
~/.meshterm. That is how `[/]Bob`, planted by hand on one machine, could
crash the suite there and pass everywhere else. $MESHTERM_HOME moves the
whole directory.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-09-08 02:17:41 -04:00

182 lines
7.1 KiB
Python

"""Logging setup: a plain text file you can open, and a console that stays out of the way.
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 logging
from logging.handlers import RotatingFileHandler
from pathlib import Path
from rich.console import Console
from rich.logging import RichHandler
_LOGGER_NAME = "meshterm"
#: The log file, in the config directory beside the data it describes.
LOG_FILENAME = "meshterm.log"
#: 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
#: ``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"
#: 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(
console: Console,
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`` 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:
The configured ``meshterm`` logger.
"""
logger = logging.getLogger(_LOGGER_NAME)
logger.setLevel(logging.DEBUG)
logger.handlers.clear()
logger.propagate = False
if not quiet:
# markup=False: a log line carries whatever the device said — a node name, a
# firmware error — and Rich would read `[...]` in it as a style tag. That made the
# *error path* the one most likely to fail: reporting a fault on a node called
# `[/]Bob` raised MarkupError from inside the handler, replacing the diagnostic
# with a traceback about the diagnostic. No log call in the package marks up its
# message, so parsing them buys nothing.
rich_handler = RichHandler(
console=console, rich_tracebacks=True, show_path=False, markup=False
)
rich_handler.setLevel(level)
logger.addHandler(rich_handler)
log_dir.mkdir(parents=True, exist_ok=True)
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)
return logger
#: Third-party loggers that must never write to the terminal — their records would print
#: straight over the full-screen TUI. Routed to the file handler instead so they stay
#: captured for debugging. ``meshcore`` is the notable offender: it calls
#: ``logging.basicConfig(level=INFO)`` on import (e.g. "INFO:meshcore:Serial Connection
#: started"). ``asyncio`` is included so its default exception handler — the one that
#: reports stray background-task errors once prompt_toolkit's screen-dumping handler is
#: disabled — logs to the file instead of the console.
_LIBRARY_LOGGERS: tuple[str, ...] = ("meshcore", "asyncio")
def _quiet_library_console(file_handler: logging.Handler) -> None:
"""Keep noisy third-party libraries off the terminal (they corrupt the TUI).
The ``meshcore`` client calls ``logging.basicConfig(level=INFO)`` when it is imported,
which installs a stream handler on the *root* logger that prints its INFO lines straight
over the screen. Two guards prevent that:
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 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.
"""
root = logging.getLogger()
if not any(isinstance(h, logging.NullHandler) for h in root.handlers):
root.addHandler(logging.NullHandler())
for name in _LIBRARY_LOGGERS:
lib = logging.getLogger(name)
lib.handlers.clear()
lib.setLevel(logging.INFO)
lib.propagate = False
lib.addHandler(file_handler)
def get_logger(name: str | None = None) -> logging.Logger:
"""Return a child of the application logger.
Args:
name: Optional child name; when ``None`` the root app logger is returned.
Returns:
The requested logger.
"""
if name is None:
return logging.getLogger(_LOGGER_NAME)
return logging.getLogger(f"{_LOGGER_NAME}.{name}")