diff --git a/benchmarks/README.md b/benchmarks/README.md index 648f39f..1540e8b 100644 --- a/benchmarks/README.md +++ b/benchmarks/README.md @@ -612,7 +612,7 @@ leaves out by default: section 4a has the rerun. The per-call chain is the same on every framework: structlog's stdlib `BoundLogger`, lite-bootstrap's processors, `JSONRenderer` with orjson, stdlib `Logger.info`, `MemoryHandler(capacity=10)` and a -`StreamHandler`. What differs per framework is who logs per request: FastAPI's opt-in access log (1 +`StreamHandler`. 2.0 propagates structlog records to the root logger's `StreamHandler` instead (#381). What differs per framework is who logs per request: FastAPI's opt-in access log (1 record), Litestar's opt-in `LoggingMiddleware` (2 records), FastMCP's opt-in logging middleware (1 record per MCP message), FastStream's own "Received" and "Processed" (filtered at the default `faststream_log_level=WARNING`). @@ -620,7 +620,7 @@ record per MCP message), FastStream's own "Received" and "Processed" (filtered a Linux, a 2-CPU container on the same Apple M2 under OrbStack, CPython 3.14.9, structlog 26.1.0, orjson 3.11.9, sentry-sdk 2.67.1, opentelemetry-sdk 1.44.0. Output to a real `/dev/null` file, 50000 calls per round, loop overhead (0.06 µs) subtracted. The `MemoryHandler` was removed afterwards -(#377), and 2.0 writes through the `StreamHandler` directly; the rows have not been rerun. +(#377), and 2.0 writes through the root `StreamHandler`; the rows have not been rerun. | call | µs/call | |---|---:| diff --git a/docs/introduction/configuration.md b/docs/introduction/configuration.md index 591fd9c..5df4f8b 100644 --- a/docs/introduction/configuration.md +++ b/docs/introduction/configuration.md @@ -336,6 +336,10 @@ Read more about Sentry's profiling options [here](https://docs.sentry.io/platfor Structlog is bootstrapped by default. To opt out, set `logging_enabled=False`. +Structlog and standard-library records go through one handler on the root logger, which writes each +record to stdout as one JSON line. A logger name structlog uses stays an ordinary stdlib logger: its +stdlib records come out as JSON too, and a handler you add to root sees structlog's records. + Configuring it costs almost nothing; the cost arrives per log record, and most of it is Sentry's. See [Performance](performance.md). diff --git a/lite_bootstrap/bootstrappers/faststream_bootstrapper.py b/lite_bootstrap/bootstrappers/faststream_bootstrapper.py index 641c235..b84a1bb 100644 --- a/lite_bootstrap/bootstrappers/faststream_bootstrapper.py +++ b/lite_bootstrap/bootstrappers/faststream_bootstrapper.py @@ -155,6 +155,7 @@ class FastStreamLoggingInstrument(LoggingInstrument[FastStreamConfig]): _prior_faststream_handlers: list[logging.Handler] | None = dataclasses.field( default=None, init=False, repr=False, compare=False ) + _prior_faststream_propagate: bool = dataclasses.field(default=False, init=False, repr=False, compare=False) def bootstrap(self) -> None: super().bootstrap() @@ -162,7 +163,9 @@ def bootstrap(self) -> None: if brokers and import_checker.is_structlog_installed and import_checker.is_faststream_installed: faststream_stdlib_logger = logging.getLogger("faststream") self._prior_faststream_handlers = faststream_stdlib_logger.handlers + self._prior_faststream_propagate = faststream_stdlib_logger.propagate faststream_stdlib_logger.handlers = [] + faststream_stdlib_logger.propagate = True logger = structlog.get_logger("faststream") logger.setLevel(self.bootstrap_config.faststream_log_level) for broker in brokers: @@ -179,7 +182,9 @@ def teardown(self) -> None: super().teardown() finally: if self._prior_faststream_handlers is not None: - logging.getLogger("faststream").handlers = self._prior_faststream_handlers + faststream_stdlib_logger = logging.getLogger("faststream") + faststream_stdlib_logger.handlers = self._prior_faststream_handlers + faststream_stdlib_logger.propagate = self._prior_faststream_propagate self._prior_faststream_handlers = None diff --git a/lite_bootstrap/bootstrappers/litestar_bootstrapper.py b/lite_bootstrap/bootstrappers/litestar_bootstrapper.py index 3b5acc5..e7ce0bd 100644 --- a/lite_bootstrap/bootstrappers/litestar_bootstrapper.py +++ b/lite_bootstrap/bootstrappers/litestar_bootstrapper.py @@ -322,9 +322,7 @@ def _build_standard_lib_logging_config(self) -> "LitestarStandardLoggingConfig": return LitestarStandardLoggingConfig( configure_root_logger=False, handlers={"console": {"class": "logging.NullHandler"}, "queue_listener": {"class": "logging.NullHandler"}}, - loggers={ - "litestar": {"level": self.bootstrap_config.logging_log_level, "handlers": [], "propagate": False} - }, + loggers={"litestar": {"level": self.bootstrap_config.logging_log_level, "handlers": [], "propagate": True}}, ) def _configure_structlog_loggers(self) -> None: @@ -334,7 +332,7 @@ def _configure_structlog_loggers(self) -> None: config=StructlogConfig( structlog_logging_config=StructLoggingConfig( processors=self.structlog_processors, - logger_factory=self.memory_logger_factory, + logger_factory=structlog.stdlib.LoggerFactory(), wrapper_class=structlog.stdlib.BoundLogger, cache_logger_on_first_use=True, pretty_print_tty=False, diff --git a/lite_bootstrap/instruments/logging_factory.py b/lite_bootstrap/instruments/logging_factory.py index 4341a86..6f39722 100644 --- a/lite_bootstrap/instruments/logging_factory.py +++ b/lite_bootstrap/instruments/logging_factory.py @@ -1,7 +1,5 @@ import dataclasses import json -import logging -import sys import typing from lite_bootstrap import import_checker @@ -11,14 +9,6 @@ import orjson -@dataclasses.dataclass(kw_only=True, slots=True, frozen=True) -class _MemoryLoggerFactoryConfig: - logging_log_level: int - # default_factory, not a bare default: a bare one binds sys.stdout at import time, so a - # process that rebinds stdout before bootstrap would keep logging to the stale stream. - log_stream: typing.Any = dataclasses.field(default_factory=lambda: sys.stdout) - - def _dumps_orjson(value: typing.Any, **kwargs: typing.Any) -> str: # noqa: ANN401 return orjson.dumps(value, **kwargs).decode() @@ -77,51 +67,3 @@ def parse(cls, formatted: str) -> "StructuredLogPayload | None": message = loaded.get("event") extra = {key: value for key, value in loaded.items() if key not in STRUCTLOG_META_KEYS} return cls(message=message, extra=extra, skip_sentry=skip_sentry) - - -class _RenderedLineFormatter(logging.Formatter): - """Emit the rendered line verbatim; stdlib appends nothing after it.""" - - def format(self, record: logging.LogRecord) -> str: - return record.getMessage() - - -if import_checker.is_structlog_installed: - import structlog - - class MemoryLoggerFactory(structlog.stdlib.LoggerFactory): - def __init__( - self, - *args: typing.Any, # noqa: ANN401 - config: "_MemoryLoggerFactoryConfig", - **kwargs: typing.Any, # noqa: ANN401 - ) -> None: - kwargs["ignore_frame_names"] = [*(kwargs.get("ignore_frame_names") or ()), __name__] - super().__init__(*args, **kwargs) - self.config = config - self._created_handlers: dict[logging.Logger, logging.StreamHandler[typing.Any]] = {} - self._leveled_loggers: set[logging.Logger] = set() - - def __call__(self, *args: typing.Any) -> logging.Logger: # noqa: ANN401 - logger: typing.Final = super().__call__(*args) - if logger in self._created_handlers: - return logger - handler: typing.Final = logging.StreamHandler(stream=self.config.log_stream) - handler.setFormatter(_RenderedLineFormatter()) - logger.addHandler(handler) - if logger.level == logging.NOTSET: - logger.setLevel(self.config.logging_log_level) - self._leveled_loggers.add(logger) - logger.propagate = False - self._created_handlers[logger] = handler - return logger - - def close_handlers(self) -> None: - for created_logger, handler in self._created_handlers.items(): - created_logger.removeHandler(handler) - created_logger.propagate = True - if created_logger in self._leveled_loggers: - created_logger.setLevel(logging.NOTSET) - handler.close() - self._created_handlers.clear() - self._leveled_loggers.clear() diff --git a/lite_bootstrap/instruments/logging_instrument.py b/lite_bootstrap/instruments/logging_instrument.py index cad35e6..e540996 100644 --- a/lite_bootstrap/instruments/logging_instrument.py +++ b/lite_bootstrap/instruments/logging_instrument.py @@ -6,22 +6,33 @@ from lite_bootstrap import import_checker from lite_bootstrap.exceptions import collect_teardown_errors from lite_bootstrap.instruments.base import BaseConfig, BaseInstrument -from lite_bootstrap.instruments.logging_factory import ( - _MemoryLoggerFactoryConfig, - _serialize_log_to_string, -) +from lite_bootstrap.instruments.logging_factory import _serialize_log_to_string if typing.TYPE_CHECKING: from structlog.typing import EventDict, WrappedLogger - from lite_bootstrap.instruments.logging_factory import MemoryLoggerFactory + +class _RenderedLine(str): + """A line structlog's chain already rendered, which the root handler's formatter emits as is.""" + + __slots__ = () + + +def _mark_rendered(_: "WrappedLogger", __: str, rendered_line: str) -> _RenderedLine: + return _RenderedLine(rendered_line) if import_checker.is_structlog_installed: import structlog - from lite_bootstrap.instruments.logging_factory import MemoryLoggerFactory + class _RenderedLinePassthroughFormatter(structlog.stdlib.ProcessorFormatter): + """Render stdlib records through the foreign chain, and emit structlog's rendered lines verbatim.""" + + def format(self, record: logging.LogRecord) -> str: + if type(record.msg) is _RenderedLine: + return record.msg + return super().format(record) if import_checker.is_opentelemetry_installed: @@ -53,7 +64,6 @@ def tracer_injection(_: "WrappedLogger", __: str, event_dict: "EventDict") -> "E __all__ = [ "LoggingConfig", "LoggingInstrument", - "MemoryLoggerFactory", "tracer_injection", ] @@ -77,9 +87,6 @@ class LoggingConfig(BaseConfig): class LoggingInstrument(BaseInstrument[LoggingConfigT]): not_configured_reason = "logging_enabled is False" missing_dependency_message = "structlog is not installed" - _logger_factory: "MemoryLoggerFactory | None" = dataclasses.field( - default_factory=lambda: 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 ) @@ -139,26 +146,14 @@ def structlog_processors(self) -> list[typing.Any]: *self.structlog_pre_chain_processors, *self.bootstrap_config.logging_extra_processors, structlog.processors.JSONRenderer(serializer=_serialize_log_to_string), + _mark_rendered, ] - @property - def memory_logger_factory(self) -> "MemoryLoggerFactory": - cached: MemoryLoggerFactory | None = self._logger_factory - if cached is None: - config = self.bootstrap_config - cached = MemoryLoggerFactory( - config=_MemoryLoggerFactoryConfig( - logging_log_level=config.logging_log_level, - ), - ) - self._logger_factory = cached - return cached - def _configure_structlog_loggers(self) -> None: structlog.configure( processors=self.structlog_processors, context_class=dict, - logger_factory=self.memory_logger_factory, + logger_factory=structlog.stdlib.LoggerFactory(), wrapper_class=structlog.stdlib.BoundLogger, cache_logger_on_first_use=True, ) @@ -167,7 +162,7 @@ def _configure_foreign_loggers(self) -> None: root_logger: typing.Final = logging.getLogger() stream_handler: typing.Final = logging.StreamHandler(sys.stdout) stream_handler.setFormatter( - structlog.stdlib.ProcessorFormatter( + _RenderedLinePassthroughFormatter( foreign_pre_chain=self.structlog_pre_chain_processors, processors=[ structlog.stdlib.ProcessorFormatter.remove_processors_meta, @@ -207,11 +202,9 @@ def teardown(self) -> None: 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 and from the memory - logger factory's ``close_handlers()`` are collected and re-raised together via - :class:`~lite_bootstrap.exceptions.TeardownError` after the rest of teardown completes, - so no single misbehaving cleanup step prevents the instrument from releasing the - rest of its resources. + 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. """ structlog.reset_defaults() root_logger = logging.getLogger() @@ -224,9 +217,3 @@ def teardown(self) -> None: root_logger.setLevel(logging.WARNING) finally: self._detach_record_filters() - if self._logger_factory is not None: - try: - with teardown_errors.capture("MemoryLoggerFactory"): - self._logger_factory.close_handlers() - finally: - self._logger_factory = None diff --git a/tests/instruments/test_logging_instrument.py b/tests/instruments/test_logging_instrument.py index d109a01..5506525 100644 --- a/tests/instruments/test_logging_instrument.py +++ b/tests/instruments/test_logging_instrument.py @@ -1,6 +1,8 @@ import contextlib import json import logging +import threading +import typing from io import StringIO from unittest.mock import patch @@ -9,8 +11,7 @@ from opentelemetry.trace import get_tracer from lite_bootstrap.exceptions import TeardownError -from lite_bootstrap.instruments.logging_factory import _MemoryLoggerFactoryConfig -from lite_bootstrap.instruments.logging_instrument import LoggingConfig, LoggingInstrument, MemoryLoggerFactory +from lite_bootstrap.instruments.logging_instrument import LoggingConfig, LoggingInstrument from lite_bootstrap.instruments.opentelemetry_instrument import OpenTelemetryConfig, OpenTelemetryInstrument from tests.conftest import LoggingMock @@ -83,70 +84,15 @@ def test_logging_instrument_tracer_injection(logging_mock: LoggingMock) -> None: opentelemetry_instrument.teardown() -def _make_factory(stream: StringIO) -> MemoryLoggerFactory: - return MemoryLoggerFactory( - config=_MemoryLoggerFactoryConfig(logging_log_level=logging.INFO, log_stream=stream), - ) - - -def test_memory_logger_factory_writes_each_line_at_once() -> None: - test_stream = StringIO() - logger_factory = _make_factory(test_stream) - try: - test_logger = logger_factory("written_at_once") - test_logger.info("first") - assert test_stream.getvalue().splitlines() == ["first"] - test_logger.info("second") - assert test_stream.getvalue().splitlines() == ["first", "second"] - assert [type(handler) for handler in test_logger.handlers] == [logging.StreamHandler] - finally: - logger_factory.close_handlers() - - -def test_memory_logger_factory_configures_each_logger_once() -> None: - test_stream = StringIO() - logger_factory = _make_factory(test_stream) - try: - first = logger_factory("configured_once") - second = logger_factory("configured_once") - second.info("one line") - - assert first is second - assert len(first.handlers) == 1 - assert test_stream.getvalue().splitlines() == ["one line"] - finally: - logger_factory.close_handlers() - - assert logging.getLogger("configured_once").handlers == [] - - -def test_memory_logger_factory_names_unnamed_logger_after_caller() -> None: - logger_factory = _make_factory(StringIO()) - try: - assert logger_factory().name == __name__ - finally: - logger_factory.close_handlers() - - -def test_memory_logger_factory_keeps_a_level_set_beforehand() -> None: - preset_logger = logging.getLogger("preset_level") - preset_logger.setLevel(logging.DEBUG) - logger_factory = _make_factory(StringIO()) +def test_unnamed_structlog_logger_is_named_after_its_caller(capsys: pytest.CaptureFixture[str]) -> None: + logging_instrument = LoggingInstrument(bootstrap_config=LoggingConfig()) try: - assert logger_factory("preset_level").level == logging.DEBUG - assert logger_factory("unset_level").level == logging.INFO + logging_instrument.bootstrap() + structlog.getLogger().info("unnamed") finally: - logger_factory.close_handlers() - preset_logger.setLevel(logging.NOTSET) - logging.getLogger("unset_level").setLevel(logging.NOTSET) - - -def test_memory_logger_factory_close_handlers_restores_the_level_it_set() -> None: - logger_factory = _make_factory(StringIO()) - logger_factory("restored_level") - logger_factory.close_handlers() + logging_instrument.teardown() - assert logging.getLogger("restored_level").level == logging.NOTSET + assert json.loads(capsys.readouterr().out)["logger"] == __name__ def test_logging_instrument_lifecycle_replay(logging_mock: LoggingMock) -> None: @@ -166,24 +112,6 @@ def test_logging_instrument_lifecycle_replay(logging_mock: LoggingMock) -> None: instrument.teardown() -def test_logging_instrument_teardown_resets_factory_when_close_handlers_raises() -> None: - instrument = LoggingInstrument( - bootstrap_config=LoggingConfig(), - ) - instrument.bootstrap() - factory = instrument._logger_factory # noqa: SLF001 - assert factory is not None - - with ( - patch.object(factory, "close_handlers", side_effect=RuntimeError("boom")), - pytest.raises(TeardownError) as excinfo, - ): - instrument.teardown() - - assert any("boom" in str(err) for _, err in excinfo.value.errors) - assert instrument._logger_factory is None # noqa: SLF001 - - def test_logging_instrument_teardown_aggregates_handler_close_errors() -> None: instrument = LoggingInstrument( bootstrap_config=LoggingConfig(), @@ -205,36 +133,11 @@ def test_logging_instrument_teardown_aggregates_handler_close_errors() -> None: assert any("boom" in str(err) for _, err in excinfo.value.errors) # After teardown despite the raise, post-loop cleanup must have completed: - assert instrument._logger_factory is None # noqa: SLF001 assert root_logger.level == logging.WARNING # And the broken handler must have been removed from root despite raising. assert target_handler not in root_logger.handlers -def test_logging_instrument_teardown_aggregates_handler_and_factory_errors() -> None: - instrument = LoggingInstrument( - bootstrap_config=LoggingConfig(), - ) - instrument.bootstrap() - root_logger = logging.getLogger() - factory = instrument._logger_factory # noqa: SLF001 - assert factory is not None - - target_handler = next(h for h in root_logger.handlers if isinstance(h, logging.StreamHandler)) - - with ( - patch.object(target_handler, "close", side_effect=RuntimeError("handler boom")), - patch.object(factory, "close_handlers", side_effect=RuntimeError("factory boom")), - pytest.raises(TeardownError) as excinfo, - ): - instrument.teardown() - - error_msgs = [str(err) for _, err in excinfo.value.errors] - assert any("handler boom" in m for m in error_msgs), error_msgs - assert any("factory boom" in m for m in error_msgs), error_msgs - assert instrument._logger_factory is None # noqa: SLF001 - - def test_logging_instrument_binds_log_stream_at_bootstrap() -> None: """The structlog logger writes to the stdout in effect at bootstrap, not the one bound at import.""" redirected_stdout = StringIO() @@ -256,11 +159,10 @@ def test_one_rendered_event_is_one_physical_line(capsys: pytest.CaptureFixture[s before the string ever becomes a `LogRecord`. Everything downstream of that is transport, so the handler must emit the rendered string verbatim. - Dropping the formatter from the stream handler `MemoryLoggerFactory` builds is what breaks it, - and the break is invisible until something raises: stdlib's `Logger.exception` hardcodes - `exc_info=True` on the record, so the default `logging.Formatter` appends `record.exc_text` - after the JSON and the same traceback ships twice. Every line-oriented log shipper reads the - suffix as four malformed events. + The root handler's formatter has to pass that string through. If it treated the record as + foreign, it would render the JSON line again as the `event` of a second JSON object, and + stdlib's `Logger.exception`, which sets `exc_info=True` on the record, would add the same + traceback a second time. """ logging_instrument = LoggingInstrument(bootstrap_config=LoggingConfig()) try: @@ -318,3 +220,54 @@ def test_structlog_lines_are_written_at_once_and_in_order_with_stdlib_lines( logging_instrument.teardown() assert events == ["1", "2", "3"] + + +def test_stdlib_lines_on_a_structlog_logger_name_stay_json(capsys: pytest.CaptureFixture[str]) -> None: + logging_instrument = LoggingInstrument(bootstrap_config=LoggingConfig()) + try: + logging_instrument.bootstrap() + structlog.getLogger("shared_name").info("from structlog") + logging.getLogger("shared_name").info("from stdlib %s", "same name") + logging.getLogger("shared_name.child").info("from stdlib child") + try: + msg = "some error" + raise ValueError(msg) # noqa: TRY301 + except ValueError: + logging.getLogger("shared_name").exception("stdlib exception") + finally: + logging_instrument.teardown() + + payloads = [json.loads(line) for line in capsys.readouterr().out.splitlines()] + + assert [(payload["logger"], payload["event"]) for payload in payloads] == [ + ("shared_name", "from structlog"), + ("shared_name", "from stdlib same name"), + ("shared_name.child", "from stdlib child"), + ("shared_name", "stdlib exception"), + ] + assert "ValueError: some error" in payloads[-1]["exception"] + + +def test_concurrent_first_use_of_a_logger_name_writes_each_line_once(capsys: pytest.CaptureFixture[str]) -> None: + thread_count: typing.Final = 8 + start_barrier: typing.Final = threading.Barrier(thread_count) + + def log_once(thread_number: int) -> None: + start_barrier.wait() + structlog.getLogger("concurrent_first_use").info(f"thread {thread_number}") + + logging_instrument = LoggingInstrument(bootstrap_config=LoggingConfig()) + try: + logging_instrument.bootstrap() + threads = [threading.Thread(target=log_once, args=(number,)) for number in range(thread_count)] + for thread in threads: + thread.start() + for thread in threads: + thread.join() + assert logging.getLogger("concurrent_first_use").handlers == [] + finally: + logging_instrument.teardown() + + events = sorted(json.loads(line)["event"] for line in capsys.readouterr().out.splitlines()) + + assert events == sorted(f"thread {number}" for number in range(thread_count)) diff --git a/tests/test_faststream_bootstrap.py b/tests/test_faststream_bootstrap.py index 5dd9856..5d41db5 100644 --- a/tests/test_faststream_bootstrap.py +++ b/tests/test_faststream_bootstrap.py @@ -1,4 +1,5 @@ import dataclasses +import json import logging import sys import typing @@ -155,9 +156,12 @@ def test_faststream_logging_instrument_injects_structlog_logger(broker: RedisBro bootstrapper.teardown() -def test_faststream_logging_replaces_faststream_stderr_handler(broker: RedisBroker) -> None: +def test_faststream_logging_replaces_faststream_stderr_handler( + broker: RedisBroker, capsys: pytest.CaptureFixture[str] +) -> None: faststream_logger = logging.getLogger("faststream") original_handlers = faststream_logger.handlers[:] + original_propagate = faststream_logger.propagate bootstrapper = FastStreamBootstrapper( bootstrap_config=FastStreamConfig( faststream_log_level=logging.INFO, @@ -167,11 +171,17 @@ def test_faststream_logging_replaces_faststream_stderr_handler(broker: RedisBrok bootstrapper.bootstrap() try: assert not [one for one in faststream_logger.handlers if getattr(one, "stream", None) is sys.stderr] - assert [type(one) for one in faststream_logger.handlers].count(logging.StreamHandler) == 1 + capsys.readouterr() + structlog.get_logger("faststream").info("from structlog") + faststream_logger.info("from stdlib") + logging.getLogger("faststream.child").info("from stdlib child") + payloads = [json.loads(line) for line in capsys.readouterr().out.splitlines()] finally: bootstrapper.teardown() + assert [payload["event"] for payload in payloads] == ["from structlog", "from stdlib", "from stdlib child"] assert faststream_logger.handlers == original_handlers + assert faststream_logger.propagate is original_propagate def test_faststream_config_default_application() -> None: diff --git a/tests/test_litestar_bootstrap.py b/tests/test_litestar_bootstrap.py index 335f3f1..21ebc22 100644 --- a/tests/test_litestar_bootstrap.py +++ b/tests/test_litestar_bootstrap.py @@ -290,8 +290,7 @@ def _recorded_litestar_logs() -> Generator[list[str]]: """Record Litestar's rendered log lines. Enter this inside the TestClient context: Litestar's StructLoggingConfig runs dictConfig at - startup, which drops handlers attached earlier, and MemoryLoggerFactory sets propagate=False, - so the handler has to sit on the "litestar" logger itself. + startup, which drops handlers attached to the "litestar" logger earlier. """ handler = _RecordingHandler() litestar_logger = logging.getLogger("litestar") @@ -331,7 +330,9 @@ def test_litestar_logging_keeps_lite_bootstrap_root_handler(litestar_config: Lit assert any(isinstance(handler.formatter, structlog.stdlib.ProcessorFormatter) for handler in root_handlers) -def test_litestar_access_log_has_one_handler(litestar_config: LitestarConfig) -> None: +def test_litestar_access_log_is_written_once( + litestar_config: LitestarConfig, capsys: pytest.CaptureFixture[str] +) -> None: @litestar.get("/ping") async def _ping_handler() -> dict[str, bool]: return {"ok": True} @@ -343,9 +344,12 @@ async def _ping_handler() -> dict[str, bool]: ) application = LitestarBootstrapper(bootstrap_config=config).bootstrap() with TestClient(app=application) as client: + capsys.readouterr() assert client.get("/ping").status_code == status_codes.HTTP_200_OK - litestar_handlers = logging.getLogger("litestar").handlers - assert [type(handler) for handler in litestar_handlers] == [logging.StreamHandler] + assert logging.getLogger("litestar").handlers == [] + + access_events = [record["event"] for record in _access_log_records(capsys.readouterr().out.splitlines())] + assert sorted(access_events) == ["HTTP Request", "HTTP Response"] def test_litestar_access_logging_disabled_by_default(litestar_config: LitestarConfig) -> None: