Do not configure logging when pyprep is imported

.github/CONTRIBUTING.md

@@ -37,6 +37,35 @@ From the project root, call:
 - `pytest` to run tests and coverage
 - `pre-commit run -a` to run style checks (Ruff and some additional hooks)
 
+## Logging conventions
+
+What pyprep's logging does, and how a user turns it on, is documented in the
+[Logging section of the API documentation](https://pyprep.readthedocs.io/en/stable/api.html#logging).
+The rules below are the ones library code has to follow to keep that true.
+
+- one `logger = logging.getLogger(__name__)` per module, at module level, so
+  records carry the module they came from
+- never `print` from library code, and never configure the root logger, add a
+  handler, or touch another package's logger (including MNE's). Those are the
+  application's calls to make; `setup_logging` and `set_log_level` exist so that
+  it can make them in one line
+- pass arguments to the logging call (`logger.info("Found %s bads", n)`) rather
+  than formatting the string yourself, so the work is skipped when the level is
+  off
+- log values with a label. A bare `logger.info(some_number)` produces an
+  unreadable line, and the examples render their log output into the docs
+
+Do not add a `NullHandler` to the `pyprep` logger, even though older advice
+says a library should. A `NullHandler` satisfies the handler search in
+`logging.Logger.callHandlers`, which stops `logging.lastResort` from firing and
+would silently drop warnings and errors instead of merely hiding `"INFO"`. We
+want quiet, not silent, and `tests/test_logging.py` enforces both properties
+from a clean interpreter.
+
+`pyprep/_logging.py` is a verbatim copy of the same module in a few sibling
+projects, save for the package name in `LOGGER_NAME` and the docstrings. If you
+change its behavior, the copies need to stay in sync.
+
 ## Building the documentation
 
 The documentation can be built using [Sphinx](https://www.sphinx-doc.org).

README.rst

@@ -76,6 +76,19 @@ all required dependencies automatically.
 The dependencies are defined in the ``pyproject.toml`` file under the
 ``dependencies`` and ``project.optional-dependencies`` sections.
 
+Logging
+=======
+
+``pyprep`` logs through the standard ``logging`` module and configures nothing
+when it is imported, so it is quiet by default but never silent: warnings and
+errors reach ``stderr`` without any setup.
+Call ``pyprep.setup_logging("info")`` to see what the pipeline decided, or
+``pyprep.set_log_level("info")`` if your application already routes logging
+somewhere of its own.
+
+See the `Logging section of the API documentation
+<https://pyprep.readthedocs.io/en/stable/api.html#logging>`_ for the details.
+
 Contributing
 ============
 

docs/api.rst

@@ -55,14 +55,44 @@ The :mod:`~pyprep.ransac` module
 Logging
 =======
 
-pyprep logs at ``"INFO"`` through its own ``pyprep`` logger, which is configured
-when the package is imported. Use the function below to change the level, redirect
-the stream, or hand the records to your application's own handlers. The root logger
-is never configured.
+pyprep logs through the standard :mod:`logging` module, on a logger named
+``pyprep``, and — like any well-behaved library — configures nothing on import.
+It is quiet, but not silent: with no configuration at all, warnings and errors
+still reach :data:`sys.stderr`, because Python falls back to
+:data:`logging.lastResort` when no handler is found. ``"INFO"`` records, which
+is where the pipeline reports what it decided, are hidden until you ask for
+them.
+
+There are two ways to ask. Interactively, :func:`~pyprep.setup_logging`
+attaches a handler to the ``pyprep`` logger and stops those records from
+propagating any further, so they are not printed twice:
+
+.. code-block:: python
+
+   import pyprep
+
+   pyprep.setup_logging("info")
+
+In an application that already routes logging somewhere of its own — a file, a
+JSON aggregator, a Rich console — do not call it at all. The records reach your
+handlers by propagation, and :func:`~pyprep.set_log_level` raises pyprep's
+verbosity without touching the handler, the stream, the format, or the
+propagation you chose:
+
+.. code-block:: python
+
+   pyprep.set_log_level("info")
+
+The root logger is never configured either way. MNE has its own ``mne`` logger,
+controlled separately with :func:`mne.set_log_level`; note also that the
+progress bar drawn during window-wise RANSAC is an ``mne.utils.ProgressBar``,
+which writes to its own stream rather than through either logger, so neither
+function silences it.
 
 .. currentmodule:: pyprep
 
 .. autosummary::
    :toctree: generated/
 
    setup_logging
+   set_log_level

docs/changelog.rst

@@ -26,7 +26,18 @@ Version 0.9.0 (unreleased)
 
 Changelog
 ~~~~~~~~~
-- Nothing yet
+- The new :func:`pyprep.set_log_level` changes the level of the ``pyprep`` logger without touching its handler, stream, format, or propagation, mirroring :func:`mne.set_log_level`. Use it instead of calling :func:`pyprep.setup_logging` a second time, which would reset all of those, by `Stefan Appelhoff`_ (:gh:`211`)
+- :func:`pyprep.setup_logging` now accepts level names in any case, so ``setup_logging("warning")`` works like :func:`mne.set_log_level` instead of raising ``ValueError``. Its ``stream`` argument became keyword-only and now defaults to :data:`sys.stdout` on every call rather than keeping whatever stream a previous call had installed, and a new keyword-only ``fmt`` argument sets the format of the installed handler, by `Stefan Appelhoff`_ (:gh:`211`)
+- All three examples now switch pyprep's logging on themselves with ``pyprep.setup_logging("info")``, since importing the package no longer does. Channel-wise RANSAC no longer logs a bare chunk counter on every chunk, reporting the chunk size and the number of chunks once instead, and two of its messages no longer carry embedded newlines that split them across two log lines, by `Stefan Appelhoff`_ (:gh:`211`)
+
+API
+~~~
+- ``pyprep`` no longer configures logging when it is imported. 0.8.0 attached a handler on :data:`sys.stdout` to the ``pyprep`` logger at import time, so users got ``"INFO"`` output for free; a library cannot know whether the application wants stdout, a file, JSON to an aggregator, or a Rich console, so that decision is handed back to the caller. Without any configuration ``pyprep`` is quiet but not silent: warnings and errors still reach :data:`sys.stderr` through :data:`logging.lastResort`, and ``"INFO"`` records appear once you call :func:`pyprep.setup_logging` or :func:`pyprep.set_log_level`. Note that no :class:`logging.NullHandler` is installed either, deliberately: one would satisfy the handler search in ``logging.Logger.callHandlers`` and suppress the ``lastResort`` fallback, dropping warnings and errors instead of merely hiding ``"INFO"``, by `Stefan Appelhoff`_ (:gh:`211`)
+- The ``propagate`` argument of :func:`pyprep.setup_logging` was removed. It existed to undo the import-time configuration and hand the records to the application's handlers; with nothing configured on import, propagation is simply what happens when :func:`pyprep.setup_logging` is never called, by `Stefan Appelhoff`_ (:gh:`211`)
+
+Bug
+~~~
+- :func:`pyprep.removeTrend.removeTrend` now raises a :class:`ValueError` for a ``'local detrend'`` step size that is larger than the window or smaller than one sample, instead of logging an error and detrending with it anyway, by `Stefan Appelhoff`_ (:gh:`211`)
 
 .. _changes_0_8_0:
 

examples/run_full_prep.py

@@ -21,7 +21,7 @@
 import numpy as np
 from mne.datasets import eegbci
 
-from pyprep import setup_logging
+import pyprep
 from pyprep.prep_pipeline import PrepPipeline
 
 ###############################################################################
@@ -32,11 +32,11 @@
 # a fairly noisy recording, which makes it a good candidate for demonstrating
 # PREP. The data are 64-channel EEG sampled at 160 Hz.
 #
-# MNE and pyprep each log at ``"INFO"`` by default; we turn both down to keep
-# this example's output short.
+# pyprep configures no logging of its own, so we ask it for ``"INFO"`` here to
+# see what each step decides. MNE is loud at ``"INFO"``, so we turn it down.
 
-mne.set_log_level("WARNING")
-setup_logging("WARNING")
+mne.set_log_level("warning")
+pyprep.setup_logging("info")
 
 edf_fpath = eegbci.load_data(subjects=4, runs=1, update_path=True)[0]
 raw = mne.io.read_raw_edf(edf_fpath, preload=True)

examples/run_prep_in_stages.py

@@ -26,7 +26,7 @@
 import numpy as np
 from mne.datasets import eegbci
 
-from pyprep import setup_logging
+import pyprep
 from pyprep.prep_pipeline import PrepPipeline
 
 ###############################################################################
@@ -37,11 +37,11 @@
 # PhysioNet BCI2000 (eegbci) dataset: a fairly noisy 64-channel recording
 # sampled at 160 Hz.
 #
-# MNE and pyprep each log at ``"INFO"`` by default; we turn both down to keep
-# this example's output short.
+# pyprep configures no logging of its own, so we ask it for ``"INFO"`` here to
+# see what each step decides. MNE is loud at ``"INFO"``, so we turn it down.
 
-mne.set_log_level("WARNING")
-setup_logging("WARNING")
+mne.set_log_level("warning")
+pyprep.setup_logging("info")
 
 edf_fpath = eegbci.load_data(subjects=4, runs=1, update_path=True)[0]
 raw = mne.io.read_raw_edf(edf_fpath, preload=True)

examples/run_ransac.py

@@ -20,8 +20,16 @@
 import numpy as np
 from scipy import signal as signal
 
+import pyprep
 from pyprep.find_noisy_channels import NoisyChannels
 
+###############################################################################
+# pyprep configures no logging of its own, so we ask it for ``"INFO"`` here to
+# see what RANSAC decides. MNE is loud at ``"INFO"``, so we turn it down.
+
+mne.set_log_level("warning")
+pyprep.setup_logging("info")
+
 ###############################################################################
 # Now let's make some arbitrary MNE raw object for demonstration purposes.
 # We will think of good channels as sine waves and bad channels correlated with

pyprep/__init__.py

@@ -4,15 +4,11 @@
 # SPDX-License-Identifier: MIT
 
 import pyprep.ransac as ransac  # noqa: F401
-from pyprep._logging import setup_logging  # noqa: F401
+from pyprep._logging import set_log_level, setup_logging  # noqa: F401
 from pyprep.find_noisy_channels import NoisyChannels  # noqa: F401
 from pyprep.prep_pipeline import PrepPipeline  # noqa: F401
 from pyprep.reference import Reference  # noqa: F401
 
-# Loud by default, like MNE. Applications turn it down with
-# setup_logging("WARNING") or take over the output with setup_logging(propagate=True).
-setup_logging()
-
 try:
     from importlib.metadata import version
 

pyprep/_logging.py

@@ -6,57 +6,101 @@
 import logging
 import sys
 
-_FORMAT = "%(asctime)s [%(levelname)s] %(name)s: %(message)s"
-_LOGGER_NAME = "pyprep"
+LOGGER_NAME = "pyprep"
+DEFAULT_FORMAT = "%(asctime)s [%(levelname)s] %(name)s: %(message)s"
 
 
 class _StreamHandler(logging.StreamHandler):
-    """Marker subclass identifying the handler that pyprep installed."""
+    """Marker subclass identifying the handler that this package installed."""
 
 
-def setup_logging(level="INFO", stream=None, propagate=False):
-    """Configure the ``pyprep`` logger.
+def _as_level(level):
+    """Accept a name in any case, or a stdlib constant like logging.DEBUG."""
+    return level.upper() if isinstance(level, str) else level
 
-    This is called at import time with its defaults, so pyprep logs at ``"INFO"``
-    to :data:`sys.stdout` without any setup. Call it again to change that.
+
+def set_log_level(level, return_old_level=False):
+    """Change the level of the ``pyprep`` logger, leaving its handlers alone.
+
+    Use this rather than :func:`pyprep.setup_logging` to turn the package up or
+    down: :func:`pyprep.setup_logging` also decides *where* the records go, so
+    calling it again just to change the level would reset the stream, the format,
+    and the propagation that an application had chosen.
 
     Parameters
     ----------
     level : int | str
-        Level for the ``pyprep`` logger. Pass ``"WARNING"`` to keep only warnings
-        and errors, or ``"DEBUG"`` for more detail. Defaults to ``"INFO"``.
+        Level for the ``pyprep`` logger, either a name (e.g. ``"debug"``,
+        ``"WARNING"``) or a stdlib constant such as :data:`logging.DEBUG`. Names
+        are case-insensitive, as in :func:`mne.set_log_level`.
+    return_old_level : bool
+        Whether to return the level the logger had before this call, so that a
+        caller can put it back afterwards. Defaults to ``False``.
+
+    Returns
+    -------
+    old_level : int | None
+        The previous level of the ``pyprep`` logger if ``return_old_level`` is
+        ``True``, and ``None`` otherwise.
+
+    Notes
+    -----
+    This cannot make records appear on its own. Until :func:`pyprep.setup_logging`
+    has run, or the application has configured a logger that this one propagates
+    to, there is no handler to write them.
+    """
+    logger = logging.getLogger(LOGGER_NAME)
+    old_level = logger.level
+    logger.setLevel(_as_level(level))
+    if return_old_level:
+        return old_level
+
+
+def setup_logging(level="info", *, stream=None, fmt=DEFAULT_FORMAT):
+    """Send pyprep's log records to a stream, at the given level.
+
+    If your application already routes logging somewhere of its own, do not call
+    this at all. The records will reach your handlers by propagation, and
+    :func:`pyprep.set_log_level` is there if you want the ``"INFO"`` ones too.
+
+    Parameters
+    ----------
+    level : int | str
+        Level for the ``pyprep`` logger, either a name (e.g. ``"debug"``,
+        ``"WARNING"``) or a stdlib constant such as :data:`logging.DEBUG`. Names
+        are case-insensitive, as in :func:`mne.set_log_level`. Defaults to
+        ``"info"``.
     stream : file-like | None
-        Destination for pyprep's own handler. ``None`` keeps the current
-        destination, which is :data:`sys.stdout` on a fresh interpreter. Ignored
-        when ``propagate`` is ``True``.
-    propagate : bool
-        ``False`` (the default) prints through pyprep's own handler and stops the
-        records there, so an application that configures the root logger does not
-        see them twice. ``True`` removes that handler and passes the records to
-        ancestor loggers instead, letting the application's own handlers format
-        and route them.
+        Destination for pyprep's handler. ``None`` means :data:`sys.stdout`.
+    fmt : str
+        Format string for the handler, in the style of :class:`logging.Formatter`.
+        Defaults to ``pyprep._logging.DEFAULT_FORMAT``, which prefixes each
+        record with a timestamp, its level, and the name of the logger it came
+        from.
+
+    Returns
+    -------
+    logger : logging.Logger
+        The configured ``pyprep`` logger.
 
     Notes
     -----
-    Only the ``pyprep`` namespace is configured; the root logger is never touched.
-    MNE has its own ``mne`` logger, controlled separately through
-    :func:`mne.set_log_level`. Before pyprep 0.8.0 several pyprep modules logged
-    through MNE's logger, so ``mne.set_log_level`` used to silence them; use this
-    function instead.
+    To hand the output back afterwards, drop the handler again with
+    ``logging.getLogger("pyprep").handlers.clear()``.
     """
-    logger = logging.getLogger(_LOGGER_NAME)
-    logger.setLevel(level)
-    own = [h for h in logger.handlers if isinstance(h, _StreamHandler)]
-    if propagate:
-        for handler in own:
-            logger.removeHandler(handler)
-            handler.close()
-    elif own:
-        if stream is not None:
-            for handler in own:
-                handler.setStream(stream)
-    else:
-        handler = _StreamHandler(stream or sys.stdout)
-        handler.setFormatter(logging.Formatter(_FORMAT))
-        logger.addHandler(handler)
-    logger.propagate = propagate
+    logger = logging.getLogger(LOGGER_NAME)
+    logger.setLevel(_as_level(level))
+
+    # Repeated calls swap our handler out instead of stacking a new one on top. The
+    # marker subclass is what makes ours identifiable: a plain isinstance check
+    # against logging.StreamHandler would also match a FileHandler that the
+    # application attached to this logger, and we would remove and close it.
+    for handler in [h for h in logger.handlers if isinstance(h, _StreamHandler)]:
+        logger.removeHandler(handler)
+        handler.close()
+
+    handler = _StreamHandler(sys.stdout if stream is None else stream)
+    handler.setFormatter(logging.Formatter(fmt))
+    logger.addHandler(handler)
+    logger.propagate = False
+    return logger

pyprep/find_noisy_channels.py

@@ -228,10 +228,11 @@ def get_bads(self, verbose=False, as_dict=False):
 
         Parameters
         ----------
-        verbose : bool | None
-            If ``True``, a summary of the channels currently flagged as by bad per
-            category is printed. Defaults to ``False``.
-        as_dict: bool | None
+        verbose : bool
+            If ``True``, a summary of the channels currently flagged as bad per
+            category is logged at ``"INFO"`` through the ``pyprep`` logger.
+            Defaults to ``False``.
+        as_dict : bool
             If ``True``, this method will return a dict of the channels currently
             flagged as bad by each individual bad channel type. If ``False``, this
             method will return a list of all unique bad channels detected so far.