Skip to content

fix(logging): let configure_logging raise the level and defer to hosts - #133

Open
ChrisW09 wants to merge 1 commit into
mainfrom
fix/67-configure-logging-level
Open

ChrisW09 wants to merge 1 commit into
mainfrom
fix/67-configure-logging-level

Conversation

@ChrisW09

Copy link
Copy Markdown
Collaborator

Fixes #67.

Only the first configure_logging call in a process set the verbosity, so after a verbose=1 fit or a default get_feature_info() call, later verbose=2 / verbose=3 fits printed only the level-1 summary. Under a host-configured root logger (logging.basicConfig), every PreTab line was printed twice.

Root cause

configure_logging returned early whenever _has_real_handler found a non-NullHandler handler on the "pretab" logger. That included the StreamHandler an earlier call had attached, and the early return also skipped set_verbosity(level). _has_real_handler looked only at the "pretab" logger itself, not at ancestor handlers that receive its records through propagation, so PreTab added its own handler next to a root handler.

Fix

  • configure_logging (pretab/core/logging.py) marks the handler it attaches with a _pretab_own_handler attribute. _has_real_handler now counts only host handlers (_is_host_handler: neither a NullHandler nor PreTab's own).
  • A host handler on the "pretab" logger still makes the call a no-op. Otherwise the level is applied on every call, and PreTab's own handler is reused instead of a second one being added.
  • The new _ancestor_has_real_handler walks up the parent loggers while propagate is true. When a host handler there receives the records, configure_logging attaches no handler and removes one it attached earlier.
  • Preprocessor.get_feature_info(verbose=True) calls configure_logging(2) when DEBUG is already enabled, else configure_logging(1). Now that later calls change the level, rendering the table would otherwise lower a more verbose level.

Behaviour changes

  • Each fit applies its own verbose level, so a later verbose=2 / verbose=3 fit logs the per-feature table and internal decisions after an earlier, less verbose configuration. Repeated configure_logging(level) calls update the "pretab" logger level.
  • With a host handler on an ancestor logger, such as the root handler from logging.basicConfig, PreTab attaches no stream handler and removes one it attached earlier. Messages appear once, through the host's handler and format (INFO:pretab.preprocessor:...). The "pretab" logger level is still set.
  • A handler passed as configure_logging(handler=...) counts as PreTab's own: later calls reuse it, and it is removed once a host handler on an ancestor receives the records.
  • get_feature_info() no longer lowers a DEBUG level set earlier (for example by set_verbosity(2)) to INFO.

Documentation

  • configure_logging docstring: the call is a no-op only for a host handler on the "pretab" logger; repeated calls update the level and reuse PreTab's handler; with a host handler on an ancestor, no handler is attached and one attached earlier is removed.
  • Preprocessor docstring, verbose parameter: a host handler on the "pretab" logger or on an ancestor (a root handler from logging.basicConfig) takes over, and each fit applies its own level.
  • Preprocessor.get_feature_info docstring, verbose parameter: a handler is attached only when no host handler receives the records, and a more verbose level is kept.
  • docs/core_concepts/outputs_and_inspection.md ("Fit-time logging"): new paragraph on per-fit levels and host handlers.

Tests

  • test_configure_logging_raises_the_level_on_later_calls: a second call sets DEBUG and leaves exactly one PreTab handler. Fails on main, passes here.
  • test_fit_verbose_2_after_verbose_1_logs_the_feature_table: a verbose=2 fit after a verbose=1 fit writes the per-feature table to stderr. Fails on main, passes here.
  • test_configure_logging_defers_to_a_root_handler: with a root StreamHandler, a verbose=1 fit logs "fit complete" exactly once through it, nothing on stderr, and attaches no PreTab handler. Fails on main, passes here.
  • test_configure_logging_hands_over_to_a_host_configured_later: PreTab's handler is removed once a root handler appears. Fails on main, passes here.
  • test_get_feature_info_does_not_lower_a_debug_level: get_feature_info() after configure_logging(2) keeps DEBUG. Guard test: passes on both by design (main never changes the first level); it fails with the configure_logging change alone, without the get_feature_info change.
  • The new _root_handlers helper runs a test body with a given set of root handlers, because pytest's capture handlers on the root logger would otherwise count as a host handler. The existing test_configure_logging_attaches_stream_handler_when_none now runs inside it.

Reproduction

Output of the script from #67 on this branch:

# Problem 1
pretab.preprocessor: fit complete: 2 numerical (ple) + 0 categorical (none) feature(s) -> 14 output columns in 0.008s
pretab.preprocessor: fit complete: 2 numerical (ple) + 0 categorical (none) feature(s) -> 14 output columns in 0.002s
pretab.preprocessor: feature  kind       pipeline                   dim   cats
pretab.preprocessor: ---------------------------------------------------------
pretab.preprocessor: a        numerical  imputer -> minmax -> ple     7      -
pretab.preprocessor: b        numerical  imputer -> minmax -> ple     7      -
# Problem 2
INFO:pretab.preprocessor:fit complete: 2 numerical (ple) + 0 categorical (none) feature(s) -> 14 output columns in 0.008s

Each problem runs in a fresh process, as in the issue.

Checks

  • just test: 1443 passed, 59 skipped, 7 xfailed; coverage 93.69% (gate 90%).
  • Minimum dependencies (CI job: Python 3.10, numpy 1.24.4, pandas 2.0.3, scipy 1.10.1, scikit-learn 1.6.0): 1430 passed, 72 skipped, 7 xfailed; scripts/quickstart.py passes.
  • just docs: strict build succeeds.
  • just check: all pre-commit and pre-push hooks pass (ruff format, ruff lint, prettier, file hygiene, pyright with 0 errors).
  • Import direction between subpackages is unchanged.

Merge notes

  • Base: main.
  • None known. Git merges this branch cleanly with each of the other per-issue branches, and none of them adds tests that read PreTab's log output from stderr. Under pytest, the root capture handlers now take over from PreTab's own handler.

This change was previously part of #75, which is closed in favour of one pull request per issue.

configure_logging returned early whenever the 'pretab' logger had any real
handler, so it could not tell PreTab's own stream handler from a host's. The
first configuration pinned the level for the rest of the process (a later
verbose=2 fit only printed the level-1 summary), and under a host-configured
root logger (logging.basicConfig) PreTab still added its own handler, so every
line was printed twice.

PreTab now marks the handler it attaches. A host handler on the 'pretab'
logger still makes the call a no-op; otherwise the level is always applied and
PreTab's handler is reused, not duplicated. When a host handler on an ancestor
already receives the records, no handler is attached and one attached earlier
is removed. get_feature_info() no longer lowers a DEBUG level set earlier.

The verbose and get_feature_info docstrings and the fit-time logging section
of the outputs and inspection guide describe the new behaviour.

Fixes #67

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

configure_logging pins the verbosity level after the first call and duplicates lines under a configured root logger

1 participant