diff --git a/docs/core_concepts/outputs_and_inspection.md b/docs/core_concepts/outputs_and_inspection.md index b8b4d80..4bc16a7 100644 --- a/docs/core_concepts/outputs_and_inspection.md +++ b/docs/core_concepts/outputs_and_inspection.md @@ -354,6 +354,11 @@ Preprocessor(numerical_method="ple", verbose=1).fit(df, y) fit complete: 2 numerical (ple) + 1 categorical (int) feature(s) -> 15 output columns in 0.02s ``` +Each fit applies its own level, so a later `verbose=2` fit in the same process or notebook logs +the table even after a `verbose=1` fit. PreTab attaches its own stream handler only when no host +handler receives its records. A handler on the `"pretab"` logger, or on an ancestor such as the +root handler that `logging.basicConfig` installs, takes over, so every line is printed once. + ```{note} When `feature_preprocessing` overrides make columns of the same kind resolve to different methods, the summary reports `mixed: , , ...` instead of a single name, so the diff --git a/pretab/core/logging.py b/pretab/core/logging.py index 358d46f..cb75f4c 100644 --- a/pretab/core/logging.py +++ b/pretab/core/logging.py @@ -34,9 +34,29 @@ def get_logger(name: str = "pretab") -> logging.Logger: return logging.getLogger(name) +# Marks the handler :func:`configure_logging` attaches, so later calls can tell +# PreTab's own handler apart from one owned by the host application. +_OWN_HANDLER_FLAG = "_pretab_own_handler" + + +def _is_host_handler(handler: logging.Handler) -> bool: + """Whether ``handler`` belongs to the host (neither a ``NullHandler`` nor PreTab's own).""" + return not isinstance(handler, logging.NullHandler) and not getattr(handler, _OWN_HANDLER_FLAG, False) + + def _has_real_handler(logger: logging.Logger) -> bool: - """Whether ``logger`` already carries a handler other than ``NullHandler``.""" - return any(not isinstance(handler, logging.NullHandler) for handler in logger.handlers) + """Whether ``logger`` itself carries a host handler (one PreTab did not attach).""" + return any(_is_host_handler(handler) for handler in logger.handlers) + + +def _ancestor_has_real_handler(logger: logging.Logger) -> bool: + """Whether a host handler on an ancestor receives ``logger``'s records through propagation.""" + current = logger + while current.propagate and current.parent is not None: + current = current.parent + if _has_real_handler(current): + return True + return False def set_verbosity(level: int = 1) -> None: @@ -57,8 +77,15 @@ def configure_logging(level: int = 1, handler: "logging.Handler | None" = None) Sets the ``"pretab"`` logger level and attaches a stream handler so PreTab's messages become visible. This never touches the root logger, and it is a - no-op when a real (non-``NullHandler``) handler is already attached -- so an - embedding host (such as DeepTab) that owns handler/level policy always wins. + no-op when the host has attached a real (non-``NullHandler``) handler to the + ``"pretab"`` logger -- so an embedding host (such as DeepTab) that owns + handler/level policy always wins. + + Repeated calls update the level (the handler PreTab attached earlier is + reused, never duplicated). When a host handler on an ancestor logger -- such + as a root handler from :func:`logging.basicConfig` -- already receives + PreTab's records, no handler is attached (and one attached earlier is + removed), so every message is printed once. Parameters ---------- @@ -71,7 +98,15 @@ def configure_logging(level: int = 1, handler: "logging.Handler | None" = None) if _has_real_handler(_LOGGER): return set_verbosity(level) + own_handlers = [existing for existing in _LOGGER.handlers if getattr(existing, _OWN_HANDLER_FLAG, False)] + if _ancestor_has_real_handler(_LOGGER): + for existing in own_handlers: + _LOGGER.removeHandler(existing) + return + if own_handlers: + return if handler is None: handler = logging.StreamHandler() handler.setFormatter(logging.Formatter("%(name)s: %(message)s")) + setattr(handler, _OWN_HANDLER_FLAG, True) _LOGGER.addHandler(handler) diff --git a/pretab/preprocessor.py b/pretab/preprocessor.py index 455cac8..29b471f 100644 --- a/pretab/preprocessor.py +++ b/pretab/preprocessor.py @@ -1,5 +1,6 @@ import hashlib import json +import logging import os import time import warnings @@ -289,8 +290,11 @@ class Preprocessor(TransformerMixin, BaseEstimator): Stored verbatim and forwarded by ``get_params`` / ``clone``, so an embedding host (e.g. DeepTab) can pass it straight through ``Preprocessor(**kwargs)``. PreTab never - configures the root logger or attaches a handler when the host already owns one, so - ``verbose=0`` keeps PreTab silent under a host's own logging. + configures the root logger or attaches a handler when the host already owns one (on + the ``"pretab"`` logger or on an ancestor, such as a root handler from + :func:`logging.basicConfig`), so ``verbose=0`` keeps PreTab silent under a host's own + logging and every message is printed once. Each fit applies its own level, so a later + fit with a higher ``verbose`` logs more. preset : {"standard", "expanded", "adaptive"} or None, default=None Optional named configuration bundle applied as a transparent alias. A preset only fills in parameters left at their defaults; any parameter set explicitly always wins. @@ -954,7 +958,8 @@ def get_feature_info(self, verbose=True): ---------- verbose : bool, default=True If True, renders an aligned per-feature table through the ``pretab`` - logger (attaching a stream handler when none is configured). If False, + logger (attaching a stream handler when no host handler receives its + records), without lowering a more verbose level set earlier. If False, the info dicts are returned silently. Returns @@ -977,7 +982,8 @@ def get_feature_info(self, verbose=True): ) if verbose: - configure_logging(1) + # Render at INFO without lowering a more verbose level set earlier. + configure_logging(2 if logger.isEnabledFor(logging.DEBUG) else 1) for line in build_transformer_summary( numerical_feature_info, categorical_feature_info, diff --git a/tests/integration/test_verbosity.py b/tests/integration/test_verbosity.py index 3c44e1e..8b44f78 100644 --- a/tests/integration/test_verbosity.py +++ b/tests/integration/test_verbosity.py @@ -6,6 +6,7 @@ :class:`~pretab.PretabWarning`. """ +import contextlib import io import logging import warnings @@ -186,9 +187,30 @@ def test_set_verbosity_sets_logger_level(): assert logger.level == logging.INFO +@contextlib.contextmanager +def _root_handlers(*handlers): + """Run with exactly ``handlers`` on the root logger (none: a plain Python process). + + pytest adds its capture handlers to the root logger when a test body starts, + so this is used inside the test body; the original handlers are restored after. + """ + root = logging.getLogger() + saved = root.handlers[:] + root.handlers = list(handlers) + try: + yield + finally: + root.handlers = saved + + +def _own_handlers(): + return [h for h in logging.getLogger("pretab").handlers if not isinstance(h, logging.NullHandler)] + + def test_configure_logging_attaches_stream_handler_when_none(): logger = logging.getLogger("pretab") - configure_logging(1) + with _root_handlers(): + configure_logging(1) assert any(isinstance(h, logging.StreamHandler) and not isinstance(h, logging.NullHandler) for h in logger.handlers) assert logger.level == logging.INFO @@ -205,6 +227,55 @@ def test_configure_logging_respects_existing_handler(): assert logger.level == logging.CRITICAL +def test_configure_logging_raises_the_level_on_later_calls(): + """Regression guard for issue #67: the first call pinned the verbosity.""" + with _root_handlers(): + configure_logging(1) + configure_logging(2) + assert logging.getLogger("pretab").level == logging.DEBUG + assert len(_own_handlers()) == 1 # the handler is reused, never duplicated + + +def test_fit_verbose_2_after_verbose_1_logs_the_feature_table(sample_data, capsys): + X, y = sample_data + with _root_handlers(): + Preprocessor(numerical_method="ple", verbose=1).fit(X, y) + capsys.readouterr() + Preprocessor(numerical_method="ple", verbose=2).fit(X, y) + err = capsys.readouterr().err + assert "fit complete" in err + assert "pipeline" in err + + +def test_get_feature_info_does_not_lower_a_debug_level(sample_data): + X, y = sample_data + pre = Preprocessor(numerical_method="ple").fit(X, y) + with _root_handlers(): + configure_logging(2) + pre.get_feature_info(verbose=True) + assert logging.getLogger("pretab").level == logging.DEBUG + + +def test_configure_logging_defers_to_a_root_handler(sample_data, capsys): + """Regression guard for issue #67: a host root handler printed every line twice.""" + X, y = sample_data + stream = io.StringIO() # a host root handler, as logging.basicConfig installs + with _root_handlers(logging.StreamHandler(stream)): + Preprocessor(numerical_method="ple", verbose=1).fit(X, y) + assert _own_handlers() == [] + assert stream.getvalue().count("fit complete") == 1 + assert "fit complete" not in capsys.readouterr().err + + +def test_configure_logging_hands_over_to_a_host_configured_later(): + with _root_handlers(): + configure_logging(1) + assert len(_own_handlers()) == 1 + with _root_handlers(logging.StreamHandler(io.StringIO())): + configure_logging(1) + assert _own_handlers() == [] + + # --------------------------------------------------------------------------- # # warning categories (PretabWarning family) # --------------------------------------------------------------------------- #