diff --git a/architecture/instruments.md b/architecture/instruments.md index e2c4a28..024283c 100644 --- a/architecture/instruments.md +++ b/architecture/instruments.md @@ -47,6 +47,13 @@ scoped to one job. It holds `MemoryLoggerFactory`, `_MemoryLoggerFactoryConfig`, the orjson structlog serializer, and the ASGI `AddressProtocol` / `RequestProtocol` typing protocols. +`_MemoryLoggerFactoryConfig.log_stream` resolves `sys.stdout` through a +`default_factory`, so the stream is bound when the instrument bootstraps rather +than when the module is imported. A process that rebinds `sys.stdout` before +bootstrap — `contextlib.redirect_stdout`, a supervisor, a test harness — is +honored, and the structlog path agrees with the root-logger handler +`_configure_foreign_loggers` installs at the same moment. + ## Optional-dependency guard Optional packages stay optional. `lite_bootstrap/import_checker.py` exposes diff --git a/lite_bootstrap/instruments/logging_factory.py b/lite_bootstrap/instruments/logging_factory.py index 1121739..49dd964 100644 --- a/lite_bootstrap/instruments/logging_factory.py +++ b/lite_bootstrap/instruments/logging_factory.py @@ -31,7 +31,9 @@ class _MemoryLoggerFactoryConfig: logging_buffer_capacity: int logging_flush_level: int logging_log_level: int - log_stream: typing.Any = sys.stdout + # 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 diff --git a/planning/changes/2026-08-10.02-log-stream-bind-at-bootstrap.md b/planning/changes/2026-08-10.02-log-stream-bind-at-bootstrap.md index 87aa0af..e3ddd56 100644 --- a/planning/changes/2026-08-10.02-log-stream-bind-at-bootstrap.md +++ b/planning/changes/2026-08-10.02-log-stream-bind-at-bootstrap.md @@ -1,5 +1,5 @@ --- -summary: Resolve `_MemoryLoggerFactoryConfig.log_stream` at bootstrap instead of at import, so structlog output follows a stdout the process rebinds after importing `lite_bootstrap` (the root-logger handler already does). +summary: `_MemoryLoggerFactoryConfig.log_stream` now resolves `sys.stdout` through a `default_factory`, so the memory logger binds the stream at bootstrap instead of at import and structlog output follows a stdout the process rebinds — matching the root-logger handler installed at the same moment. --- # Change: Bind the memory logger's stream at bootstrap, not at import @@ -54,17 +54,23 @@ between import and bootstrap. - `lite_bootstrap/instruments/logging_factory.py` — `log_stream` gains a `default_factory`. - `tests/instruments/test_logging_instrument.py` — test added. +- `architecture/instruments.md` — records the bootstrap-time binding. +- `planning/releases/1.4.0.md` — bug-fix entry (1.4.0 is written but not yet tagged). ## Verification -- [ ] Failing test first: bootstrap a `FreeBootstrapper` inside +- [x] Failing test first: bootstrap a `LoggingInstrument` inside `contextlib.redirect_stdout(io.StringIO())`, log one line, assert it lands - in the buffer. Command: `just test -k "log_stream"`. Expected failure: the - buffer is empty because the line went to the import-time stdout. -- [ ] Apply the change. -- [ ] Test passes — `just test -k "log_stream"`. -- [ ] `just test` — full suite green, coverage still 100%. -- [ ] `just lint` — clean. + in the buffer. Command: `just test -k "binds_log_stream"`. Observed failure: + the buffer was empty while pytest's own captured stdout held the line. +- [x] Apply the change. +- [x] Test passes — `just test -k "binds_log_stream"`. +- [x] `just test` — 230 passed, coverage 100%. +- [x] `just lint-ci` — clean. + +The test drives `LoggingInstrument` directly rather than `FreeBootstrapper`: it +lives in `tests/instruments/test_logging_instrument.py` next to the other +factory tests, and the instrument is what owns the stream. ## Notes @@ -72,3 +78,10 @@ Found while fixing the Litestar access-log body leak (`planning/changes/2026-08-10.01-litestar-middleware-logging.md`), which is where the test-capture consequence is documented. Deliberately left out of that change to keep a security fix unencumbered. + +That consequence is now obsolete: with the stream resolved at bootstrap, +`capsys` does observe structlog output in a test that bootstraps inside the test +body (verified). `2026-08-10.01`'s Testing section describes what was true when +it shipped and is left as written — the access-logging tests keep recording +through a handler on the `litestar` logger, which is more precise than reading +captured stdout and does not depend on pytest's capture mode. diff --git a/planning/releases/1.4.0.md b/planning/releases/1.4.0.md index 74bd2f0..f741d5a 100644 --- a/planning/releases/1.4.0.md +++ b/planning/releases/1.4.0.md @@ -91,6 +91,11 @@ warning — set the flag to actually turn logging on. field themselves. The bootstrapper now fills it when the config leaves it unset; a caller's own value, including an explicit `None` for no limit, is untouched. Reported upstream as [litestar#4296](https://github.com/litestar-org/litestar/issues/4296). +- **Structlog output follows a redirected stdout.** `_MemoryLoggerFactoryConfig.log_stream` + bound `sys.stdout` once, at import time, so a process that replaced `sys.stdout` after + importing `lite_bootstrap` but before bootstrapping kept logging to the stale stream — + while the root-logger handler installed at bootstrap followed the new one. The stream is + now resolved at bootstrap, so both agree. Affects every bootstrapper. - **The `litestar` extra's floor moved from `>=2.9` to `>=2.15`.** `AppConfig.request_max_body_size`, which the fix above now reads, was only added in litestar 2.13; and `litestar.middleware.ASGIMiddleware`, which the OpenTelemetry middleware already subclassed diff --git a/tests/instruments/test_logging_instrument.py b/tests/instruments/test_logging_instrument.py index d0cff51..e0410a5 100644 --- a/tests/instruments/test_logging_instrument.py +++ b/tests/instruments/test_logging_instrument.py @@ -1,3 +1,4 @@ +import contextlib import logging from io import StringIO from unittest.mock import patch @@ -212,3 +213,17 @@ def test_logging_instrument_teardown_aggregates_handler_and_factory_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 memory logger writes to the stdout in effect at bootstrap, not the one bound at import.""" + redirected_stdout = StringIO() + logging_instrument = LoggingInstrument(bootstrap_config=LoggingConfig(logging_buffer_capacity=0)) + try: + with contextlib.redirect_stdout(redirected_stdout): + logging_instrument.bootstrap() + structlog.getLogger("log_stream_binding").info("bound at bootstrap") + finally: + logging_instrument.teardown() + + assert "bound at bootstrap" in redirected_stdout.getvalue()