diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 48fe5f7..ca88f57 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -46,6 +46,7 @@ repos: - pydantic-settings - pydocstring-rs - pytest + - rich - sphinx - sphinx-autodoc-typehints - sphinxcontrib-katex diff --git a/pyproject.toml b/pyproject.toml index 0cf50eb..b23be23 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -23,12 +23,17 @@ classifiers = [ dynamic = [ "version" ] dependencies = [ "anndata", + "pydantic-settings", + "python-dotenv", # for debug logging (referenced from the issue template) "session-info2", "typing-extensions; python_version<'3.13'", ] optional-dependencies.datasets = [ "pooch", "pyyaml", "tqdm" ] -optional-dependencies.settings = [ "pydantic-settings", "python-dotenv" ] +optional-dependencies.rich = [ "rich" ] +# Kept for backwards compat: anndata <0.13 references scverse-misc[settings]. +# The deps are now hard dependencies (see above), so this extra is empty. +optional-dependencies.settings = [] optional-dependencies.spatialdata = [ "spatialdata" ] optional-dependencies.sphinx = [ "pydocstring-rs>=0.1.13", "sphinx>=9" ] # https://docs.pypi.org/project_metadata/#project-urls diff --git a/src/scverse_misc/__init__.py b/src/scverse_misc/__init__.py index baeedc8..141e9c5 100644 --- a/src/scverse_misc/__init__.py +++ b/src/scverse_misc/__init__.py @@ -1,11 +1,12 @@ -from contextlib import suppress - from ._deprecated import Deprecation, deprecated, deprecated_arg from ._extensions import ExtensionNamespace, make_register_namespace_decorator - -__all__ = ["ExtensionNamespace", "make_register_namespace_decorator", "deprecated", "deprecated_arg", "Deprecation"] - -with suppress(ImportError): - from ._settings import Settings # noqa: F401 - - __all__.append("Settings") +from ._settings import Settings + +__all__ = [ + "ExtensionNamespace", + "make_register_namespace_decorator", + "deprecated", + "deprecated_arg", + "Deprecation", + "Settings", +] diff --git a/src/scverse_misc/logging.py b/src/scverse_misc/logging.py new file mode 100644 index 0000000..91901f9 --- /dev/null +++ b/src/scverse_misc/logging.py @@ -0,0 +1,252 @@ +"""Shared logger for scverse packages. + +Skeleton: one ``scverse`` parent logger owning a single handler (rich if +installed, else plain), with package loggers as children. Control via +:data:`config`. The only extension point is :class:`Rule` — subclass it to +filter or rewrite output; register any number with :meth:`config.add_rule`. + +Two **universal rules** ship enabled by default and are no-ops until a record +carries the matching attribute: + +- :class:`Elapsed` renders ``record.time_passed`` (a ``timedelta``): substitutes + ``{time_passed}`` in the message, else appends ``(H:MM:SS)``. +- :class:`Deep` appends ``record.deep`` as ``": detail"``. + +Because rules run on the handler, they render identically under rich and plain. + +scanpy's ``time=`` / ``deep=`` keywords and the ``-> datetime`` return are a +call-site concern a rule cannot provide (a rule runs after the call returns), +so they live in an **opt-in** logger: ``get_logger("scanpy", timed=True)``:: + + log = get_logger("scanpy", timed=True) + t = log.info("normalizing") # returns a datetime + log.info("finished ({time_passed})", time=t) # Elapsed rule renders it + log.info("done", time=t, deep="42 cells dropped") +""" + +from __future__ import annotations + +import logging +from datetime import datetime, timedelta +from typing import Any, Literal, Self, cast, overload + +from pydantic import field_validator, model_validator + +from ._settings import Settings + +__all__ = ["Rule", "Elapsed", "Deep", "TimedLogger", "config", "get_logger"] + +_ROOT = "scverse" +HINT = (logging.INFO + logging.DEBUG) // 2 # 15; used by the timed logger +logging.addLevelName(HINT, "HINT") + + +class Rule(logging.Filter): + """A logging rule — subclass and override what you need; both default to no-ops. + + - :meth:`keep` ``(record) -> bool`` — return ``False`` to drop the record. + - :meth:`rewrite` ``(message, record) -> str`` — return the new text + (``message`` is the fully formatted string). + + Rules run in registration order on the shared handler, for every package. + """ + + def keep(self, record: logging.LogRecord) -> bool: + """Return ``False`` to drop the record (default: keep everything).""" + return True + + def rewrite(self, message: str, record: logging.LogRecord) -> str: + """Return the new message text (default: unchanged).""" + return message + + def filter(self, record: logging.LogRecord) -> bool: # stdlib hook; don't override + """Stdlib hook: apply :meth:`keep` then :meth:`rewrite`. Don't override.""" + if not self.keep(record): + return False + message = record.getMessage() # always a str, %-args already expanded + new = self.rewrite(message, record) + if new != message: + record.msg, record.args = new, () + return True + + +class Elapsed(Rule): + """Render ``record.time_passed`` (a ``timedelta``). Universal, enabled by default.""" + + def rewrite(self, message: str, record: logging.LogRecord) -> str: + """Substitute ``{time_passed}`` if present, else append ``(H:MM:SS)``.""" + td = getattr(record, "time_passed", None) + if not td: # None or zero -> show nothing (matches scanpy) + return message + td = timedelta(seconds=int(td.total_seconds())) # strip sub-second noise + if "{time_passed}" in message: + return message.replace("{time_passed}", str(td)) + return f"{message} ({td})" + + +class Deep(Rule): + """Append ``record.deep`` as detail. Universal, enabled by default.""" + + def rewrite(self, message: str, record: logging.LogRecord) -> str: + """Append ``record.deep`` as ``": detail"`` when present.""" + deep = getattr(record, "deep", None) + return message if deep is None else f"{message}: {deep}" + + +def _make_handler(use_rich: bool) -> logging.Handler: + if use_rich: + from rich.logging import RichHandler + + return RichHandler(show_path=False, show_time=False) # rich renders the level itself + handler = logging.StreamHandler() + handler.setFormatter(logging.Formatter("%(levelname)s: %(message)s")) + return handler + + +def _rich_available() -> bool: + from importlib.util import find_spec + + return find_spec("rich") is not None + + +class _LogConfig(Settings): + """Central logging configuration; the singleton instance is :data:`config`. + + Subclasses :class:`~scverse_misc.Settings`, so values also load from + environment variables (prefix ``SCVERSE_MISC_``) and support the inherited + :meth:`override`/:meth:`reset` context managers. The shared ``scverse`` + logger is the source of truth for the live state; assigning a field + re-applies it via the validator below. + """ + + verbosity: str | int = "warning" + """Central level for all scverse loggers; a level name (``"info"``) or an int.""" + + rich: bool | None = None + """Force rich rendering on/off; ``None`` auto-detects whether rich is installed.""" + + @field_validator("verbosity") + @classmethod + def _canonical_level(cls, value: str | int) -> str: + """Validate and normalize to a canonical level name (e.g. ``"WARNING"``).""" + if isinstance(value, str): + if not isinstance(logging.getLevelName(value.upper()), int): + raise ValueError(f"unknown log level name: {value!r}") + return value.upper() + name = logging.getLevelName(value) + if name.startswith("Level "): + raise ValueError(f"unknown log level: {value!r}") + return name + + @model_validator(mode="after") + def _apply(self) -> Self: + """Push the current settings onto the shared ``scverse`` logger and handler.""" + root = logging.getLogger(_ROOT) + root.propagate = False # one handler here; don't double-log via root + root.setLevel(self.verbosity) + use_rich = _rich_available() if self.rich is None else self.rich + current = root.handlers[0] if root.handlers else None + # a plain handler is a StreamHandler, rich's RichHandler is not -> cheap rich test + if current is None or isinstance(current, logging.StreamHandler) == use_rich: + rules = list(current.filters) if current else [Elapsed(), Deep()] # carry rules across + for h in list(root.handlers): + root.removeHandler(h) + handler = _make_handler(use_rich) + for r in rules: + handler.addFilter(r) + root.addHandler(handler) + return self + + @property + def _root(self) -> logging.Logger: + return logging.getLogger(_ROOT) + + @property + def _rules(self) -> list[logging.Filter]: + return cast("list[logging.Filter]", self._root.handlers[0].filters) + + def add_rule(self, rule: Rule) -> None: + for h in self._root.handlers: + h.addFilter(rule) + + def remove_rule(self, rule: Rule) -> None: + for h in self._root.handlers: + h.removeFilter(rule) + + +config = _LogConfig() + + +class TimedLogger: + """Opt-in scanpy-style wrapper: ``time=``/``deep=`` keywords + a ``datetime`` return. + + Sets ``time_passed``/``deep`` on the record (rendered by the :class:`Elapsed` + and :class:`Deep` rules) and returns the current time so callers can thread it. + Everything else delegates to the underlying real logger. + """ + + def __init__(self, logger: logging.Logger) -> None: + self._logger = logger + + def __getattr__(self, name: str) -> Any: # noqa: ANN401 # transparent delegation to the real logger + if name == "_logger": + raise AttributeError(name) + return getattr(self._logger, name) + + def _emit( + self, + level: int, + msg: object, + *args: object, + time: datetime | None = None, + deep: object = None, + ) -> datetime: + now = datetime.now() + if self._logger.isEnabledFor(level): + extra: dict[str, object] = {} + if time is not None: + extra["time_passed"] = now - time # thread the returned value (both naive) + if deep is not None and self._logger.getEffectiveLevel() < level: + extra["deep"] = deep + # stacklevel=3: skip _emit + the level method so the call-site is the caller + self._logger.log(level, msg, *args, extra=extra, stacklevel=3) + return now + + def debug(self, msg: object, *a: object, time: datetime | None = None, deep: object = None) -> datetime: + """Log at DEBUG; return the current time (see :class:`TimedLogger`).""" + return self._emit(logging.DEBUG, msg, *a, time=time, deep=deep) + + def hint(self, msg: object, *a: object, time: datetime | None = None, deep: object = None) -> datetime: + """Log at HINT; return the current time (see :class:`TimedLogger`).""" + return self._emit(HINT, msg, *a, time=time, deep=deep) + + def info(self, msg: object, *a: object, time: datetime | None = None, deep: object = None) -> datetime: + """Log at INFO; return the current time (see :class:`TimedLogger`).""" + return self._emit(logging.INFO, msg, *a, time=time, deep=deep) + + def warning(self, msg: object, *a: object, time: datetime | None = None, deep: object = None) -> datetime: + """Log at WARNING; return the current time (see :class:`TimedLogger`).""" + return self._emit(logging.WARNING, msg, *a, time=time, deep=deep) + + def error(self, msg: object, *a: object, time: datetime | None = None, deep: object = None) -> datetime: + """Log at ERROR; return the current time (see :class:`TimedLogger`).""" + return self._emit(logging.ERROR, msg, *a, time=time, deep=deep) + + def critical(self, msg: object, *a: object, time: datetime | None = None, deep: object = None) -> datetime: + """Log at CRITICAL; return the current time (see :class:`TimedLogger`).""" + return self._emit(logging.CRITICAL, msg, *a, time=time, deep=deep) + + +@overload +def get_logger(name: str, *, timed: Literal[False] = False) -> logging.Logger: ... +@overload +def get_logger(name: str, *, timed: Literal[True]) -> TimedLogger: ... +def get_logger(name: str, *, timed: bool = False) -> logging.Logger | TimedLogger: + """Return the ``scverse.`` logger a package should use. + + ``timed=False`` (default) returns a plain :class:`logging.Logger`. + ``timed=True`` returns a :class:`TimedLogger` with scanpy-style ``time=`` / + ``deep=`` keywords and a ``datetime`` return. + """ + logger = logging.getLogger(name if name.startswith(f"{_ROOT}.") else f"{_ROOT}.{name}") + return TimedLogger(logger) if timed else logger diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..d3959c0 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,197 @@ +from __future__ import annotations + +import io +import logging +from datetime import datetime, timedelta +from typing import TYPE_CHECKING + +import pytest +from pydantic import ValidationError + +from scverse_misc import logging as mod +from scverse_misc.logging import Deep, Elapsed, Rule, TimedLogger, config, get_logger + +if TYPE_CHECKING: + from collections.abc import Generator + + +@pytest.fixture +def sink() -> Generator[io.StringIO, None, None]: + """Force the plain handler, capture its output, and restore global state after.""" + old_level = config._root.level + old_rules = list(config._rules) + config.rich = False + handler = config._root.handlers[0] + assert isinstance(handler, logging.StreamHandler) + buf = io.StringIO() + handler.setStream(buf) + config.verbosity = "debug" + try: + yield buf + finally: + # drop any rules a test added, then restore level + a clean plain handler + for rule in list(config._rules): + if rule not in old_rules: + config.remove_rule(rule) + config._root.setLevel(old_level) + + +def test_get_logger_plain_naming() -> None: + plain = get_logger("selftest") + assert isinstance(plain, logging.Logger) + assert plain.name == "scverse.selftest" + assert plain.parent is not None and plain.parent.name == "scverse" + + +def test_get_logger_does_not_double_prefix() -> None: + assert get_logger("scverse.already").name == "scverse.already" + + +def test_timed_logger_returns_datetime(sink: io.StringIO) -> None: + log = get_logger("selftest", timed=True) + assert isinstance(log, TimedLogger) + t = log.info("start") + assert isinstance(t, datetime) + + +def test_elapsed_substitution_and_append(sink: io.StringIO) -> None: + log = get_logger("selftest", timed=True) + now = datetime.now() + log.info("finished ({time_passed})", time=now - timedelta(seconds=5)) + log.info("done", time=now - timedelta(seconds=2)) + out = sink.getvalue() + assert "finished (0:00:05)" in out + assert "done (0:00:02)" in out + + +def test_elapsed_noop_without_time(sink: io.StringIO) -> None: + log = get_logger("selftest", timed=True) + log.info("plain message") + out = sink.getvalue() + assert "plain message" in out + assert "(" not in out.split("plain message", 1)[1] + + +def test_deep_appended(sink: io.StringIO) -> None: + log = get_logger("selftest", timed=True) + log.info("normalized", deep="3 cells dropped") + assert "normalized: 3 cells dropped" in sink.getvalue() + + +def test_deep_falsy_zero_preserved(sink: io.StringIO) -> None: + # 0 must not be dropped by a truthiness check (Deep uses `is None`) + log = get_logger("selftest", timed=True) + log.info("count", deep=0) + assert "count: 0" in sink.getvalue() + + +def test_deep_hidden_when_not_below_level(sink: io.StringIO) -> None: + # deep only renders when the effective level is strictly below the call level + config.verbosity = "info" + log = get_logger("selftest", timed=True) + log.info("msg", deep="hidden detail") + out = sink.getvalue() + assert "msg" in out + assert "hidden detail" not in out + + +def test_user_rule_composes_and_verbosity_gates(sink: io.StringIO) -> None: + class Tag(Rule): + def rewrite(self, message: str, record: logging.LogRecord) -> str: + return f"[{record.name.rsplit('.', 1)[-1]}] {message}" + + config.add_rule(Tag()) + log = get_logger("selftest", timed=True) + log.warning("hi") + assert "[selftest] hi" in sink.getvalue() + + +def test_rule_keep_can_drop_record(sink: io.StringIO) -> None: + class DropAll(Rule): + def keep(self, record: logging.LogRecord) -> bool: + return False + + config.add_rule(DropAll()) + get_logger("selftest").warning("should be dropped") + assert sink.getvalue() == "" + + +def test_base_rule_is_passthrough(sink: io.StringIO) -> None: + config.add_rule(Rule()) # base keep()/rewrite() are no-ops + get_logger("selftest").warning("unchanged") + assert "unchanged" in sink.getvalue() + + +def test_verbosity_get_set_by_name_and_int() -> None: + config.verbosity = "warning" + assert config.verbosity == "WARNING" + plain = get_logger("selftest") + assert not plain.isEnabledFor(logging.INFO) + assert plain.isEnabledFor(logging.WARNING) + config.verbosity = logging.DEBUG + assert plain.isEnabledFor(logging.DEBUG) + + +def test_verbosity_rejects_unknown_level() -> None: + config.verbosity = "warning" + for bad in ("bogus", 999): + with pytest.raises(ValidationError): + config.verbosity = bad + assert config.verbosity == "WARNING" # rejected assignment leaves the value untouched + + +def test_override_restores_verbosity() -> None: + config.verbosity = "warning" + with config.override(verbosity="debug"): + assert config.verbosity == "DEBUG" + assert logging.getLogger("scverse").level == logging.DEBUG + assert config.verbosity == "WARNING" + + +def test_env_var_sets_verbosity(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setenv("SCVERSE_MISC_VERBOSITY", "info") + assert mod._LogConfig().verbosity == "INFO" + config.verbosity = "warning" # construction set the shared logger; restore it + + +def test_universal_rules_enabled_by_default() -> None: + assert any(isinstance(r, Elapsed) for r in config._rules) + assert any(isinstance(r, Deep) for r in config._rules) + + +def test_hint_level_registered() -> None: + assert logging.getLevelName(mod.HINT) == "HINT" + + +def test_remove_rule_is_idempotent() -> None: + rule = Rule() + config.add_rule(rule) + config.remove_rule(rule) + config.remove_rule(rule) # removing again must not raise + assert rule not in config._rules + + +def test_all_level_methods_emit_and_return_datetime(sink: io.StringIO) -> None: + log = get_logger("selftest", timed=True) + for emit in (log.debug, log.hint, log.info, log.warning, log.error, log.critical): + assert isinstance(emit("msg"), datetime) + + +def test_timed_logger_delegates_unknown_attrs() -> None: + log = get_logger("selftest", timed=True) + # name / getEffectiveLevel aren't defined on TimedLogger -> __getattr__ delegates + assert log.name == "scverse.selftest" + assert log.getEffectiveLevel() == logging.getLogger("scverse.selftest").getEffectiveLevel() + + +def test_rich_property_installs_rich_handler() -> None: + pytest.importorskip("rich") + from rich.logging import RichHandler + + try: + config.rich = True + assert isinstance(config._root.handlers[0], RichHandler) + assert config.rich is True + finally: + config.rich = False + assert config.rich is False