diff --git a/CLAUDE.md b/CLAUDE.md index 9f21846..91c85a6 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -46,9 +46,10 @@ installed, so all drivers whose dependencies are on PyPI get import-tested. - **`Pyro5.config` is reset around every test** (autouse `pyro_config` fixture), because `update_pyro_config()` writes Pyro5 process globals and importing `pyrolab.api` applies the developer's own user config. Still pass `host="localhost"` explicitly when constructing daemons. -- **Use the `data_dir` fixture for anything touching runtime files** (`USER_CONFIG_FILE`, `RUNTIME_CONFIG`, - `LOCKFILE`, `PYROLAB_LOGDIR`, `NAMESERVER_STORAGE`). Tests must never write to the real data dir. See - "Runtime state" for why patching `pyrolab.X` alone is not enough. +- **The `data_dir` fixture is autouse**: every test sees PyroLab's paths (`USER_CONFIG_FILE`, `RUNTIME_CONFIG`, + `LOCKFILE`, `PYROLAB_LOGFILE`, `NAMESERVER_STORAGE`, `LEGACY_DATA_DIR`, ...) redirected into its own temp dir, so + no test can touch the real per-user directories or copy a developer's real pre-0.5 files. Add new path + constants to it. See "Runtime state" for why patching `pyrolab.X` alone is not enough. - `global_config` gives a fresh `GlobalConfiguration` singleton; `sample_config_yaml` / `sample_config_file` are a complete valid config using only `pyrolab.server` and `pyrolab.drivers.sample`. - **Hardware tests** get `@pytest.mark.hardware` and are skipped unless `--run-hardware` is passed. Import @@ -145,21 +146,34 @@ Most commands are thin wrappers that proxy to the running `PyroLabDaemon`. ### Runtime state -`pyrolab/__init__.py` creates and exports the data-dir constants at import time: `PYROLAB_DATA_DIR` -(`pyrolab/data/local/` inside the package), `USER_CONFIG_FILE`, `RUNTIME_CONFIG`, `LOCKFILE`, -`NAMESERVER_STORAGE`, `PYROLAB_LOGDIR`. It also installs a rotating file handler writing to -`logs/pyrolab_.log`. Env vars: `PYROLAB_LOGLEVEL`, `PYROLAB_LOGFILE`, `PYROLAB_HUSH_DEPRECATION`, -`PYROLAB_NO_VERSION_CHECK`. +`pyrolab/__init__.py` exports the path constants, computed at import from `pyrolab/locations.py` (per-user +`platformdirs` directories, or everything under `PYROLAB_DATA_DIR`): `USER_CONFIG_FILE`, `RUNTIME_CONFIG`, +`LOCKFILE`, `STARTUP_ERROR_FILE`, `NAMESERVER_STORAGE`, `PYROLAB_LOGDIR`, `PYROLAB_LOGFILE`, `UPDATE_CHECK_FILE`. +**Importing creates nothing** (`test_locations.py` checks this in a fresh interpreter); directories are created +where files are written (`atomic_write_text` makes parents). Before 0.5 everything lived in the package's +`pyrolab/data/local`; `migrate_legacy_files()` copies the config and nameserver databases from there once (a +marker file stops it repeating), run by the CLI callback and the daemon. + +Other modules bind these constants by value (`from pyrolab import LOCKFILE, ...` in `api`, `cli`, +`configure`, `manager`, `pyrolabd`), so redirecting a path means patching it in each of those modules — +which is what the `data_dir` test fixture does. + +**Logging** (`pyrolab/logs.py`): as a library, `pyrolab` only adds a `NullHandler` — it never configures +logging, `sys.excepthook`, or warning filters on import. The daemon (`pyrolabd.main`) is the **only writer** of +one rotating JSON-lines log (`PYROLAB_LOGFILE`, 5 MB x 5). Each child runner logs through its **own pipe** +(`log_to_pipe` in the child, `collect_from_pipe` in the parent): never a shared `multiprocessing.Queue` or +loguru `enqueue=True`, because a child killed mid-write would hold the shared lock and block all logging (a +real deadlock, tested in `test_logs.py`). The CLI's `run()` entry point (not `app`, which tests invoke) +applies process-wide settings; CLI commands only log to stderr when `PYROLAB_LOGLEVEL` is set. `pyrolab +status` / `logs show|export|clean` read the log back; entries after the last `daemon-start` event belong to +the current run. Env vars: `PYROLAB_DATA_DIR`, `PYROLAB_LOGFILE`, `PYROLAB_LOGLEVEL`, +`PYROLAB_HUSH_DEPRECATION`, `PYROLAB_NO_VERSION_CHECK`. **Importing `pyrolab` must never touch the network.** The PyPI update check lives in `pyrolab/updates.py` and runs only from the CLI's main callback, at most once a day (result cached in `UPDATE_CHECK_FILE`). An autouse test fixture sets `PYROLAB_NO_VERSION_CHECK` so CLI tests stay offline, and `test_updates.py` fails if importing the package performs any hostname lookup. -Other modules bind these constants by value (`from pyrolab import LOCKFILE, ...` in `api`, `cli`, -`configure`, `manager`, `pyrolabd`), so redirecting a path means patching it in each of those modules — -which is what the `data_dir` test fixture does. - `pyrolab/api.py` is the intended public surface — it re-exports the Pyro5 names plus PyroLab's, and on import applies the first configured nameserver's settings to `Pyro5.config` so `locate_ns()` just works. That step is best-effort: **importing `pyrolab.api` must never fail** because of the local config (invalid, no nameservers, @@ -175,8 +189,11 @@ excluded from import sorting (a ruff per-file ignore); import order there is loa `connect()` arguments must be keyword arguments with defaults — `autoconnect()` dictionary-unpacks `_autoconnect_params` into it. - numpydoc docstrings and type hints throughout; the API docs are autogenerated from them. -- Log via the `logging` module (`log = logging.getLogger(__name__)`). Servers run windowless in child - processes and fail silently, so logs are often the only diagnostic. +- Log via the standard `logging` module (`log = logging.getLogger(__name__)`), never by configuring handlers + in library code. Servers run windowless in child processes and fail silently, so logs (`pyrolab status`, + `pyrolab logs show`) are often the only diagnostic. +- `host: public` means "the address clients should reach this machine at" (`utils.get_ip`, which falls back + rather than failing without a route outside). Clients connect to the PyroLab server, never to instruments. - Optional hardware dependencies belong in a pyproject extra (`tsl550`, `ppcl55x`, `rto`, `arduino`, `cameras`), not in the base `dependencies`. PyPI rejects direct git URLs, so git-sourced extras stay commented out. `[tool.uv.sources]` can point development installs at git, but PyPI users never see it, so diff --git a/docs/user_guide/clients.rst b/docs/user_guide/clients.rst index 4117149..2d0c71d 100644 --- a/docs/user_guide/clients.rst +++ b/docs/user_guide/clients.rst @@ -16,6 +16,17 @@ up the connection: with Proxy(uri) as remote_object: remote_object.useful_method() +To see where an error happened on the server, not just that it was raised, +have Python print remote tracebacks (PyroLab doesn't change this for you when +imported, since it's your application's setting): + +.. code-block:: python + + import sys + import Pyro5.errors + + sys.excepthook = Pyro5.errors.excepthook + Assuming drivers and services have been written correctly, they only raise builtin Python exceptions. You can also catch different levels of exceptions if you know what exceptions an object can raise. Therefore you can use them in diff --git a/docs/user_guide/configuration.rst b/docs/user_guide/configuration.rst index 712b774..1626c43 100644 --- a/docs/user_guide/configuration.rst +++ b/docs/user_guide/configuration.rst @@ -51,3 +51,24 @@ Services .. todo:: Coming soon. + + +Choosing ``host`` +----------------- + +A nameserver or daemon listens on the address given by ``host``, and the URIs +it publishes contain that address, so it must be one that *clients* can reach. +Clients only ever connect to the PyroLab machine; instruments are reached by +that machine, not by clients. + +``localhost`` + Only programs on the same machine can connect (the default). +``public`` + PyroLab picks this machine's address on the network that routes to the + internet. On a machine without a route outside (an isolated lab network) + it falls back to the address the machine's hostname resolves to, then to + ``127.0.0.1``, and logs a warning. +an IP address or hostname + Use this when the machine is on several networks and the clients are not + on the internet-facing one, e.g. a private lab network on a second + network card. diff --git a/docs/user_guide/envvars.rst b/docs/user_guide/envvars.rst index 95fe537..26ccb03 100644 --- a/docs/user_guide/envvars.rst +++ b/docs/user_guide/envvars.rst @@ -1,31 +1,92 @@ .. _user_guide: -Environment Variables -===================== - -A few notes on simply starting PyroLab. When launched from the terminal, -PyroLab reads a few environment variables for convenient configuration. +Files, Logs, and Environment Variables +====================================== -.. todo:: - - Link to where the data directories is discussed, for appdirs. +Where PyroLab keeps its files +----------------------------- +Each user has their own PyroLab configuration, logs, and runtime state, kept in +the platform's usual places rather than inside the installed package (so +upgrading PyroLab never touches them): + +.. list-table:: + :header-rows: 1 + + * - + - Linux + - Windows + - macOS + * - Configuration + - ``~/.config/pyrolab`` + - ``%LOCALAPPDATA%\pyrolab`` + - ``~/Library/Application Support/pyrolab`` + * - Logs + - ``~/.local/state/pyrolab/log`` + - ``%LOCALAPPDATA%\pyrolab\Logs`` + - ``~/Library/Logs/pyrolab`` + * - Runtime state + - ``~/.local/state/pyrolab`` + - ``%LOCALAPPDATA%\pyrolab`` + - ``~/Library/Application Support/pyrolab`` + * - Nameserver data + - ``~/.local/share/pyrolab`` + - ``%LOCALAPPDATA%\pyrolab`` + - ``~/Library/Application Support/pyrolab`` + +``pyrolab --data`` prints the exact paths on your machine. Set +``PYROLAB_DATA_DIR`` (below) to keep everything in one directory instead. + +Versions before 0.5 kept these files inside the installed package. The first +time you run a ``pyrolab`` command after upgrading, it copies your +configuration and nameserver databases to the new locations (once, without +overwriting anything, and leaving the originals in place). + + +Logs +---- + +The background daemon writes a single log file, ``pyrolab.log``, for itself and +every nameserver and daemon it runs. It rotates at 5 MB, keeping five older +files. Each line is one JSON record. Rather than reading it directly: + +``pyrolab status`` + Whether the daemon is running, and the warnings and errors logged since it + started. +``pyrolab logs show`` + The log since the daemon last started (``--level``, ``--all``, ``--lines``). +``pyrolab logs export FILE`` + The whole log as text (or ``--json``), to attach to a bug report. +``pyrolab logs clean`` + Delete the logs (stop the daemon first). + +Output the daemon itself prints (such as a crash in a child process before it +could log) goes to ``pyrolabd_output.log`` beside the log. + +When you use PyroLab as a library (in a client script), it writes no log +files and leaves your application's logging alone; its messages go wherever +your application sends the ``pyrolab`` loggers. + + +Environment variables +--------------------- + +``PYROLAB_DATA_DIR`` + Keep all of PyroLab's files in this directory (logs in its ``logs`` + subdirectory) instead of the per-user locations above. ``PYROLAB_LOGFILE`` - The log file to write to. If not set, the default is ``pyrolab.log`` - within PyroLab's default data directory (see appdirs). + Where the daemon writes its log, instead of ``pyrolab.log`` in the log + directory. ``PYROLAB_LOGLEVEL`` - The log level to use. If not set, the default is ``INFO``. + The level to log at (``DEBUG``, ``INFO``, ``WARNING``, ...; default + ``INFO``). For the daemon this sets what goes into the log; when set, other + ``pyrolab`` commands also print their own log messages to the terminal. ``PYROLAB_HUSH_DEPRECATION`` - If set, silences all DeprecationWarnings from all modules. + If set, the ``pyrolab`` command and daemon hide DeprecationWarnings. ``PYROLAB_NO_VERSION_CHECK`` If set (to any value), the ``pyrolab`` command line tool never checks PyPI for a newer release. Otherwise it checks at most once a day, with a short timeout, and caches the result (including a failed check) so that machines on isolated networks don't wait on every command. Importing ``pyrolab`` as a library never checks. - -This can be very helpful when debugging to see how the program is progressing, -and when the program is being too verbose, it's easy to silence. Note that -including debugging will also include log statements from all of PyroLab's -dependencies. diff --git a/pyproject.toml b/pyproject.toml index 16b027b..3df08a2 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -70,6 +70,7 @@ dependencies = [ "tabulate", "requests", "packaging>=23.0", + "platformdirs>=3.0", ] # Optional hardware dependencies, installed with the "extras" syntax, e.g. @@ -113,7 +114,7 @@ namespaces = false "Research Group" = "https://camacholab.byu.edu/" [project.scripts] -pyrolab = "pyrolab.cli:app" +pyrolab = "pyrolab.cli:run" [tool.pytest.ini_options] minversion = "6.0" diff --git a/pyrolab/__init__.py b/pyrolab/__init__.py index 8ad02d4..79571b7 100644 --- a/pyrolab/__init__.py +++ b/pyrolab/__init__.py @@ -23,16 +23,10 @@ A framework for using remote lab instruments as local resources built on Pyro5. """ -import atexit -import fileinput +import logging import os -import pathlib import platform -import re import sys -from pathlib import Path -from time import strptime -from typing import Callable, Iterable # Check if Python version is supported pyversion = sys.version_info @@ -64,105 +58,33 @@ __website_url__ = "https://camacholab.byu.edu/" -# Filter warnings -import warnings - -warnings.filterwarnings("default", category=DeprecationWarning) -if "PYROLAB_HUSH_DEPRECATION" in os.environ: - warnings.filterwarnings("ignore", category=DeprecationWarning) - - -# Configuration directories -from importlib.resources import files - -base_path = files("pyrolab") / "data" / "local" - -# Data directories -PYROLAB_DATA_DIR = pathlib.Path(base_path) -PYROLAB_DATA_DIR.mkdir(parents=True, exist_ok=True) - -NAMESERVER_STORAGE = PYROLAB_DATA_DIR / "nameserver" -NAMESERVER_STORAGE.mkdir(parents=True, exist_ok=True) - -PYROLAB_LOGDIR = PYROLAB_DATA_DIR / "logs" -PYROLAB_LOGDIR.mkdir(parents=True, exist_ok=True) -PYROLAB_MASTERLOG = PYROLAB_LOGDIR / "pyrolab.log" +# Where PyroLab keeps its files: per-user directories (see pyrolab.locations). +# Importing creates nothing; files and directories are created when written. +from pathlib import Path -LOCKFILE = PYROLAB_DATA_DIR / "pyrolabd.lock" -USER_CONFIG_FILE = PYROLAB_DATA_DIR / "user_configuration.yaml" -RUNTIME_CONFIG = PYROLAB_DATA_DIR / "runtime_config.yaml" -UPDATE_CHECK_FILE = PYROLAB_DATA_DIR / "update_check.json" +from pyrolab.locations import LEGACY_DATA_DIR +from pyrolab.locations import locations as _find_locations + +_locations = _find_locations() + +PYROLAB_DATA_DIR = _locations.data_dir +NAMESERVER_STORAGE = _locations.data_dir / "nameserver" +PYROLAB_LOGDIR = _locations.log_dir +# The daemon's single log file; PYROLAB_LOGFILE overrides where it goes. +PYROLAB_LOGFILE = Path( + os.environ.get("PYROLAB_LOGFILE") or PYROLAB_LOGDIR / "pyrolab.log" +) +USER_CONFIG_FILE = _locations.config_dir / "user_configuration.yaml" +LOCKFILE = _locations.state_dir / "pyrolabd.lock" +RUNTIME_CONFIG = _locations.state_dir / "runtime_config.yaml" # Why the background daemon exited before it could serve requests, for `up`. -STARTUP_ERROR_FILE = PYROLAB_DATA_DIR / "pyrolabd_startup_error.txt" - - -# Set up logging to file -import logging -import logging.handlers - - -def get_loglevel() -> int: - loglevel = os.getenv("PYROLAB_LOGLEVEL", "INFO") - try: - loglevel = getattr(logging, loglevel.upper()) - except AttributeError: - loglevel = logging.INFO - return loglevel - - -if len(logging.root.handlers) == 0: - logfile = PYROLAB_LOGDIR / f"pyrolab_{os.getpid()}.log" - root = logging.getLogger() - h = logging.handlers.RotatingFileHandler(logfile, "a", 30000, 10) - f = logging.Formatter( - "[%(asctime)s.%(msecs)03d] %(levelname)-8s %(process)-5s %(processName)-16s %(name)-20s %(message)s", - datefmt="%Y-%m-%d %H:%M:%S", - ) - h.setFormatter(f) - root.addHandler(h) - root.setLevel(get_loglevel()) - root.debug("PyroLab logging configured") - - -# Include remote traceback in local tracebacks -import Pyro5.errors - -sys.excepthook = Pyro5.errors.excepthook - - -def try_itr(func: Callable, itr: Iterable, *exceptions, **kwargs): - """ - Tests a function on an iterable, yields iterable if no exception is raised. - """ - for elem in itr: - try: - func(elem, **kwargs) - yield elem - except exceptions: - pass - +STARTUP_ERROR_FILE = _locations.state_dir / "pyrolabd_startup_error.txt" +# Records that files from a pre-0.5 install were copied (see pyrolab.locations). +LEGACY_MIGRATION_MARKER = _locations.state_dir / "legacy_files_copied.txt" +UPDATE_CHECK_FILE = _locations.cache_dir / "update_check.json" -# @atexit.register -# def condense_logs(): -# """ -# Cleans up the logfile directory every once in a while. -# Runs at exit or when "pyrolab down" is called. Condenses all process log -# files into a single logfile that is sorted by timestamp. -# """ -# f_names = list(PYROLAB_LOGDIR.glob("*.*")) -# lines = list(fileinput.input(f_names)) -# t_fmt = "%Y-%m-%d %H:%M:%S.%f" # format of time stamps -# t_pat = re.compile(r"\[(.+?)\]") # pattern to extract timestamp -# lines = list( -# try_itr( -# lambda l: strptime(t_pat.search(l).group(1), t_fmt), lines, AttributeError -# ) -# ) -# with PYROLAB_MASTERLOG.open(mode="w") as f: -# for l in sorted(lines, key=lambda l: strptime(t_pat.search(l).group(1), t_fmt)): -# f.write(l) -# if PYROLAB_MASTERLOG in f_names: -# f_names.remove(PYROLAB_MASTERLOG) -# for f in f_names: -# f.unlink() +# As a library, PyroLab leaves logging to the application: its loggers do +# nothing until the application (or PyroLab's own CLI and daemon, see +# pyrolab.logs) configures logging. +logging.getLogger(__name__).addHandler(logging.NullHandler()) diff --git a/pyrolab/cli.py b/pyrolab/cli.py index 5490fc5..6ccaff6 100644 --- a/pyrolab/cli.py +++ b/pyrolab/cli.py @@ -11,16 +11,16 @@ Try ``pyrolab --help`` for help. """ -import fileinput +import json +import logging import platform -import re import subprocess import sys import textwrap import time from pathlib import Path -from time import sleep, strptime -from typing import Callable, Iterable, Optional +from time import sleep +from typing import Optional from tabulate import tabulate @@ -34,12 +34,17 @@ import pyrolab from pyrolab import ( + LEGACY_DATA_DIR, + LEGACY_MIGRATION_MARKER, LOCKFILE, + NAMESERVER_STORAGE, PYROLAB_LOGDIR, + PYROLAB_LOGFILE, RUNTIME_CONFIG, STARTUP_ERROR_FILE, UPDATE_CHECK_FILE, USER_CONFIG_FILE, + logs, updates, ) from pyrolab.api import Proxy @@ -52,6 +57,7 @@ reset_config, update_config, ) +from pyrolab.locations import DATA_DIR_ENV_VAR, migrate_legacy_files from pyrolab.pyrolabd import PyroLabDaemon, read_lockfile from pyrolab.utils import atomic_write_text, pid_is_running @@ -126,9 +132,16 @@ def _version_callback(value: bool = True) -> None: def _show_data_dir(value: bool = True) -> None: if value: - from pyrolab import PYROLAB_DATA_DIR - - typer.echo(f"{PYROLAB_DATA_DIR}") + rows = [ + ("Configuration", USER_CONFIG_FILE), + ("Log file", PYROLAB_LOGFILE), + ("Runtime state", LOCKFILE.parent), + ("Nameserver data", NAMESERVER_STORAGE), + ("Cache", UPDATE_CHECK_FILE.parent), + ] + for label, path in rows: + typer.echo(f"{label + ':':17s}{path}") + typer.echo(f"(Set {DATA_DIR_ENV_VAR} to keep everything in one directory.)") raise typer.Exit() @@ -146,13 +159,25 @@ def main( False, "--data", "-d", - help="Show the data directories and exit.", + help="Show where PyroLab keeps its files and exit.", callback=_show_data_dir, is_eager=True, ), ): # Runs before every subcommand (but not --version or --data, which exit - # first). Checks PyPI at most once a day; see pyrolab.updates. + # first). + copied = migrate_legacy_files( + LEGACY_DATA_DIR, USER_CONFIG_FILE, NAMESERVER_STORAGE, LEGACY_MIGRATION_MARKER + ) + if copied: + typer.secho( + "PyroLab now keeps its files outside the installed package. Copied " + "from the old location (the originals are untouched):\n" + + "".join(f" {line}\n" for line in copied), + fg=typer.colors.YELLOW, + err=True, + ) + # Checks PyPI at most once a day; see pyrolab.updates. latest = updates.check_for_update(pyrolab.__version__, UPDATE_CHECK_FILE) if latest: typer.secho( @@ -255,8 +280,8 @@ def up( reason = ( STARTUP_ERROR_FILE.read_text().strip() if STARTUP_ERROR_FILE.exists() - else f"it exited with code {process.returncode}; see the logs in " - f"{PYROLAB_LOGDIR}" + else f"it exited with code {process.returncode}; see 'pyrolab logs " + f"show' and {PYROLAB_LOGDIR / DAEMON_OUTPUT_LOG}" ) typer.secho( f"PyroLab daemon failed to start: {reason}", fg=typer.colors.RED @@ -265,8 +290,7 @@ def up( if time.monotonic() > deadline: typer.secho( f"PyroLab daemon did not respond within {timeout:g} seconds. It may " - "still be starting; check with 'pyrolab ps', or see the logs in " - f"{PYROLAB_LOGDIR}.", + "still be starting; check with 'pyrolab status'.", fg=typer.colors.RED, ) raise typer.Exit(1) @@ -290,8 +314,8 @@ def down( while LOCKFILE.exists(): if time.monotonic() > deadline: typer.secho( - f"PyroLab daemon has not exited after {timeout:g} seconds; see the " - f"logs in {PYROLAB_LOGDIR}.", + f"PyroLab daemon has not exited after {timeout:g} seconds; see " + "'pyrolab logs show'.", fg=typer.colors.RED, ) raise typer.Exit(1) @@ -334,6 +358,53 @@ def ps(): typer.echo(daemon.ps()) +@app.command() +def status( + lines: int = typer.Option( + 20, "--lines", "-n", help="Show at most this many (the most recent)." + ), +): + """ + Is the daemon running, and what has gone wrong since it started? + + Shows the warnings and errors logged since the daemon last started (or + during its last run, if it has stopped). + """ + info = read_lockfile() + running = info is not None and pid_is_running(info.pid) + if not running: + typer.echo("PyroLab daemon is not running.") + elif _daemon_responds(info.uri): + typer.secho( + f"PyroLab daemon is running (pid {info.pid}, {info.uri}).", + fg=typer.colors.GREEN, + ) + else: + typer.secho( + f"PyroLab daemon (pid {info.pid}) is running but not responding.", + fg=typer.colors.YELLOW, + ) + + entries, _ = logs.read_entries(logs.log_files(PYROLAB_LOGFILE)) + if not entries: + typer.echo(f"Nothing has been logged yet ({PYROLAB_LOGFILE}).") + return + problems = list(logs.at_least(logs.since_last_start(entries), logging.WARNING)) + when = "since it started" if running else "during its last run" + if not problems: + typer.echo(f"No warnings or errors {when}.") + return + shown = problems[-lines:] if lines > 0 else problems + typer.echo( + f"{len(problems)} warnings and errors {when}" + + (f" (the last {len(shown)}):" if len(shown) < len(problems) else ":") + ) + for entry in shown: + typer.echo(logs.format_entry(entry, details=False)) + if any(e.get("exception") or e.get("stack") for e in shown): + typer.echo("For tracebacks: pyrolab logs show --level warning") + + ############################################################################### # pyrolab config ############################################################################### @@ -527,71 +598,87 @@ def info(): ############################################################################### logs_app = typer.Typer() -app.add_typer(logs_app, name="logs", help="Compile and export log files.") +app.add_typer(logs_app, name="logs", help="Read, export, and clean up the log.") -@logs_app.command("clean") -def logs_clean(): - """ - Deletes all log files. - """ - for f in PYROLAB_LOGDIR.glob("*.*"): - # Try to delete file if not in use - try: - f.unlink() - except PermissionError: - pass +def _parse_level(level: str) -> int: + number = logs.find_level(level) + if number is None: + raise typer.BadParameter(f"unknown level '{level}' (e.g. DEBUG, INFO, WARNING)") + return number -def try_itr(func: Callable, itr: Iterable, *exceptions, **kwargs): +@logs_app.command("show") +def logs_show( + level: str = typer.Option( + "INFO", "--level", "-l", help="Show entries at this level and above." + ), + all_runs: bool = typer.Option( + False, "--all", help="Include earlier runs of the daemon, not just the latest." + ), + lines: int = typer.Option( + 50, "--lines", "-n", help="Show at most this many (the most recent); 0 for all." + ), +): """ - Tests a function on an iterable, yields iterable if no exception is raised. + Show the log, from the daemon's most recent start. """ - for elem in itr: - try: - func(elem, **kwargs) - yield elem - except exceptions: - pass + minimum = _parse_level(level) + entries, skipped = logs.read_entries(logs.log_files(PYROLAB_LOGFILE)) + if not all_runs: + entries = logs.since_last_start(entries) + selected = list(logs.at_least(entries, minimum)) + for entry in selected[-lines:] if lines > 0 else selected: + typer.echo(logs.format_entry(entry)) + if not selected: + typer.echo("No matching log entries.") + if skipped: + typer.secho(f"({skipped} unreadable lines skipped)", err=True) @logs_app.command("export") -def logs_export(filename: str): - """ - Exports the log file to a file. - """ - # The daemon's raw stdout/stderr isn't in the timestamped log format. - f_names = [f for f in PYROLAB_LOGDIR.glob("*.*") if f.name != DAEMON_OUTPUT_LOG] - lines = list(fileinput.input(f_names)) - t_fmt = "%Y-%m-%d %H:%M:%S.%f" # format of time stamps - t_pat = re.compile(r"\[(.+?)\]") # pattern to extract timestamp - - # Group lines into log entries - log_entries = [] - current_entry = [] - for line in lines: - # If we've found a new timestamp and we have a current entry, add it to - # the list and start a new entry. - if t_pat.match(line) and current_entry: - log_entries.append("".join(current_entry)) - current_entry = [line] - # Otherwise, keep extending the current entry. - else: - current_entry.append(line) - # Add the last entry to the list - if current_entry: - log_entries.append("".join(current_entry)) - - # Sort log entries by timestamp - log_entries = sorted( - log_entries, key=lambda entry: strptime(t_pat.search(entry).group(1), t_fmt) +def logs_export( + filename: str, + as_json: bool = typer.Option( + False, "--json", help="Write JSON lines (one entry per line) instead of text." + ), +): + """ + Write the whole log, oldest first, to a file. + """ + entries, skipped = logs.read_entries(logs.log_files(PYROLAB_LOGFILE)) + lines = [json.dumps(e) if as_json else logs.format_entry(e) for e in entries] + atomic_write_text(filename, "".join(f"{line}\n" for line in lines)) + typer.secho( + f"Exported {len(entries)} log entries to {filename}", fg=typer.colors.GREEN ) + if skipped: + typer.echo(f"Skipped {skipped} unreadable lines.") - # Write sorted log entries to the output file - with Path(filename).open(mode="w") as f: - for entry in log_entries: - f.write(entry) - typer.secho(f"Exported logs to {filename}", fg=typer.colors.GREEN) + +@logs_app.command("clean") +def logs_clean(): + """ + Delete the log files. The daemon must be stopped first. + """ + info = read_lockfile() + if info is not None and pid_is_running(info.pid): + typer.secho( + "The PyroLab daemon is running and writing the log; stop it first " + "('pyrolab down').", + fg=typer.colors.RED, + ) + raise typer.Exit(1) + removed = 0 + for path in logs.log_files(PYROLAB_LOGFILE) + [PYROLAB_LOGDIR / DAEMON_OUTPUT_LOG]: + try: + path.unlink() + removed += 1 + except FileNotFoundError: + pass + except OSError as e: + typer.secho(f"Could not remove {path}: {e}", fg=typer.colors.RED) + typer.echo(f"Removed {removed} log files.") ############################################################################### @@ -739,5 +826,18 @@ def ns_list( # app.add_typer(add_app, name="add") -if __name__ == "__main__": +def run() -> None: + """ + The ``pyrolab`` command. + + Applies process-wide settings (remote tracebacks, warnings, logging to + stderr if PYROLAB_LOGLEVEL is set) here rather than in ``app``, so that + using the app in-process, as the tests do, changes nothing global. + """ + logs.configure_process() + logs.configure_cli_logging() app() + + +if __name__ == "__main__": + run() diff --git a/pyrolab/locations.py b/pyrolab/locations.py new file mode 100644 index 0000000..a0477b2 --- /dev/null +++ b/pyrolab/locations.py @@ -0,0 +1,129 @@ +# Copyright © PyroLab Project Contributors +# Licensed under the terms of the GNU GPLv3+ License +# (see pyrolab/__init__.py for details) + +""" +Locations +========= + +Where PyroLab keeps its files. + +Each user gets their own configuration, logs, and runtime state, in the +platform's usual places (via ``platformdirs``):: + + Linux Windows macOS + config ~/.config/pyrolab %LOCALAPPDATA%\\pyrolab ~/Library/Application Support/pyrolab + state ~/.local/state/pyrolab %LOCALAPPDATA%\\pyrolab ~/Library/Application Support/pyrolab + data ~/.local/share/pyrolab %LOCALAPPDATA%\\pyrolab ~/Library/Application Support/pyrolab + logs ~/.local/state/pyrolab/log %LOCALAPPDATA%\\pyrolab\\Logs ~/Library/Logs/pyrolab + cache ~/.cache/pyrolab %LOCALAPPDATA%\\pyrolab\\Cache ~/Library/Caches/pyrolab + +Setting ``PYROLAB_DATA_DIR`` puts everything in that one directory instead +(logs in its ``logs`` subdirectory), e.g. for a shared service account. + +Nothing here creates directories; files are created where they are written. +Versions before 0.5 kept everything inside the installed package, in +``pyrolab/data/local``; :py:func:`migrate_legacy_files` copies what is worth +keeping from there. +""" + +import os +import shutil +from pathlib import Path +from typing import List, Mapping, NamedTuple + +import platformdirs + +APP_NAME = "pyrolab" +DATA_DIR_ENV_VAR = "PYROLAB_DATA_DIR" + +# Where versions before 0.5 kept their files, inside the installed package. +LEGACY_DATA_DIR = Path(__file__).resolve().parent / "data" / "local" + + +class Locations(NamedTuple): + config_dir: Path + state_dir: Path + data_dir: Path + log_dir: Path + cache_dir: Path + + +def locations(environ: Mapping[str, str] = os.environ) -> Locations: + """ + Work out PyroLab's directories for the current user. + + Parameters + ---------- + environ : Mapping[str, str], optional + The environment to read ``PYROLAB_DATA_DIR`` from (default + ``os.environ``). + + Returns + ------- + Locations + The config, state, data, log, and cache directories. + """ + root = environ.get(DATA_DIR_ENV_VAR) + if root: + root = Path(root).expanduser() + return Locations(root, root, root, root / "logs", root) + dirs = platformdirs.PlatformDirs(APP_NAME, appauthor=False) + return Locations( + config_dir=Path(dirs.user_config_dir), + state_dir=Path(dirs.user_state_dir), + data_dir=Path(dirs.user_data_dir), + log_dir=Path(dirs.user_log_dir), + cache_dir=Path(dirs.user_cache_dir), + ) + + +def migrate_legacy_files( + legacy_dir: Path, user_config_file: Path, nameserver_storage: Path, marker: Path +) -> List[str]: + """ + Copy the configuration and nameserver databases from a pre-0.5 install. + + Runs once: afterwards ``marker`` records that it did, so a configuration + the user later resets isn't brought back. Nothing that already exists at + the new location is overwritten, and the old files are left in place. + Logs, lockfiles, and runtime state aren't copied. + + Parameters + ---------- + legacy_dir : Path + The old ``pyrolab/data/local`` directory. + user_config_file : Path + Where the user configuration lives now. + nameserver_storage : Path + Where nameserver databases live now. + marker : Path + A file recording that migration has run. + + Returns + ------- + List[str] + A description of each file copied (empty if nothing was). + """ + if marker.exists() or not legacy_dir.is_dir(): + return [] + + copied = [] + + def copy(src: Path, dst: Path) -> None: + if src.is_file() and not dst.exists(): + dst.parent.mkdir(parents=True, exist_ok=True) + shutil.copy2(src, dst) + copied.append(f"{src} -> {dst}") + + copy(legacy_dir / "user_configuration.yaml", user_config_file) + legacy_storage = legacy_dir / "nameserver" + if legacy_storage.is_dir(): + for src in sorted(legacy_storage.iterdir()): + copy(src, nameserver_storage / src.name) + + marker.parent.mkdir(parents=True, exist_ok=True) + marker.write_text( + f"Copied from {legacy_dir}:\n" + "".join(f"{c}\n" for c in copied) + ) + return copied diff --git a/pyrolab/logs.py b/pyrolab/logs.py new file mode 100644 index 0000000..7d68ef6 --- /dev/null +++ b/pyrolab/logs.py @@ -0,0 +1,359 @@ +# Copyright © PyroLab Project Contributors +# Licensed under the terms of the GNU GPLv3+ License +# (see pyrolab/__init__.py for details) + +""" +Logs +==== + +PyroLab's log: one file, written by one process. + +The background daemon (``pyrolabd``) is the only writer of the log file. The +nameservers and daemons it runs as child processes send their records to it, +each over a pipe of its own (:py:func:`log_to_pipe` in the child, +:py:func:`collect_from_pipe` in the parent). A shared queue would be simpler, +but every process would then write through one cross-process lock, and a +child killed while holding it (stopping escalates to ``kill()`` for processes +that hang) would block logging, and with it the daemon, for good. With a +pipe per child, a killed child can only break its own pipe. + +Each line of the log is one JSON object, so it can be read back reliably by +``pyrolab status``, ``pyrolab logs show``, and ``pyrolab logs export``. + +Importing ``pyrolab`` configures none of this: as a library it only adds a +``NullHandler``. The ``pyrolab`` command and the daemon set up logging for +their own processes. +""" + +import json +import logging +import logging.handlers +import os +import threading +import warnings +from datetime import datetime +from pathlib import Path +from typing import Callable, Iterable, Iterator, List, Optional, Tuple + +LOG_MAX_BYTES = 5 * 1024 * 1024 +LOG_BACKUPS = 5 +LOGLEVEL_ENV_VAR = "PYROLAB_LOGLEVEL" +HUSH_DEPRECATION_ENV_VAR = "PYROLAB_HUSH_DEPRECATION" + +# Marks where each run of the daemon begins, for "since it last started". +DAEMON_START_EVENT = "daemon-start" + + +def log_level() -> int: + """The level from ``PYROLAB_LOGLEVEL`` (a name such as DEBUG), default INFO.""" + level = logging.getLevelName(os.environ.get(LOGLEVEL_ENV_VAR, "INFO").upper()) + return level if isinstance(level, int) else logging.INFO + + +############################################################################### +# Format +############################################################################### + + +class JsonLinesFormatter(logging.Formatter): + """Formats each record as one line of JSON.""" + + def format(self, record: logging.LogRecord) -> str: + entry = { + "time": datetime.fromtimestamp(record.created).isoformat( + timespec="milliseconds" + ), + "level": record.levelname, + "process": record.processName, + "pid": record.process, + "logger": record.name, + "message": record.getMessage(), + } + if record.exc_info: + entry["exception"] = self.formatException(record.exc_info) + elif record.exc_text: + entry["exception"] = record.exc_text + if record.stack_info: + entry["stack"] = self.formatStack(record.stack_info) + event = getattr(record, "event", None) + if event: + entry["event"] = event + return json.dumps(entry) + + +def format_entry(entry: dict, details: bool = True) -> str: + """ + A log entry as readable text, with any traceback indented below it (or, + with ``details=False``, just a note that there is one). + """ + time = entry.get("time", "?").replace("T", " ") + text = ( + f"{time} {entry.get('level', '?'):8s} " + f"{entry.get('process', '?')} ({entry.get('pid', '?')}) " + f"{entry.get('logger', '?')}: {entry.get('message', '')}" + ) + for extra in ("exception", "stack"): + if not entry.get(extra): + continue + if details: + text += "\n" + "\n".join( + " " + line for line in entry[extra].splitlines() + ) + else: + text += " [traceback]" + return text + + +############################################################################### +# Process setup +############################################################################### + + +def configure_process() -> None: + """ + Process-wide settings for PyroLab's own executables (the CLI and daemon). + + Shows remote tracebacks for Pyro errors and shows deprecation warnings + (unless ``PYROLAB_HUSH_DEPRECATION`` is set). Never called on import: a + library must not change these for the application that imports it. + """ + import sys + + import Pyro5.errors + + sys.excepthook = Pyro5.errors.excepthook + action = "ignore" if HUSH_DEPRECATION_ENV_VAR in os.environ else "default" + warnings.filterwarnings(action, category=DeprecationWarning) + + +def configure_cli_logging() -> None: + """ + Logging for short-lived CLI commands: to stderr, and only if + ``PYROLAB_LOGLEVEL`` is set. They never write the daemon's log file. + """ + if LOGLEVEL_ENV_VAR in os.environ: + handler = logging.StreamHandler() + handler.setFormatter(logging.Formatter("%(levelname)s %(name)s: %(message)s")) + root = logging.getLogger() + root.addHandler(handler) + root.setLevel(log_level()) + + +def start_file_logging( + logfile: Path, max_bytes: int = LOG_MAX_BYTES, backups: int = LOG_BACKUPS +) -> logging.Handler: + """ + Make this process the writer of the log file (used by the daemon). + + Adds a rotating JSON-lines handler to the root logger, sends warnings to + the log, and records the start of a new run. Undo with + :py:func:`stop_file_logging`. + + Returns + ------- + logging.Handler + The handler that was added. + """ + logfile.parent.mkdir(parents=True, exist_ok=True) + handler = logging.handlers.RotatingFileHandler( + logfile, maxBytes=max_bytes, backupCount=backups, encoding="utf-8" + ) + handler.setFormatter(JsonLinesFormatter()) + root = logging.getLogger() + root.addHandler(handler) + root.setLevel(log_level()) + logging.captureWarnings(True) + # Written straight to the file, whatever the log level. + handler.handle( + logging.makeLogRecord( + { + "name": "pyrolab.pyrolabd", + "levelno": logging.INFO, + "levelname": "INFO", + "msg": f"PyroLab daemon starting (pid {os.getpid()})", + "event": DAEMON_START_EVENT, + } + ) + ) + return handler + + +def stop_file_logging(handler: logging.Handler) -> None: + """Undo :py:func:`start_file_logging`.""" + logging.captureWarnings(False) + logging.getLogger().removeHandler(handler) + handler.close() + + +############################################################################### +# Child processes +############################################################################### + + +class PipeHandler(logging.Handler): + """Sends records over a pipe to the process that writes the log.""" + + def __init__(self, conn) -> None: + super().__init__() + self.conn = conn + + def emit(self, record: logging.LogRecord) -> None: + try: + self.conn.send(self.prepare(record)) + except Exception: + self.handleError(record) + + @staticmethod + def prepare(record: logging.LogRecord) -> dict: + """A picklable copy of the record, with message and traceback as text.""" + data = dict(record.__dict__) + data["msg"] = record.getMessage() + data["args"] = None + if record.exc_info: + data["exc_text"] = logging.Formatter().formatException(record.exc_info) + data["exc_info"] = None + data.pop("message", None) + for key, value in list(data.items()): + if not isinstance(value, (str, int, float, bool, type(None))): + data[key] = repr(value) + return data + + +def log_to_pipe(conn) -> None: + """ + In a child process: send all logging to the parent over ``conn``. + + Replaces any handlers inherited from the parent (with the "fork" start + method a child inherits the parent's file handler, and must not write the + file itself). + """ + root = logging.getLogger() + root.handlers = [PipeHandler(conn)] + root.setLevel(log_level()) + logging.captureWarnings(True) + + +def collect_from_pipe( + conn, + name: str = "log-collector", + alive: Optional[Callable[[], bool]] = None, + poll_interval: float = 0.5, +) -> threading.Thread: + """ + In the parent: log every record a child sends over ``conn``. + + Runs in a daemon thread that ends when the pipe closes (the child exited, + or was killed, possibly mid-message), or, if ``alive`` is given, once the + child is dead and everything it sent has been read. The second matters on + Windows: a child that is killed while still starting never takes over its + end of the pipe from the parent, so the pipe never reports closed. + + Parameters + ---------- + conn : multiprocessing.connection.Connection + The receiving end of the child's log pipe. + name : str, optional + The thread's name. + alive : callable, optional + Returns whether the child is still running, e.g. ``process.is_alive``. + poll_interval : float, optional + How often to check ``alive`` while the pipe is idle, in seconds. + + Returns + ------- + threading.Thread + The started thread. + """ + + def collect() -> None: + while True: + try: + if alive is not None and not conn.poll(poll_interval): + if alive(): + continue + if not conn.poll(0): # dead, and nothing left to read + break + data = conn.recv() + except (EOFError, OSError): + break + except Exception: # a torn or unreadable message + logging.getLogger(__name__).warning( + "Unreadable log message from a child process; dropping its pipe", + exc_info=True, + ) + break + record = logging.makeLogRecord(data) + logging.getLogger(record.name).handle(record) + conn.close() + + thread = threading.Thread(target=collect, name=name, daemon=True) + thread.start() + return thread + + +############################################################################### +# Reading the log back +############################################################################### + + +def log_files(logfile: Path) -> List[Path]: + """The log file and its rotated backups, oldest first.""" + backups = sorted( + (p for p in logfile.parent.glob(logfile.name + ".*") if p.suffix[1:].isdigit()), + key=lambda p: int(p.suffix[1:]), + reverse=True, + ) + return backups + ([logfile] if logfile.exists() else []) + + +def read_entries(files: Iterable[Path]) -> Tuple[List[dict], int]: + """ + Read log entries from JSON-lines files. + + Returns + ------- + entries, skipped + Every readable entry, in file order, and the number of lines that + couldn't be read (e.g. from an older log format). + """ + entries, skipped = [], 0 + for path in files: + try: + lines = path.read_text(encoding="utf-8", errors="replace").splitlines() + except OSError: + continue + for line in lines: + if not line.strip(): + continue + try: + entry = json.loads(line) + except ValueError: + skipped += 1 + continue + if isinstance(entry, dict) and "time" in entry: + entries.append(entry) + else: + skipped += 1 + return entries, skipped + + +def since_last_start(entries: List[dict]) -> List[dict]: + """The entries from the daemon's most recent start onward.""" + for i in range(len(entries) - 1, -1, -1): + if entries[i].get("event") == DAEMON_START_EVENT: + return entries[i:] + return entries + + +def at_least(entries: Iterable[dict], level: int) -> Iterator[dict]: + """The entries at ``level`` or above.""" + for entry in entries: + entry_level = logging.getLevelName(entry.get("level", "")) + if isinstance(entry_level, int) and entry_level >= level: + yield entry + + +def find_level(name: str) -> Optional[int]: + """A level number from its name, or None if there is no such level.""" + level = logging.getLevelName(name.upper()) + return level if isinstance(level, int) else None diff --git a/pyrolab/manager.py b/pyrolab/manager.py index 2d617b3..b81d48a 100644 --- a/pyrolab/manager.py +++ b/pyrolab/manager.py @@ -57,7 +57,7 @@ from Pyro5.client import Proxy from Pyro5.core import NAMESERVER_NAME -from pyrolab import RUNTIME_CONFIG +from pyrolab import RUNTIME_CONFIG, logs from pyrolab.configure import GlobalConfiguration, PyroLabConfiguration from pyrolab.nameserver import start_ns_loop from pyrolab.utils import get_ip @@ -271,6 +271,9 @@ class NameServerRunner(multiprocessing.Process): A dict shared with the manager (``multiprocessing.Manager().dict()``). The runner sets ``ready`` once it is serving, and ``error`` if it fails. + log_conn : multiprocessing.connection.Connection, optional + The sending end of this runner's own log pipe; the runner's logging + goes there (see :py:mod:`pyrolab.logs`). """ def __init__( @@ -281,6 +284,7 @@ def __init__( msg_queue: Queue = None, msg_polling: float = 1.0, shared_state: Optional[dict] = None, + log_conn=None, **kwargs, ) -> None: super().__init__(*args, **kwargs) @@ -296,6 +300,7 @@ def __init__( self.msg_polling = msg_polling self.nsconfig = nsconfig self.state = shared_state if shared_state is not None else {} + self.log_conn = log_conn self.KILL_SIGNAL = False def process_message_queue(self) -> None: @@ -338,6 +343,8 @@ def run(self) -> None: Any error is reported to the manager through ``shared_state`` before the process exits. """ + if self.log_conn is not None: + logs.log_to_pipe(self.log_conn) log.info("Starting nameserver '%s'", self.name) try: self.nsconfig.update_pyro_config() @@ -386,6 +393,9 @@ class DaemonRunner(multiprocessing.Process): shared_state : dict, optional A dict shared with the manager. The runner sets ``ready`` once it is serving, and ``error`` if it fails. + log_conn : multiprocessing.connection.Connection, optional + The sending end of this runner's own log pipe; the runner's logging + goes there (see :py:mod:`pyrolab.logs`). """ def __init__( @@ -398,6 +408,7 @@ def __init__( shared_uris: dict[str, URI], msg_polling: float = 1.0, shared_state: Optional[dict] = None, + log_conn=None, **kwargs, ) -> None: log.debug("Building DaemonRunner") @@ -409,6 +420,7 @@ def __init__( self.daemonconfig = daemonconfig self.serviceconfigs = serviceconfigs self.state = shared_state if shared_state is not None else {} + self.log_conn = log_conn self.KILL_SIGNAL = False def setup_daemon(self) -> Tuple[Daemon, Dict[str, URI]]: @@ -511,6 +523,8 @@ def run(self) -> None: When the kill signal is received, removes its registrations and exits. Any error is reported to the manager through ``shared_state``. """ + if self.log_conn is not None: + logs.log_to_pipe(self.log_conn) log.info("Starting daemon '%s'", self.name) stop_registering = threading.Event() registrar = None @@ -689,13 +703,20 @@ def _shared_dict(self) -> dict: def _message_queue(self): return multiprocessing.Queue() - def _create_runner(self, kind: str, name: str, msg_queue, shared_state, uris): + def _log_pipe(self): + """(receiving end, sending end) of a new child's private log pipe.""" + return multiprocessing.Pipe(duplex=False) + + def _create_runner( + self, kind: str, name: str, msg_queue, shared_state, uris, log_conn=None + ): if kind == NAMESERVER: return NameServerRunner( name=name, nsconfig=self.GLOBAL_CONFIG.get_nameserver_config(name), msg_queue=msg_queue, shared_state=shared_state, + log_conn=log_conn, daemon=True, ) return DaemonRunner( @@ -705,6 +726,7 @@ def _create_runner(self, kind: str, name: str, msg_queue, shared_state, uris): msg_queue=msg_queue, shared_uris=uris, shared_state=shared_state, + log_conn=log_conn, daemon=True, ) @@ -722,11 +744,19 @@ def _spawn(self, kind: str, name: str) -> ProcessGroup: msg_queue = self._message_queue() shared_state = self._shared_dict() uris = self._shared_dict() if kind == DAEMON else None - runner = self._create_runner(kind, name, msg_queue, shared_state, uris) + log_recv, log_send = self._log_pipe() + runner = self._create_runner( + kind, name, msg_queue, shared_state, uris, log_conn=log_send + ) cls = NameServerProcessGroup if kind == NAMESERVER else DaemonProcessGroup group = cls(runner, msg_queue, datetime.now(), uris, shared_state) group.started = self._clock() runner.start() + if log_send is not None: + # The child has its own copy now; closing ours means the collector + # sees end-of-file as soon as the child exits or is killed. + log_send.close() + logs.collect_from_pipe(log_recv, name=f"log-{name}", alive=runner.is_alive) return group def _death_reason(self, group: ProcessGroup) -> str: diff --git a/pyrolab/nameserver.py b/pyrolab/nameserver.py index 7adf84d..e8f92c3 100644 --- a/pyrolab/nameserver.py +++ b/pyrolab/nameserver.py @@ -12,20 +12,17 @@ import logging import socket import sys +from pathlib import Path from typing import Callable, Optional from Pyro5.nameserver import BroadcastServer, NameServerDaemon from Pyro5.nameserver import start_ns as _pyro_start_ns -from pyrolab import NAMESERVER_STORAGE from pyrolab.configure import NameServerConfiguration log = logging.getLogger(__name__) -STORAGE_FILE = NAMESERVER_STORAGE / "storage" - - # # Inheriting from the Nameserver # class NameServer(Pyro5.nameserver.NameServer): # """ @@ -35,6 +32,14 @@ # pass +def _prepare_storage(storage: str) -> str: + """Create the directory a "sql:..."/"dbm:..." storage file goes in.""" + kind, _, path = storage.partition(":") + if kind in ("sql", "dbm") and path: + Path(path).parent.mkdir(parents=True, exist_ok=True) + return storage + + def start_ns_loop( cfg: NameServerConfiguration, loop_condition: Callable = lambda: True, @@ -69,6 +74,7 @@ def start_ns_loop( bchost = cfg.ns_bchost bcport = cfg.ns_bcport storage = cfg.get_storage_location() + _prepare_storage(storage) cfg.update_pyro_config() daemon = NameServerDaemon( @@ -150,5 +156,5 @@ def start_ns(cfg: NameServerConfiguration): enableBroadcast=cfg.broadcast, bchost=cfg.ns_bchost, bcport=cfg.ns_bcport, - storage=cfg.get_storage_location(), + storage=_prepare_storage(cfg.get_storage_location()), ) diff --git a/pyrolab/pyrolabd.py b/pyrolab/pyrolabd.py index f266ae9..d725661 100644 --- a/pyrolab/pyrolabd.py +++ b/pyrolab/pyrolabd.py @@ -20,8 +20,19 @@ from pydantic import BaseModel from tabulate import tabulate -from pyrolab import LOCKFILE, RUNTIME_CONFIG, STARTUP_ERROR_FILE, USER_CONFIG_FILE +from pyrolab import ( + LEGACY_DATA_DIR, + LEGACY_MIGRATION_MARKER, + LOCKFILE, + NAMESERVER_STORAGE, + PYROLAB_LOGFILE, + RUNTIME_CONFIG, + STARTUP_ERROR_FILE, + USER_CONFIG_FILE, + logs, +) from pyrolab.configure import GlobalConfiguration, describe_config_error +from pyrolab.locations import migrate_legacy_files from pyrolab.manager import ProcessManager from pyrolab.utils import atomic_write_text, pid_is_running @@ -358,7 +369,7 @@ def _report_startup_error(message: str) -> None: """Log why the daemon could not start, and leave the reason for `up`.""" log.error("PyroLab daemon failed to start: %s", message) try: - STARTUP_ERROR_FILE.write_text(message) + atomic_write_text(STARTUP_ERROR_FILE, message) except OSError: log.exception("Could not write %s", STARTUP_ERROR_FILE) @@ -382,11 +393,28 @@ def main(port: int = 0) -> int: """ existing = read_lockfile() if existing is not None and pid_is_running(existing.pid): + # Checked before opening the log: a second daemon must never become a + # second writer of the log file. _report_startup_error( f"another PyroLab daemon is already running (pid {existing.pid})" ) return 1 + handler = logs.start_file_logging(PYROLAB_LOGFILE) + try: + for copied in migrate_legacy_files( + LEGACY_DATA_DIR, + USER_CONFIG_FILE, + NAMESERVER_STORAGE, + LEGACY_MIGRATION_MARKER, + ): + log.info("Copied from a pre-0.5 install: %s", copied) + return _serve(port) + finally: + logs.stop_file_logging(handler) + + +def _serve(port: int) -> int: daemon = None published = False try: @@ -428,4 +456,5 @@ def main(port: int = 0) -> int: if __name__ == "__main__": + logs.configure_process() sys.exit(main(int(sys.argv[1]) if len(sys.argv) > 1 else 0)) diff --git a/pyrolab/updates.py b/pyrolab/updates.py index 04c8c73..d1af717 100644 --- a/pyrolab/updates.py +++ b/pyrolab/updates.py @@ -25,6 +25,8 @@ import requests from packaging.version import InvalidVersion, Version +from pyrolab.utils import atomic_write_text + log = logging.getLogger(__name__) PYPI_URL = "https://pypi.org/pypi/pyrolab/json" @@ -93,7 +95,7 @@ def check_for_update( # Record the attempt even when it failed, so an offline machine doesn't # retry (and wait for the timeout) on every command. try: - cache_file.write_text(json.dumps({"checked": now, "latest": latest})) + atomic_write_text(cache_file, json.dumps({"checked": now, "latest": latest})) except OSError as e: log.debug("Could not write version check cache %s: %s", cache_file, e) diff --git a/pyrolab/utils.py b/pyrolab/utils.py index dc675ec..2f414ee 100644 --- a/pyrolab/utils.py +++ b/pyrolab/utils.py @@ -9,6 +9,7 @@ Convenience functions for working with the pyrolab package. """ +import logging import os import secrets import socket @@ -21,21 +22,56 @@ import pyrolab +log = logging.getLogger(__name__) + def get_ip() -> str: """ - Get the IP address of the local machine. + This machine's best-guess address for other machines to reach it. + + Used for ``host: public``: daemons and nameservers listen on this address, + and it goes into the URIs they publish, so it must be one the *clients* can + reach. The guess is the address of the interface that would route to the + internet (no traffic is sent). On a machine with several networks that may + not be the clients' network; set ``host`` to the right address instead. + + Falls back, with a warning, to the address this machine's hostname resolves + to, then to 127.0.0.1, rather than failing on a network with no route + outside. Returns ------- str - The IP address of the local machine. + An IPv4 address. """ - s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) - s.connect(("8.8.8.8", 80)) - ip = s.getsockname()[0] - s.close() - return ip + try: + with socket.socket(socket.AF_INET, socket.SOCK_DGRAM) as s: + s.connect(("8.8.8.8", 80)) # UDP: picks a route, sends nothing + return s.getsockname()[0] + except OSError as e: + reason = e + + try: + ip = socket.gethostbyname(socket.gethostname()) + except OSError: + ip = None + if ip and not ip.startswith("127."): + log.warning( + "No route to the internet to find this machine's address (%s); using " + "%s, which its hostname resolves to. If clients can't connect, set " + "'host' to the address they should use instead of 'public'.", + reason, + ip, + ) + return ip + + log.warning( + "Could not find this machine's network address (%s); using 127.0.0.1, " + "which only clients on this machine can reach. Set 'host' to the " + "address clients should use instead of 'public'.", + reason, + ) + return "127.0.0.1" def generate_random_name(count: int = 3) -> str: @@ -140,6 +176,7 @@ def atomic_write_text(path, text: str) -> None: from pathlib import Path path = Path(path) + path.parent.mkdir(parents=True, exist_ok=True) tmp = path.with_name(f"{path.name}.{os.getpid()}.tmp") try: with open(tmp, "w") as f: diff --git a/tests/conftest.py b/tests/conftest.py index 99a9800..37a4213 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -71,25 +71,30 @@ def no_version_check(monkeypatch): monkeypatch.setenv("PYROLAB_NO_VERSION_CHECK", "1") -@pytest.fixture +@pytest.fixture(autouse=True) def data_dir(tmp_path, monkeypatch): """ - Redirect PyroLab's runtime files (configs, lockfile, logs) into a temp dir. + Redirect PyroLab's files (configs, lockfile, logs, ...) into a temp dir. - Returns a namespace with the redirected paths. None of the files exist - until a test creates them. + Autouse, so no test can touch the real per-user directories (or copy files + from a developer's real pre-0.5 install). Returns a namespace with the + redirected paths; only the log and nameserver directories exist up front. """ + root = tmp_path / "pyrolab-data" paths = SimpleNamespace( - root=tmp_path, - USER_CONFIG_FILE=tmp_path / "user_configuration.yaml", - RUNTIME_CONFIG=tmp_path / "runtime_config.yaml", - LOCKFILE=tmp_path / "pyrolabd.lock", - UPDATE_CHECK_FILE=tmp_path / "update_check.json", - STARTUP_ERROR_FILE=tmp_path / "pyrolabd_startup_error.txt", - PYROLAB_LOGDIR=tmp_path / "logs", - NAMESERVER_STORAGE=tmp_path / "nameserver", + root=root, + USER_CONFIG_FILE=root / "user_configuration.yaml", + RUNTIME_CONFIG=root / "runtime_config.yaml", + LOCKFILE=root / "pyrolabd.lock", + UPDATE_CHECK_FILE=root / "update_check.json", + STARTUP_ERROR_FILE=root / "pyrolabd_startup_error.txt", + PYROLAB_LOGDIR=root / "logs", + PYROLAB_LOGFILE=root / "logs" / "pyrolab.log", + NAMESERVER_STORAGE=root / "nameserver", + LEGACY_DATA_DIR=root / "legacy", # absent unless a test creates it + LEGACY_MIGRATION_MARKER=root / "legacy_files_copied.txt", ) - paths.PYROLAB_LOGDIR.mkdir() + paths.PYROLAB_LOGDIR.mkdir(parents=True) paths.NAMESERVER_STORAGE.mkdir() import importlib diff --git a/tests/test_cli.py b/tests/test_cli.py index 0dcce8c..4d49797 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -1,3 +1,4 @@ +import json import os import subprocess import sys @@ -503,48 +504,198 @@ def test_rename_without_config(data_dir): ############################################################################### -def test_logs_export_merges_and_sorts(data_dir, tmp_path): - def write_log(name, *lines): - (data_dir.PYROLAB_LOGDIR / name).write_text("".join(f"{x}\n" for x in lines)) +def write_log(data_dir, *entries, start_marker=True): + """Write JSON-lines log entries as the daemon would.""" + lines = [] + if start_marker: + lines.append( + { + "time": "2026-10-05T09:00:00.000", + "level": "INFO", + "process": "MainProcess", + "pid": 1, + "logger": "pyrolab.pyrolabd", + "message": "PyroLab daemon starting (pid 1)", + "event": "daemon-start", + } + ) + for i, (level, message) in enumerate(entries): + lines.append( + { + "time": f"2026-10-05T10:00:{i:02d}.000", + "level": level, + "process": "lab", + "pid": 2, + "logger": "pyrolab.manager", + "message": message, + } + ) + with data_dir.PYROLAB_LOGFILE.open("a") as f: + for line in lines: + f.write(json.dumps(line) + "\n") + + +def test_logs_show_since_last_start(data_dir): + write_log(data_dir, ("ERROR", "from an earlier run")) + write_log(data_dir, ("INFO", "fine"), ("WARNING", "hmm")) + result = runner.invoke(cli.app, ["logs", "show"]) + assert result.exit_code == 0, result.output + assert "hmm" in result.output and "fine" in result.output + assert "earlier run" not in result.output - write_log( - "pyrolab_1.log", - "[2026-01-01 10:00:00.000] INFO first", - "[2026-01-01 10:00:02.000] ERROR third", - "Traceback (most recent call last):", - " boom", - ) - write_log( - "pyrolab_2.log", - "[2026-01-01 10:00:01.000] INFO second", - "[2026-01-01 10:00:03.000] INFO fourth", - ) - # Raw daemon output (tracebacks, no timestamps) is not merged. - (data_dir.PYROLAB_LOGDIR / cli.DAEMON_OUTPUT_LOG).write_text( - "Traceback (most recent call last):\nRuntimeError: boom\n" - ) - out = tmp_path / "merged.log" + result = runner.invoke(cli.app, ["logs", "show", "--all", "--level", "error"]) + assert "earlier run" in result.output + assert "hmm" not in result.output + + +def test_logs_show_limits_lines(data_dir): + write_log(data_dir, *[("INFO", f"message {i}") for i in range(10)]) + result = runner.invoke(cli.app, ["logs", "show", "-n", "3"]) + assert "message 9" in result.output + assert "message 6" not in result.output + + +def test_logs_show_rejects_unknown_level(data_dir): + result = runner.invoke(cli.app, ["logs", "show", "--level", "loud"]) + assert result.exit_code == 2 + assert "unknown level 'loud'" in result.output + + +def test_logs_export_text_and_json(data_dir, tmp_path): + # Regression: export crashed on entries without a parseable timestamp, + # which a rotated plain-text log routinely had (#71, #36). + write_log(data_dir, ("INFO", "first"), ("ERROR", "second")) + with data_dir.PYROLAB_LOGFILE.open("a") as f: + f.write("Traceback (most recent call last):\n[not json]\n") + out = tmp_path / "export.txt" result = runner.invoke(cli.app, ["logs", "export", str(out)]) assert result.exit_code == 0, result.output - assert out.read_text().splitlines() == [ - "[2026-01-01 10:00:00.000] INFO first", - "[2026-01-01 10:00:01.000] INFO second", - "[2026-01-01 10:00:02.000] ERROR third", - "Traceback (most recent call last):", - " boom", - "[2026-01-01 10:00:03.000] INFO fourth", - ] + assert "Exported 3 log entries" in result.output + assert "Skipped 2 unreadable lines" in result.output + text = out.read_text().splitlines() + assert text[1].endswith("lab (2) pyrolab.manager: first") + assert "ERROR" in text[2] and text[2].endswith("second") + + result = runner.invoke(cli.app, ["logs", "export", str(out), "--json"]) + assert [json.loads(line)["message"] for line in out.read_text().splitlines()][ + 1: + ] == ["first", "second"] + + +def test_logs_export_includes_rotated_files_oldest_first(data_dir, tmp_path): + log = data_dir.PYROLAB_LOGFILE + for suffix, message in ((".2", "oldest"), (".1", "older")): + log.with_name(log.name + suffix).write_text( + json.dumps({"time": "t", "message": message}) + "\n" + ) + write_log(data_dir, ("INFO", "newest"), start_marker=False) + out = tmp_path / "export.json" + runner.invoke(cli.app, ["logs", "export", str(out), "--json"]) + messages = [json.loads(line)["message"] for line in out.read_text().splitlines()] + assert messages == ["oldest", "older", "newest"] def test_logs_clean(data_dir): - for i in range(3): - (data_dir.PYROLAB_LOGDIR / f"pyrolab_{i}.log").write_text("x\n") + write_log(data_dir, ("INFO", "x")) + log = data_dir.PYROLAB_LOGFILE + log.with_name(log.name + ".1").write_text("old\n") + (data_dir.PYROLAB_LOGDIR / cli.DAEMON_OUTPUT_LOG).write_text("raw\n") result = runner.invoke(cli.app, ["logs", "clean"]) assert result.exit_code == 0 + assert "Removed 3 log files" in result.output assert list(data_dir.PYROLAB_LOGDIR.iterdir()) == [] +def test_logs_clean_refuses_while_daemon_runs(running_daemon, data_dir): + write_log(data_dir, ("INFO", "x")) + result = runner.invoke(cli.app, ["logs", "clean"]) + assert result.exit_code == 1 + assert "pyrolab down" in result.output + assert data_dir.PYROLAB_LOGFILE.exists() + + +############################################################################### +# pyrolab status (#36) +############################################################################### + + +def test_status_when_not_running(data_dir): + result = runner.invoke(cli.app, ["status"]) + assert result.exit_code == 0 + assert "PyroLab daemon is not running." in result.output + assert "Nothing has been logged yet" in result.output + + +def test_status_shows_problems_since_start(running_daemon, data_dir, monkeypatch): + monkeypatch.setattr(cli, "_daemon_responds", lambda uri: True) + write_log(data_dir, ("ERROR", "from an earlier run")) + write_log(data_dir, ("INFO", "fine"), ("WARNING", "hmm"), ("ERROR", "bad")) + result = runner.invoke(cli.app, ["status"]) + assert result.exit_code == 0, result.output + assert f"PyroLab daemon is running (pid {os.getpid()}" in result.output + assert "2 warnings and errors since it started:" in result.output + assert "hmm" in result.output and "bad" in result.output + assert "fine" not in result.output and "earlier run" not in result.output + + +def test_status_summarizes_tracebacks(data_dir): + with data_dir.PYROLAB_LOGFILE.open("a") as f: + f.write( + json.dumps( + { + "time": "2026-10-05T10:00:00.000", + "level": "ERROR", + "message": "Daemon 'lab' failed", + "exception": "Traceback (most recent call last):\nRuntimeError: x", + } + ) + + "\n" + ) + result = runner.invoke(cli.app, ["status"]) + assert "Daemon 'lab' failed [traceback]" in result.output + assert "Traceback (most recent call last)" not in result.output + assert "pyrolab logs show --level warning" in result.output + + +def test_status_after_daemon_stopped(data_dir): + write_log(data_dir, ("WARNING", "on the way down")) + result = runner.invoke(cli.app, ["status"]) + assert "during its last run" in result.output + + +def test_status_without_problems(data_dir): + write_log(data_dir, ("INFO", "fine")) + result = runner.invoke(cli.app, ["status"]) + assert "No warnings or errors during its last run." in result.output + + +############################################################################### +# Locations and migration (#66) +############################################################################### + + +def test_data_option_lists_locations(data_dir): + result = runner.invoke(cli.app, ["--data"]) + assert result.exit_code == 0 + assert str(data_dir.USER_CONFIG_FILE) in result.output + assert str(data_dir.PYROLAB_LOGFILE) in result.output + assert "PYROLAB_DATA_DIR" in result.output + + +def test_first_command_copies_legacy_config(data_dir): + legacy = data_dir.LEGACY_DATA_DIR + legacy.mkdir() + (legacy / "user_configuration.yaml").write_text("daemons: {old: {}}\n") + + result = runner.invoke(cli.app, ["info"]) + assert "outside the installed package" in result.stderr + assert data_dir.USER_CONFIG_FILE.read_text() == "daemons: {old: {}}\n" + + result = runner.invoke(cli.app, ["info"]) + assert "outside the installed package" not in result.stderr # only once + + ############################################################################### # pyrolab up ############################################################################### diff --git a/tests/test_lifecycle.py b/tests/test_lifecycle.py index 395aca8..0ccbe24 100644 --- a/tests/test_lifecycle.py +++ b/tests/test_lifecycle.py @@ -122,12 +122,13 @@ def pm(global_config, sample_config_file, removed): pm._clock = pm.clock pm._shared_dict = dict pm._message_queue = queue.Queue + pm._log_pipe = lambda: (None, None) # fake runners don't log over pipes pm.start_checkup_timer = lambda *args, **kwargs: None pm.stop_checkup_timer = lambda: None pm.behavior = {} pm.spawned = {} - def create_runner(kind, name, msg_queue, shared_state, uris): + def create_runner(kind, name, msg_queue, shared_state, uris, log_conn=None): process = FakeProcess(msg_queue, shared_state, **pm.behavior.get(name, {})) process.name = name if kind == mgr.DAEMON: @@ -196,7 +197,7 @@ def test_launch_when_already_running_does_not_spawn_twice(pm): def test_launch_spawn_error_is_reported(pm, monkeypatch): - def broken(*args): + def broken(*args, **kwargs): raise OSError("too many open files") pm._create_runner = broken @@ -366,7 +367,7 @@ def test_restart_that_cannot_spawn_counts_as_a_crash(pm): current(pm, "plain").crash() pm.checkup(continuous=False) - def broken(*args): + def broken(*args, **kwargs): raise OSError("no more processes") pm._create_runner = broken @@ -480,3 +481,48 @@ def test_service_info_before_uri_is_published(pm): def test_service_info_for_unknown_service(pm): assert pm.get_service_process_info("svc") == {"daemon": "", "uri": ""} + + +############################################################################### +# Child logging reaches the daemon (#25) +############################################################################### + + +def test_child_logs_reach_the_daemon_through_their_own_pipe(pm, caplog, wait_for): + import logging + import multiprocessing + + from pyrolab import logs + + pm._log_pipe = lambda: multiprocessing.Pipe(duplex=False) + sent = {} + + def create_runner(kind, name, msg_queue, shared_state, uris, log_conn=None): + process = FakeProcess(msg_queue, shared_state) + process.name = name + process.daemonconfig = pm.GLOBAL_CONFIG.get_daemon_config(name) + process.serviceconfigs = {} + original_start = process.start + + def start(): + original_start() + # What a runner does first in its own process; sent before + # _spawn closes the manager's copy of the sending end. + handler = logs.PipeHandler(log_conn) + record = logging.LogRecord( + "pyrolab.child", logging.WARNING, __file__, 1, "from %s", (name,), None + ) + record.processName = name + handler.handle(record) + sent[name] = log_conn + + process.start = start + return process + + pm._create_runner = create_runner + with caplog.at_level(logging.WARNING, logger="pyrolab.child"): + pm.launch_daemon("plain", wait=True) + sent["plain"].close() # the "child" exits + assert wait_for(lambda: "from plain" in caplog.text) + record = next(r for r in caplog.records if r.getMessage() == "from plain") + assert record.processName == "plain" diff --git a/tests/test_locations.py b/tests/test_locations.py new file mode 100644 index 0000000..8e03f02 --- /dev/null +++ b/tests/test_locations.py @@ -0,0 +1,131 @@ +""" +Where PyroLab keeps its files (#66), and what importing it changes (#63). +""" + +import os +import subprocess +import sys +import textwrap + +from pyrolab import locations + +############################################################################### +# Layout +############################################################################### + + +def test_default_locations_are_per_user_and_named_once(): + locs = locations.locations({}) + for path in locs: + assert "pyrolab" in path.parts + assert path.parts.count("pyrolab") == 1 # no "pyrolab/pyrolab" + # Not inside the installed package any more. + package = locations.LEGACY_DATA_DIR.parent.parent + assert all(package not in path.parents for path in locs) + + +def test_data_dir_override_puts_everything_in_one_place(tmp_path): + locs = locations.locations({"PYROLAB_DATA_DIR": str(tmp_path)}) + assert locs.config_dir == locs.state_dir == locs.data_dir == tmp_path + assert locs.cache_dir == tmp_path + assert locs.log_dir == tmp_path / "logs" + + +############################################################################### +# Migration from a pre-0.5 install +############################################################################### + + +def legacy_install(root): + legacy = root / "legacy" + (legacy / "nameserver").mkdir(parents=True) + (legacy / "user_configuration.yaml").write_text("daemons: {old: {}}\n") + (legacy / "nameserver" / "ns_prod.sql").write_text("db") + (legacy / "runtime_config.yaml").write_text("not copied") + (legacy / "logs").mkdir() + return legacy + + +def migrate(root, legacy): + return locations.migrate_legacy_files( + legacy, + root / "config" / "user_configuration.yaml", + root / "data" / "nameserver", + root / "state" / "marker.txt", + ) + + +def test_migration_copies_config_and_nameserver_data(tmp_path): + legacy = legacy_install(tmp_path) + copied = migrate(tmp_path, legacy) + assert len(copied) == 2 + assert (tmp_path / "config" / "user_configuration.yaml").read_text() == ( + "daemons: {old: {}}\n" + ) + assert (tmp_path / "data" / "nameserver" / "ns_prod.sql").read_text() == "db" + assert (legacy / "user_configuration.yaml").exists() # originals untouched + + +def test_migration_never_overwrites(tmp_path): + legacy = legacy_install(tmp_path) + new_config = tmp_path / "config" / "user_configuration.yaml" + new_config.parent.mkdir() + new_config.write_text("daemons: {new: {}}\n") + migrate(tmp_path, legacy) + assert new_config.read_text() == "daemons: {new: {}}\n" + + +def test_migration_runs_once(tmp_path): + legacy = legacy_install(tmp_path) + migrate(tmp_path, legacy) + (tmp_path / "config" / "user_configuration.yaml").unlink() # `config reset` + assert migrate(tmp_path, legacy) == [] + assert not (tmp_path / "config" / "user_configuration.yaml").exists() + + +def test_migration_without_legacy_install(tmp_path): + assert migrate(tmp_path, tmp_path / "missing") == [] + assert not (tmp_path / "state").exists() # no marker, nothing created + + +############################################################################### +# Importing pyrolab changes nothing global (#63) and creates nothing (#66) +############################################################################### + + +def test_import_has_no_side_effects(tmp_path): + # Fresh interpreter, since this one has long since imported pyrolab. + data_dir = tmp_path / "fresh-install" # not the autouse fixture's dir + code = textwrap.dedent( + """ + import logging, sys, warnings + filters = list(warnings.filters) + import pyrolab, pyrolab.api, pyrolab.configure, pyrolab.manager + import pyrolab.pyrolabd, pyrolab.server + library_filters = list(warnings.filters) + # The CLI is the `pyrolab` program rather than the library, and it + # imports requests, whose urllib3 adds warning filters of its own. + import pyrolab.cli + + problems = [] + if logging.getLogger().handlers: + problems.append(f"root handlers: {logging.getLogger().handlers}") + if sys.excepthook is not sys.__excepthook__: + problems.append("sys.excepthook replaced") + if library_filters != filters: + problems.append("warning filters changed") + handlers = logging.getLogger("pyrolab").handlers + if [type(h).__name__ for h in handlers] != ["NullHandler"]: + problems.append(f"pyrolab logger handlers: {handlers}") + sys.exit("; ".join(problems) or 0) + """ + ) + env = dict(os.environ, PYROLAB_DATA_DIR=str(data_dir)) + env.pop("PYROLAB_LOGFILE", None) + result = subprocess.run( + [sys.executable, "-c", code], env=env, capture_output=True, text=True + ) + assert result.returncode == 0, result.stderr + # Regression: importing created the data and log directories, and a log + # file for every process (#64, #66). + assert not data_dir.exists() diff --git a/tests/test_logs.py b/tests/test_logs.py new file mode 100644 index 0000000..359b0f9 --- /dev/null +++ b/tests/test_logs.py @@ -0,0 +1,333 @@ +""" +The single log file (#25, #64) and reading it back (#71, #36). + +The child-process tests start real processes, since the point is how logging +behaves across them; each is bounded by timeouts. +""" + +import json +import logging +import multiprocessing as mp +import pickle +import time + +import pytest + +from pyrolab import logs + +############################################################################### +# Format and reading +############################################################################### + + +def make_record(msg="hello %s", args=("world",), level=logging.INFO, **extra): + record = logging.LogRecord("pyrolab.test", level, __file__, 1, msg, args, None) + record.__dict__.update(extra) + return record + + +def test_json_lines_formatter(): + record = make_record(event="daemon-start") + entry = json.loads(logs.JsonLinesFormatter().format(record)) + assert entry["message"] == "hello world" + assert entry["level"] == "INFO" + assert entry["logger"] == "pyrolab.test" + assert entry["event"] == "daemon-start" + assert {"time", "process", "pid"} <= set(entry) + + +def test_json_lines_formatter_includes_traceback(): + try: + 1 / 0 + except ZeroDivisionError: + record = make_record() + record.exc_info = __import__("sys").exc_info() + entry = json.loads(logs.JsonLinesFormatter().format(record)) + assert "ZeroDivisionError" in entry["exception"] + assert "\n" not in logs.JsonLinesFormatter().format(record) # one line + + +def test_format_entry_indents_traceback(): + text = logs.format_entry( + { + "time": "2026-10-05T10:00:00.000", + "level": "ERROR", + "process": "lab", + "pid": 7, + "logger": "pyrolab.manager", + "message": "boom", + "exception": "Traceback:\n line\nValueError", + } + ) + assert text.splitlines() == [ + "2026-10-05 10:00:00.000 ERROR lab (7) pyrolab.manager: boom", + " Traceback:", + " line", + " ValueError", + ] + + +def test_read_entries_skips_unreadable_lines(tmp_path): + # Regression: one malformed entry crashed `logs export` (#71). + path = tmp_path / "pyrolab.log" + path.write_text( + '{"time": "t1", "message": "a"}\n' + "[2026-01-01 10:00:00.000] INFO old plain-text format\n" + "Traceback (most recent call last):\n" + "\n" + '{"no": "time"}\n' + '{"time": "t2", "message": "b"}\n' + ) + entries, skipped = logs.read_entries([path]) + assert [e["message"] for e in entries] == ["a", "b"] + assert skipped == 3 + + +def test_since_last_start_and_levels(): + entries = [ + {"time": "1", "level": "ERROR", "message": "old run"}, + {"time": "2", "level": "INFO", "event": logs.DAEMON_START_EVENT}, + {"time": "3", "level": "INFO", "message": "fine"}, + {"time": "4", "level": "WARNING", "message": "hmm"}, + ] + recent = logs.since_last_start(entries) + assert [e["time"] for e in recent] == ["2", "3", "4"] + assert [e["time"] for e in logs.at_least(recent, logging.WARNING)] == ["4"] + # No start marker (e.g. rotated away): everything counts. + assert logs.since_last_start(entries[2:]) == entries[2:] + + +############################################################################### +# The daemon's log file +############################################################################### + + +@pytest.fixture +def file_logging(tmp_path): + """Make this process the log writer (as the daemon is), then undo it.""" + logfile = tmp_path / "logs" / "pyrolab.log" + handlers = [] + + def start(**kwargs): + handlers.append(logs.start_file_logging(logfile, **kwargs)) + return logfile + + yield start + for handler in handlers: + logs.stop_file_logging(handler) + + +def test_file_logging_writes_json_lines_with_start_marker(file_logging): + logfile = file_logging() + logging.getLogger("pyrolab.test").warning("careful") + entries, skipped = logs.read_entries(logs.log_files(logfile)) + assert skipped == 0 + assert entries[0]["event"] == logs.DAEMON_START_EVENT + assert entries[-1]["message"] == "careful" + + +def test_stop_file_logging_removes_handler(tmp_path): + before = list(logging.getLogger().handlers) + handler = logs.start_file_logging(tmp_path / "pyrolab.log") + logs.stop_file_logging(handler) + assert logging.getLogger().handlers == before + + +def test_rotation_keeps_entries_in_order(file_logging): + # Regression: per-PID files with 30 KB rotation threw history away (#64). + logfile = file_logging(max_bytes=2000, backups=50) + log = logging.getLogger("pyrolab.test") + for i in range(200): + log.warning("message %03d", i) + files = logs.log_files(logfile) + assert len(files) > 3 + assert files[-1] == logfile # oldest first, current last + entries, _ = logs.read_entries(files) + numbered = [e["message"] for e in entries if e["message"].startswith("message")] + assert numbered == [f"message {i:03d}" for i in range(200)] + + +############################################################################### +# Child processes +############################################################################### + + +def test_log_to_pipe_replaces_inherited_handlers(): + # With "fork", a child inherits the daemon's file handler and must not + # write the file itself. + root = logging.getLogger() + saved = list(root.handlers), root.level + a, b = mp.Pipe(duplex=False) + try: + root.addHandler(logging.NullHandler()) + logs.log_to_pipe(b) + assert [type(h) for h in root.handlers] == [logs.PipeHandler] + finally: + root.handlers[:] = saved[0] + root.setLevel(saved[1]) + logging.captureWarnings(False) + a.close() + b.close() + + +def test_prepared_records_are_picklable(): + try: + raise ValueError("bad") + except ValueError: + record = make_record(unpicklable=lambda: None) + record.exc_info = __import__("sys").exc_info() + data = logs.PipeHandler.prepare(record) + restored = logging.makeLogRecord(pickle.loads(pickle.dumps(data))) + assert restored.getMessage() == "hello world" + assert "ValueError: bad" in restored.exc_text + + +def _child_logs(conn, count): + logs.log_to_pipe(conn) + log = logging.getLogger("pyrolab.child") + for i in range(count): + log.info("child message %d", i) + try: + 1 / 0 + except ZeroDivisionError: + log.exception("child failed") + + +def _child_spams(conn): + logs.log_to_pipe(conn) + while True: + logging.getLogger("pyrolab.child").info("x" * 2000) + + +def _start_child(target, *args, name): + recv, send = mp.Pipe(duplex=False) + proc = mp.Process(target=target, args=(send, *args), name=name, daemon=True) + proc.start() + send.close() + collector = logs.collect_from_pipe( + recv, name=f"log-{name}", alive=proc.is_alive, poll_interval=0.1 + ) + return proc, collector + + +@pytest.fixture(params=["spawn", "fork"]) +def start_method(request): + if request.param not in mp.get_all_start_methods(): + pytest.skip(f"no {request.param} start method on this platform") + return mp.get_context(request.param) + + +def test_children_log_to_one_file_through_their_pipes( + file_logging, start_method, monkeypatch +): + # Regression: every process wrote its own file, uncoordinated (#25, #64). + monkeypatch.setattr(mp, "Process", start_method.Process) + monkeypatch.setattr(mp, "Pipe", start_method.Pipe) + logfile = file_logging() + children = [_start_child(_child_logs, 100, name=f"lab-{i}") for i in range(2)] + for proc, collector in children: + proc.join(30) + collector.join(10) + assert proc.exitcode == 0 + assert not collector.is_alive() + + entries, skipped = logs.read_entries(logs.log_files(logfile)) + assert skipped == 0 + for i in range(2): + mine = [e for e in entries if e["process"] == f"lab-{i}"] + assert len(mine) == 101 + assert "ZeroDivisionError" in mine[-1]["exception"] + + +def test_killed_child_cannot_block_logging(file_logging, start_method, monkeypatch): + # The reason for a pipe per child rather than one shared queue: a child + # killed mid-write (as stopping does with hung processes) must not leave a + # lock held that blocks every other process's logging. + monkeypatch.setattr(mp, "Process", start_method.Process) + monkeypatch.setattr(mp, "Pipe", start_method.Pipe) + logfile = file_logging() + for _ in range(3): + victims = [_start_child(_child_spams, name="victim") for _ in range(3)] + time.sleep(0.3) + for proc, collector in victims: + proc.kill() + proc.join(10) + collector.join(10) + assert not collector.is_alive() + + survivor, collector = _start_child(_child_logs, 20, name="survivor") + survivor.join(30) + collector.join(10) + assert survivor.exitcode == 0 + logging.getLogger("pyrolab.test").warning("parent still logging") + + entries, _ = logs.read_entries(logs.log_files(logfile)) + assert len([e for e in entries if e["process"] == "survivor"]) == 21 + assert entries[-1]["message"] == "parent still logging" + + +def _never_starts_logging(conn): + time.sleep(60) # e.g. killed before it gets going + + +def test_collector_ends_when_child_dies_without_closing_pipe(): + # On Windows a child killed while still starting never takes its end of + # the pipe over from the parent, so the pipe never reports closed; the + # collector must notice the child died instead of waiting forever. + recv, send = mp.Pipe(duplex=False) + state = {"alive": True} + collector = logs.collect_from_pipe( + recv, alive=lambda: state["alive"], poll_interval=0.05 + ) + send.send(logs.PipeHandler.prepare(make_record("last words", ()))) + state["alive"] = False # dies, but `send` (the stranded end) stays open + collector.join(5) + assert not collector.is_alive() + send.close() + + +def test_collector_reads_everything_before_stopping(caplog): + # The collector runs while the records are sent (a pipe's buffer can be + # small -- on Windows, sending 50 records with no reader blocks), then the + # child "dies": everything still in the pipe must be read first. + recv, send = mp.Pipe(duplex=False) + state = {"alive": True} + with caplog.at_level(logging.INFO, logger="pyrolab.test"): + collector = logs.collect_from_pipe( + recv, alive=lambda: state["alive"], poll_interval=0.05 + ) + for i in range(50): + send.send(logs.PipeHandler.prepare(make_record("record %d", (i,)))) + state["alive"] = False + collector.join(5) + assert not collector.is_alive() + assert [r.getMessage() for r in caplog.records][-1] == "record 49" + send.close() + + +############################################################################### +# Process setup +############################################################################### + + +def test_cli_logging_only_when_requested(monkeypatch): + root = logging.getLogger() + saved = list(root.handlers), root.level + try: + monkeypatch.delenv(logs.LOGLEVEL_ENV_VAR, raising=False) + logs.configure_cli_logging() + assert root.handlers == saved[0] + + monkeypatch.setenv(logs.LOGLEVEL_ENV_VAR, "debug") + logs.configure_cli_logging() + assert isinstance(root.handlers[-1], logging.StreamHandler) + assert root.level == logging.DEBUG + finally: + root.handlers[:] = saved[0] + root.setLevel(saved[1]) + + +@pytest.mark.parametrize("value, level", [("WARNING", 30), ("debug", 10), ("nope", 20)]) +def test_log_level_from_environment(monkeypatch, value, level): + monkeypatch.setenv(logs.LOGLEVEL_ENV_VAR, value) + assert logs.log_level() == level diff --git a/tests/test_pyrolabd.py b/tests/test_pyrolabd.py index e463ef0..25881ca 100644 --- a/tests/test_pyrolabd.py +++ b/tests/test_pyrolabd.py @@ -298,3 +298,50 @@ def test_main_refuses_to_start_twice(run_main, data_dir): assert result["code"] == 1 assert "already running" in data_dir.STARTUP_ERROR_FILE.read_text() assert read_lockfile() == other # the running daemon's lockfile is untouched + + +############################################################################### +# The daemon owns the log (#25, #64) +############################################################################### + + +def test_main_writes_the_log_and_cleans_up( + run_main, data_dir, sample_config_file, wait_for +): + import logging + + from pyrolab import logs + + handlers_before = list(logging.getLogger().handlers) + data_dir.USER_CONFIG_FILE.write_text(sample_config_file.read_text()) + thread, result = run_main() + info = wait_for(read_lockfile) + with Proxy(info.uri) as proxy: + proxy.shutdown() + thread.join(timeout=10) + + entries, skipped = logs.read_entries(logs.log_files(data_dir.PYROLAB_LOGFILE)) + assert skipped == 0 + assert entries[0]["event"] == logs.DAEMON_START_EVENT + assert any("listening at" in e["message"] for e in entries) + assert logging.getLogger().handlers == handlers_before # handler removed + + +def test_refused_daemon_does_not_touch_the_log(run_main, data_dir): + write_lockfile(InstanceInfo(pid=os.getpid(), uri="PYRO:pyrolabd@localhost:1")) + thread, result = run_main() + thread.join(timeout=10) + assert result["code"] == 1 + assert not data_dir.PYROLAB_LOGFILE.exists() # never a second writer + + +def test_main_copies_legacy_files(run_main, data_dir, wait_for): + legacy = data_dir.LEGACY_DATA_DIR + legacy.mkdir() + (legacy / "user_configuration.yaml").write_text("daemons: {old: {}}\n") + thread, result = run_main() + info = wait_for(read_lockfile) + with Proxy(info.uri) as proxy: + proxy.shutdown() + thread.join(timeout=10) + assert data_dir.USER_CONFIG_FILE.read_text() == "daemons: {old: {}}\n" diff --git a/tests/test_utils.py b/tests/test_utils.py index 64d0480..aed3544 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -2,6 +2,8 @@ import subprocess import sys +import pytest + import pyrolab from pyrolab import utils @@ -35,6 +37,12 @@ class FakeSocket: def __init__(self, *args): pass + def __enter__(self): + return self + + def __exit__(self, *exc): + self.close() + def connect(self, addr): calls["connect"] = addr @@ -66,7 +74,8 @@ def test_pid_is_running_rejects_invalid_pids(): def test_atomic_write_text(tmp_path): - target = tmp_path / "file.txt" + tmp_path = tmp_path / "out" + target = tmp_path / "file.txt" # parent created on demand utils.atomic_write_text(target, "first") utils.atomic_write_text(target, "second") assert target.read_text() == "second" @@ -74,6 +83,8 @@ def test_atomic_write_text(tmp_path): def test_atomic_write_text_failure_leaves_original(tmp_path, monkeypatch): + tmp_path = tmp_path / "out" + tmp_path.mkdir() target = tmp_path / "file.txt" target.write_text("original") @@ -87,3 +98,42 @@ def boom(src, dst): pass assert target.read_text() == "original" assert [f.name for f in tmp_path.iterdir()] == ["file.txt"] # no temp left + + +@pytest.fixture +def no_route(monkeypatch): + """A machine with no route outside (e.g. an isolated lab network).""" + + class NoRouteSocket: + def __init__(self, *args): + pass + + def __enter__(self): + return self + + def __exit__(self, *exc): + pass + + def connect(self, addr): + raise OSError(101, "Network is unreachable") + + monkeypatch.setattr(utils.socket, "socket", NoRouteSocket) + + +def test_get_ip_without_route_uses_hostname(no_route, monkeypatch, caplog): + # Regression: raised "Network is unreachable" on isolated networks (#80). + monkeypatch.setattr(utils.socket, "gethostbyname", lambda name: "192.168.7.20") + assert utils.get_ip() == "192.168.7.20" + assert "set 'host' to the address" in caplog.text + + +@pytest.mark.parametrize("resolved", ["127.0.1.1", OSError("no such host")]) +def test_get_ip_falls_back_to_loopback(no_route, monkeypatch, caplog, resolved): + def resolve(name): + if isinstance(resolved, Exception): + raise resolved + return resolved + + monkeypatch.setattr(utils.socket, "gethostbyname", resolve) + assert utils.get_ip() == "127.0.0.1" + assert "only clients on this machine can reach" in caplog.text diff --git a/uv.lock b/uv.lock index bf91f12..b8d0204 100644 --- a/uv.lock +++ b/uv.lock @@ -2236,6 +2236,7 @@ dependencies = [ { name = "numpy", version = "2.4.6", source = { registry = "https://pypi.org/simple" }, marker = "python_full_version < '3.12'" }, { name = "numpy", version = "2.5.3", source = { registry = "https://pypi.org/simple" }, marker = "python_full_version >= '3.12'" }, { name = "packaging" }, + { name = "platformdirs" }, { name = "pydantic" }, { name = "pyro5" }, { name = "pyyaml" }, @@ -2285,6 +2286,7 @@ requires-dist = [ { name = "numpy" }, { name = "opencv-python", marker = "extra == 'cameras'" }, { name = "packaging", specifier = ">=23.0" }, + { name = "platformdirs", specifier = ">=3.0" }, { name = "pydantic", specifier = ">=1.9.1,<2.0.0" }, { name = "pyfirmata", marker = "extra == 'arduino'" }, { name = "pyro5" },