fix: correctly setup initial logging (#3747)

Author: flying-sheep

docs/release-notes/3747.bugfix.md

@@ -0,0 +1 @@
+Fix setup of initial log stream {smaller}`P Angerer`

src/scanpy/_settings/__init__.py

@@ -9,7 +9,7 @@
 
 from .. import logging
 from .._compat import deprecated, old_positionals
-from .._singleton import SingletonMeta
+from .._singleton import SingletonMeta, documenting
 from ..logging import _RootLogger, _set_log_file, _set_log_level
 from .verbosity import Verbosity
 
@@ -69,7 +69,7 @@ def wrapped(self: S, var: T, *args: P.args, **kwargs: P.kwargs) -> R:
 class SettingsMeta(SingletonMeta):
     # logging
     _root_logger: _RootLogger
-    _logfile: TextIO | None
+    _logfile: TextIO
     _verbosity: Verbosity
     # rest
     _n_pcs: int
@@ -288,15 +288,15 @@ def logpath(cls) -> Path | None:
     @_type_check_arg2(Path | str)
     def logpath(cls, logpath: Path | str | None) -> None:
         if logpath is None:
-            cls._logfile = None
+            cls.logfile = None
             cls._logpath = None
             return
         # set via “file object” branch of logfile.setter
         cls.logfile = Path(logpath).open("a")  # noqa: SIM115
         cls._logpath = Path(logpath)
 
     @property
-    def logfile(cls) -> TextIO | None:
+    def logfile(cls) -> TextIO:
         """The open file to write logs to.
 
         Set it to a :class:`~pathlib.Path` or :class:`str` to open a new one.
@@ -310,7 +310,7 @@ def logfile(cls) -> TextIO | None:
     @logfile.setter
     def logfile(cls, logfile: Path | str | TextIO | None) -> None:
         if not logfile:  # "" or None
-            logfile = sys.stdout if cls._is_run_from_ipython() else sys.stderr
+            logfile = cls._default_logfile()
         if isinstance(logfile, Path | str):
             cls.logpath = logfile
             return
@@ -441,6 +441,10 @@ def _is_run_from_ipython() -> bool:
 
         return getattr(builtins, "__IPYTHON__", False)
 
+    @classmethod
+    def _default_logfile(cls) -> TextIO:
+        return sys.stdout if cls._is_run_from_ipython() else sys.stderr
+
     def __str__(cls) -> str:
         return "\n".join(
             f"{k} = {v!r}"
@@ -456,8 +460,8 @@ def __new__(cls) -> type[Self]:
         return cls
 
     # logging
-    _root_logger: ClassVar = _RootLogger(logging.INFO)
-    _logfile: ClassVar = None
+    _root_logger: ClassVar = _RootLogger(logging.WARNING)
+    _logfile: ClassVar = SettingsMeta._default_logfile()
     _logpath: ClassVar = None
     _verbosity: ClassVar = Verbosity.warning
     # rest
@@ -481,3 +485,8 @@ def __new__(cls) -> type[Self]:
     _start: ClassVar = time()
     _previous_time: ClassVar = _start
     _previous_memory_usage: ClassVar = -1
+
+
+if not documenting():  # finish initialization
+    _set_log_level(settings, settings.verbosity.level)
+    _set_log_file(settings)

src/testing/scanpy/_pytest/__init__.py

@@ -4,6 +4,7 @@
 
 import os
 import sys
+from types import MappingProxyType
 from typing import TYPE_CHECKING
 
 import pytest
@@ -12,16 +13,18 @@
 from .marks import needs
 
 if TYPE_CHECKING:
-    from collections.abc import Generator, Iterable
+    from collections.abc import Generator, Iterable, Mapping
+
+_original_settings: Mapping[str, object] | None = None
 
 
 # Defining it here because it’s autouse.
 @pytest.fixture(autouse=True)
-def _global_test_context(
+def original_settings(
     request: pytest.FixtureRequest,
     cache: pytest.Cache,
     tmp_path_factory: pytest.TempPathFactory,
-) -> Generator[None, None, None]:
+) -> Generator[Mapping[str, object], None, None]:
     """Switch to agg backend, reset settings, and close all figures at teardown."""
     # make sure seaborn is imported and did its thing
     import seaborn as sns  # noqa: F401
@@ -30,6 +33,10 @@ def _global_test_context(
 
     import scanpy as sc
 
+    global _original_settings  # noqa: PLW0603
+    if _original_settings is None:
+        _original_settings = MappingProxyType(sc.settings.__dict__.copy())
+
     setup()
     sc.settings.logfile = sys.stderr
     sc.settings.verbosity = "hint"
@@ -44,7 +51,7 @@ def _global_test_context(
     if isinstance(request.node, pytest.DoctestItem):
         _modify_doctests(request)
 
-    yield
+    yield _original_settings
 
     plt.close("all")
 

tests/test_logging.py

@@ -5,6 +5,7 @@
 from contextlib import redirect_stdout
 from datetime import datetime
 from io import StringIO
+from logging import StreamHandler
 from typing import TYPE_CHECKING
 
 import pytest
@@ -15,14 +16,26 @@
 from scanpy import settings as s
 
 if TYPE_CHECKING:
+    from collections.abc import Mapping
     from pathlib import Path
 
 
-def test_defaults():
-    assert s.logpath is None
+def test_defaults(
+    caplog: pytest.LogCaptureFixture, original_settings: Mapping[str, object]
+) -> None:
+    assert s.logpath is original_settings["_logpath"] is None
+    assert s.logfile is original_settings["_logfile"] is sys.stderr
+    # we override s.verbosity, so we only check the default here:
+    assert original_settings["_verbosity"] is Verbosity.warning
+
+    # check logging handler file and level
+    [handler] = (h for h in s._root_logger.handlers if h is not caplog.handler)
+    assert isinstance(handler, StreamHandler)
+    assert handler.stream is s.logfile
+    assert s._root_logger.level == s.verbosity.level
 
 
-def test_records(caplog: pytest.LogCaptureFixture):
+def test_records(caplog: pytest.LogCaptureFixture) -> None:
     s.verbosity = Verbosity.debug
     log.error("0")
     log.warning("1")