MeshTerm/meshterm/persistence/logging.py

# SPDX-License-Identifier: Apache-2.0
"""Logging setup: a plain text file that you can open, and a console that does not interfere.

There are two sinks. The console handler uses Rich formatting. It shows the records that
are for a person who watches the terminal. The file handler writes ordinary log lines to
``<config_dir>/meshterm.log``: one record on each line, with the timestamp, the level,
the logger, and the message. A traceback is indented under the line that raised it.

The file is plain text on purpose. It was JSON Lines before, because some program might
replay it one day. No program ever did. The only job of the file is this: a person who
has a problem opens it. Often this person reports the problem, and pastes the last twenty
lines into an issue. That person has a text editor, not a JSON parser.

The file rotates. Before, it was a single :class:`~logging.FileHandler`, which grows with
no limit. A real log file got to 11MB in ten weeks. That is a large quantity of disk
space on a handheld, and it is too large to attach to a bug report.

A preference sets how much MeshTerm writes: ``log_level``, with the default ``WARNING``.
Thus the file has the problems, not a full account of a session that works. When you
look for the cause of a problem, set it lower, to ``INFO`` or ``DEBUG``.

No log ever holds a password or a secret. Both handlers hide each secret that
:mod:`meshterm.core.secrets` finds in a record, and the file formatter does it again on
the traceback. This does not depend on a preference.

A preference, ``anonymize``, masks the personal details of each line before it
goes into the file: the account name in a home folder, the address of a radio, and the
address of a host (refer to :mod:`meshterm.core.anonymize`). The mask applies as each line
is written, so the file never holds what it masks. A line that was written before the
preference was turned on stays as it is.
"""

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 next to the data that it describes.
LOG_FILENAME = "meshterm.log"

#: The size at which the file rolls over, and the number of rolled files to keep. This is
#: approximately two weeks of a session with much traffic at DEBUG. Also, the full set is
#: small enough to attach to an issue with no problem.
_MAX_BYTES = 2 * 1024 * 1024
_BACKUP_COUNT = 3

#: ``2026-09-07 14:23:11 WARNING  meshterm.core.connection: link lost, retrying``
#: The level is padded, so that the messages align. The logger name tells which part of
#: MeshTerm wrote the record.
_LINE_FORMAT = "%(asctime)s %(levelname)-8s %(name)s: %(message)s"
_TIME_FORMAT = "%Y-%m-%d %H:%M:%S"


#: The levels that the ``log_level`` preference offers, by their own names. They are
#: written out here, instead of taken from ``logging.getLevelName`` or
#: ``getLevelNamesMapping``. The string-to-number direction of ``getLevelName`` is
#: deprecated. ``getLevelNamesMapping`` came in Python 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:
    """Change a value of the ``log_level`` preference into a level number.

    Args:
        name: A level name, in any letter case.
        fallback: The level to use when the name is not known. A typo in a
            ``preferences.toml`` that a person edited must cause less log detail. It must
            not prevent the start of the app.

    Returns:
        The level number that matches.
    """
    return _LEVELS.get(name.strip().upper(), fallback)


def log_path(log_dir: Path) -> Path:
    """Return the path of the log file, for an error message that names it."""
    return log_dir / LOG_FILENAME


def log_file_for(level: int) -> Path | None:
    """Return the file that gets a record at ``level``, or ``None`` if no file gets it.

    This function is for a message that says "the full error is in …". The message can say
    this only when the record went to that file, and the ``log_level`` preference controls
    that. If a user set the level of the file to ``ERROR``, the file has no warnings. Thus
    the message must not tell the user to look for them there.

    Args:
        level: The level at which the record was logged.

    Returns:
        The path of the log file, or ``None`` when logging is not configured or the level
        of the file is above ``level``.
    """
    for handler in logging.getLogger(_LOGGER_NAME).handlers:
        if isinstance(handler, logging.FileHandler) and handler.level <= level:
            return Path(handler.baseFilename)
    return None


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 to which the handler renders.
        log_dir: The directory for the ``meshterm.log`` file.
        level: The log level of the console.
        file_level: The log level of the file, from the ``log_level`` preference.
        quiet: When ``True``, write nothing to the console. Logging to the file continues.

    Returns:
        The configured ``meshterm`` logger.
    """
    logger = logging.getLogger(_LOGGER_NAME)
    logger.setLevel(logging.DEBUG)
    _drop_handlers(logger)
    logger.propagate = False

    if not quiet:
        # markup=False: a log line can have any text that the device sent (a node name, a
        # firmware error). With markup on, Rich reads `[...]` in such text as a style tag.
        # Because of this, the error path was the path most likely to fail. A report of a
        # fault on a node with the name `[/]Bob` raised MarkupError in the handler, and a
        # traceback about the diagnostic replaced the diagnostic. No log call in the
        # package uses markup in its message, so to parse the messages gives no benefit.
        rich_handler = RichHandler(
            console=console, rich_tracebacks=True, show_path=False, markup=False
        )
        rich_handler.setLevel(level)
        rich_handler.addFilter(_HIDE_SECRETS)
        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.addFilter(_HIDE_SECRETS)
    file_handler.setFormatter(_FileFormatter(_LINE_FORMAT, datefmt=_TIME_FORMAT))
    logger.addHandler(file_handler)

    _quiet_library_console(file_handler)

    return logger


class _HideSecrets(logging.Filter):
    """Hide each password and secret in the message of a record, for every handler.

    A filter on a handler sees each record that the handler gets, also the records of a
    child logger and of the libraries in :data:`_LIBRARY_LOGGERS`. A filter on a logger
    sees only the records of that logger. The filter writes the hidden message back into
    the record, so each handler after it gets the hidden form. A second pass finds nothing
    more, so the order of the handlers does not matter.

    The text of an exception can repeat a secret too. The console handler draws a
    traceback from the exception itself, and not from text that a filter can change. Thus,
    when the traceback of a record holds a secret, the filter adds the hidden traceback to
    the message as text and removes the exception from the record. Only such a record
    loses the drawn traceback of the console.
    """

    def filter(self, record: logging.LogRecord) -> bool:
        """Replace the message of ``record`` with its hidden form, and keep the record."""
        from ..core.secrets import hide

        try:
            message = record.getMessage()
        except Exception:  # noqa: BLE001 - a bad format is the problem of the handler
            return True
        hidden = hide(message)
        if record.exc_info and record.exc_info[0] is not None:
            traceback = logging.Formatter().formatException(record.exc_info)
            hidden_traceback = hide(traceback)
            if hidden_traceback != traceback:
                hidden = f"{hidden}\n{hidden_traceback}"
                record.exc_info, record.exc_text = None, None
        if hidden != message or record.args:
            record.msg, record.args = hidden, None
        return True


_HIDE_SECRETS = _HideSecrets()


class _FileFormatter(logging.Formatter):
    """The line format of the file, with no secret, and anonymized when the user asks.

    The formatter works on the whole formatted text: the message, and the traceback under
    it. :class:`_HideSecrets` already hid the message. The text of an exception in a
    traceback can repeat a secret too, so the formatter hides secrets again here, always.
    Then it masks the personal details if the ``anonymize`` preference is on. A traceback
    holds the most home folders, because each frame names its file. The formatter reads
    the preference at each record, so a change on the Preferences page applies to the
    next line. The mask does not change the record. The console handler gets the same
    record and shows it unmasked, because the console belongs to the user who reads it.
    """

    def format(self, record: logging.LogRecord) -> str:
        """Format ``record`` as one line (and its traceback), with no secret in it."""
        from ..core.anonymize import anonymize
        from ..core.preferences import current
        from ..core.secrets import hide

        text = hide(super().format(record))
        return anonymize(text) if current().anonymize else text


#: Third-party loggers that must never write to the terminal, because their records print
#: over the full-screen TUI. This module routes them to the file handler instead, so that
#: the records stay available for debugging. ``meshcore`` is the main cause: it calls
#: ``logging.basicConfig(level=INFO)`` when it is imported (for example,
#: "INFO:meshcore:Serial Connection started"). ``asyncio`` is in the list so that its
#: default exception handler logs to the file instead of the console. That handler reports
#: stray errors of background tasks after the prompt_toolkit handler that dumps errors on
#: the screen is turned off.
_LIBRARY_LOGGERS: tuple[str, ...] = ("meshcore", "asyncio")


def _quiet_library_console(file_handler: logging.Handler) -> None:
    """Keep the output of noisy third-party libraries off the terminal (it corrupts the TUI).

    The ``meshcore`` client calls ``logging.basicConfig(level=INFO)`` when it is imported.
    This call installs a stream handler on the root logger, and that handler prints its
    INFO lines over the screen. Two guards prevent this problem:

    1. Give the root logger a :class:`~logging.NullHandler`. ``basicConfig`` acts only
       when the root has no handlers. Thus it becomes a no-op and never adds its stream
       handler.
    2. Turn off propagation for each known library logger, and attach only
       ``file_handler``. Thus its records still go to the log, but they never get to the
       console, also if some other code path installs a stream handler on the root logger.

    Args:
        file_handler: The file handler of the application. It also gets the library
            records.
    """
    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)
        _drop_handlers(lib)
        lib.setLevel(logging.INFO)
        lib.propagate = False
        lib.addHandler(file_handler)


def _drop_handlers(logger: logging.Logger) -> None:
    """Detach the handlers of ``logger``, and close each one.

    If the function only clears the list, it removes the reference but leaves the file
    open. Each new configuration (a reconnect in the app, or each in-process CLI run under
    test) leaked one more descriptor on ``meshterm.log``. On Windows, such a descriptor is
    also a lock on a file that the rotation must rename later. A handler that fails to
    close is removed all the same, because the purpose of this call is that the old
    handlers get no more records.
    """
    for handler in list(logger.handlers):
        try:
            handler.close()
        except Exception:  # noqa: BLE001 - a handler that we discard must not stop the app
            pass
    logger.handlers.clear()


def get_logger(name: str | None = None) -> logging.Logger:
    """Return a child of the application logger.

    Args:
        name: An optional child name. When it is ``None``, the function returns the root
            logger of the app.

    Returns:
        The requested logger.
    """
    if name is None:
        return logging.getLogger(_LOGGER_NAME)
    return logging.getLogger(f"{_LOGGER_NAME}.{name}")