From 68f6e64d6232236763634135ad1d2e6632559c42 Mon Sep 17 00:00:00 2001 From: Artur Shiriev Date: Tue, 3 Nov 2026 08:22:53 +0300 Subject: [PATCH] Restore root logger state on logging teardown Fixes #388 ## Breaking changes Logging teardown preserves other root handlers and restores the root level from before bootstrap. --- docs/introduction/configuration.md | 5 ++- .../instruments/logging_instrument.py | 29 ++++++++------ tests/instruments/test_logging_instrument.py | 40 ++++++++++++++----- .../test_logging_record_filters.py | 27 +++---------- 4 files changed, 57 insertions(+), 44 deletions(-) diff --git a/docs/introduction/configuration.md b/docs/introduction/configuration.md index 5df4f8b..2ead4ba 100644 --- a/docs/introduction/configuration.md +++ b/docs/introduction/configuration.md @@ -348,7 +348,7 @@ Additional parameters: - `logging_enabled` - whether to configure structlog (default: `True`). - `logging_log_level` - `logging_extra_processors` -- `logging_unset_handlers` +- `logging_unset_handlers` - logger names whose handlers are cleared at bootstrap. These removals are permanent. - `logging_record_filters` - standard-library `logging.Filter` instances to attach to named loggers (see below). - `logging_time_stamper` - a `structlog.processors.TimeStamper` instance controlling timestamp format (default: `TimeStamper(fmt="iso")`). Pass a custom instance to change the format or enable UTC: @@ -361,6 +361,9 @@ config = FastAPIConfig( ) ``` +Teardown removes and closes the root handler installed by lite-bootstrap and restores the root +logger level from before bootstrap. Other root handlers stay attached. + ### Filtering standard-library log records `logging_record_filters` attaches `logging.Filter` instances to loggers by name. A filter sees every diff --git a/lite_bootstrap/instruments/logging_instrument.py b/lite_bootstrap/instruments/logging_instrument.py index 87f8db3..2115459 100644 --- a/lite_bootstrap/instruments/logging_instrument.py +++ b/lite_bootstrap/instruments/logging_instrument.py @@ -83,6 +83,8 @@ class LoggingConfig(BaseConfig): class LoggingInstrument(BaseInstrument[LoggingConfigT]): not_configured_reason = "logging_enabled is False" missing_dependency_message = "structlog is not installed" + _root_handler: logging.Handler | None = dataclasses.field(default=None, init=False, repr=False, compare=False) + _previous_root_level: int | None = dataclasses.field(default=None, init=False, repr=False, compare=False) _attached_filters: list[tuple[logging.Logger, logging.Filter]] = dataclasses.field( default_factory=list, init=False, repr=False, compare=False ) @@ -180,7 +182,9 @@ def _configure_foreign_loggers(self) -> None: logger=root_logger, ) ) + self._previous_root_level = root_logger.level root_logger.addHandler(stream_handler) + self._root_handler = stream_handler root_logger.setLevel(self.bootstrap_config.logging_log_level) def _attach_record_filters(self) -> None: @@ -204,24 +208,23 @@ def bootstrap(self) -> None: self._attach_record_filters() def teardown(self) -> None: - """Reset structlog and root logger. + """Reset structlog, remove the installed handler and filters, and restore the root level. - Root logger level is unconditionally set to WARNING; pre-existing user configuration is overwritten. - Filters from ``logging_record_filters`` are removed one pair at a time, so a filter the - application or another library put on the same logger survives. - - Best-effort cleanup: errors from individual ``handler.close()`` calls are collected and - re-raised together via :class:`~lite_bootstrap.exceptions.TeardownError` after the rest of - teardown completes, so no single misbehaving handler keeps the others open. + Handler removals configured through ``logging_unset_handlers`` are permanent. + Errors from closing the installed handler are reported after the rest of teardown. """ structlog.reset_defaults() root_logger = logging.getLogger() with collect_teardown_errors() as teardown_errors: try: - for h in root_logger.handlers[:]: - root_logger.removeHandler(h) - with teardown_errors.capture(type(h).__name__): - h.close() - root_logger.setLevel(logging.WARNING) + if self._root_handler is not None: + handler = self._root_handler + self._root_handler = None + root_logger.removeHandler(handler) + with teardown_errors.capture(type(handler).__name__): + handler.close() + if self._previous_root_level is not None: + root_logger.setLevel(self._previous_root_level) + self._previous_root_level = None finally: self._detach_record_filters() diff --git a/tests/instruments/test_logging_instrument.py b/tests/instruments/test_logging_instrument.py index 5506525..2aa89fa 100644 --- a/tests/instruments/test_logging_instrument.py +++ b/tests/instruments/test_logging_instrument.py @@ -112,17 +112,41 @@ def test_logging_instrument_lifecycle_replay(logging_mock: LoggingMock) -> None: instrument.teardown() +def test_logging_instrument_teardown_restores_root_logger() -> None: + root_logger = logging.getLogger() + original_handlers = root_logger.handlers[:] + original_level = root_logger.level + existing_handler = logging.StreamHandler(StringIO()) + root_logger.addHandler(existing_handler) + root_logger.setLevel(logging.DEBUG) + instrument = LoggingInstrument(bootstrap_config=LoggingConfig()) + try: + instrument.bootstrap() + (owned_handler,) = set(root_logger.handlers) - {*original_handlers, existing_handler} + with patch.object(existing_handler, "close", wraps=existing_handler.close) as close: + instrument.teardown() + close.assert_not_called() + + assert existing_handler in root_logger.handlers + assert root_logger.level == logging.DEBUG + assert owned_handler not in root_logger.handlers + finally: + for handler in original_handlers: + root_logger.addHandler(handler) + root_logger.removeHandler(existing_handler) + existing_handler.close() + root_logger.setLevel(original_level) + + def test_logging_instrument_teardown_aggregates_handler_close_errors() -> None: instrument = LoggingInstrument( bootstrap_config=LoggingConfig(), ) - instrument.bootstrap() root_logger = logging.getLogger() - - # Find the StreamHandler added by _configure_foreign_loggers and patch its close. - bootstrap_added = [h for h in root_logger.handlers if isinstance(h, logging.StreamHandler)] - assert bootstrap_added, "bootstrap should have added at least one StreamHandler to root" - target_handler = bootstrap_added[0] + previous_level = root_logger.level + existing_handlers = set(root_logger.handlers) + instrument.bootstrap() + (target_handler,) = set(root_logger.handlers) - existing_handlers with ( patch.object(target_handler, "close", side_effect=RuntimeError("boom")), @@ -132,9 +156,7 @@ def test_logging_instrument_teardown_aggregates_handler_close_errors() -> None: assert isinstance(excinfo.value.__cause__, RuntimeError) assert any("boom" in str(err) for _, err in excinfo.value.errors) - # After teardown despite the raise, post-loop cleanup must have completed: - assert root_logger.level == logging.WARNING - # And the broken handler must have been removed from root despite raising. + assert root_logger.level == previous_level assert target_handler not in root_logger.handlers diff --git a/tests/instruments/test_logging_record_filters.py b/tests/instruments/test_logging_record_filters.py index 67bc232..35b3570 100644 --- a/tests/instruments/test_logging_record_filters.py +++ b/tests/instruments/test_logging_record_filters.py @@ -2,6 +2,7 @@ import logging import re import typing +from unittest.mock import patch import faststream.asgi import pytest @@ -284,34 +285,18 @@ def test_teardown_removes_filters_even_when_a_handler_close_fails() -> None: configured_filter = RecordingFilter() target_logger = logging.getLogger("teardown_despite_error.target") - class ExplodingHandler(logging.Handler): - exploded = False - - def emit(self, record: logging.LogRecord) -> None: - """Never called: this handler exists only to fail on close.""" - - def close(self) -> None: - """Fail the first close only: a later logging.shutdown still reaches this handler until it is collected.""" - super().close() - if not self.exploded: - self.exploded = True - msg = "boom" - raise RuntimeError(msg) - instrument = LoggingInstrument( bootstrap_config=LoggingConfig( logging_record_filters={"teardown_despite_error.target": (configured_filter,)}, ), ) + root_logger = logging.getLogger() + existing_handlers = set(root_logger.handlers) instrument.bootstrap() - exploding_handler = ExplodingHandler() - logging.getLogger().addHandler(exploding_handler) + (owned_handler,) = set(root_logger.handlers) - existing_handlers - try: - with pytest.raises(TeardownError): - instrument.teardown() - finally: - logging.getLogger().removeHandler(exploding_handler) + with patch.object(owned_handler, "close", side_effect=RuntimeError("boom")), pytest.raises(TeardownError): + instrument.teardown() assert target_logger.filters == []