Skip to content

Commit cfb7650

Browse files
authored
fix(logging): bind the memory logger's stream at bootstrap (#166)
_MemoryLoggerFactoryConfig.log_stream defaulted to a bare sys.stdout, evaluated once at module import, so every MemoryLoggerFactory handler wrote to whatever sys.stdout was at import time. A process that rebound sys.stdout before bootstrapping kept logging structlog output to the stale stream, while the root-logger handler created at bootstrap followed the new one. Resolving it through a default_factory moves the lookup to bootstrap, where the root handler already binds, so both paths agree. Affects every bootstrapper; behavior is unchanged when nothing rebinds sys.stdout. See planning/changes/2026-08-10.02-log-stream-bind-at-bootstrap.md
1 parent e062f66 commit cfb7650

5 files changed

Lines changed: 51 additions & 9 deletions

File tree

‎architecture/instruments.md‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,13 @@ scoped to one job. It holds `MemoryLoggerFactory`, `_MemoryLoggerFactoryConfig`,
4747
the orjson structlog serializer, and the ASGI `AddressProtocol` /
4848
`RequestProtocol` typing protocols.
4949

50+
`_MemoryLoggerFactoryConfig.log_stream` resolves `sys.stdout` through a
51+
`default_factory`, so the stream is bound when the instrument bootstraps rather
52+
than when the module is imported. A process that rebinds `sys.stdout` before
53+
bootstrap — `contextlib.redirect_stdout`, a supervisor, a test harness — is
54+
honored, and the structlog path agrees with the root-logger handler
55+
`_configure_foreign_loggers` installs at the same moment.
56+
5057
## Optional-dependency guard
5158

5259
Optional packages stay optional. `lite_bootstrap/import_checker.py` exposes

‎lite_bootstrap/instruments/logging_factory.py‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,9 @@ class _MemoryLoggerFactoryConfig:
3131
logging_buffer_capacity: int
3232
logging_flush_level: int
3333
logging_log_level: int
34-
log_stream: typing.Any = sys.stdout
34+
# default_factory, not a bare default: a bare one binds sys.stdout at import time, so a
35+
# process that rebinds stdout before bootstrap would keep logging to the stale stream.
36+
log_stream: typing.Any = dataclasses.field(default_factory=lambda: sys.stdout)
3537

3638

3739
def _dumps_orjson(value: typing.Any, **kwargs: typing.Any) -> str: # noqa: ANN401

‎planning/changes/2026-08-10.02-log-stream-bind-at-bootstrap.md‎

Lines changed: 21 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
---
2-
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).
2+
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.
33
---
44

55
# Change: Bind the memory logger's stream at bootstrap, not at import
@@ -54,21 +54,34 @@ between import and bootstrap.
5454

5555
- `lite_bootstrap/instruments/logging_factory.py` — `log_stream` gains a `default_factory`.
5656
- `tests/instruments/test_logging_instrument.py` — test added.
57+
- `architecture/instruments.md` — records the bootstrap-time binding.
58+
- `planning/releases/1.4.0.md` — bug-fix entry (1.4.0 is written but not yet tagged).
5759

5860
## Verification
5961

60-
- [ ] Failing test first: bootstrap a `FreeBootstrapper` inside
62+
- [x] Failing test first: bootstrap a `LoggingInstrument` inside
6163
`contextlib.redirect_stdout(io.StringIO())`, log one line, assert it lands
62-
in the buffer. Command: `just test -k "log_stream"`. Expected failure: the
63-
buffer is empty because the line went to the import-time stdout.
64-
- [ ] Apply the change.
65-
- [ ] Test passes — `just test -k "log_stream"`.
66-
- [ ] `just test` — full suite green, coverage still 100%.
67-
- [ ] `just lint` — clean.
64+
in the buffer. Command: `just test -k "binds_log_stream"`. Observed failure:
65+
the buffer was empty while pytest's own captured stdout held the line.
66+
- [x] Apply the change.
67+
- [x] Test passes — `just test -k "binds_log_stream"`.
68+
- [x] `just test` — 230 passed, coverage 100%.
69+
- [x] `just lint-ci` — clean.
70+
71+
The test drives `LoggingInstrument` directly rather than `FreeBootstrapper`: it
72+
lives in `tests/instruments/test_logging_instrument.py` next to the other
73+
factory tests, and the instrument is what owns the stream.
6874

6975
## Notes
7076

7177
Found while fixing the Litestar access-log body leak
7278
(`planning/changes/2026-08-10.01-litestar-middleware-logging.md`), which is
7379
where the test-capture consequence is documented. Deliberately left out of that
7480
change to keep a security fix unencumbered.
81+
82+
That consequence is now obsolete: with the stream resolved at bootstrap,
83+
`capsys` does observe structlog output in a test that bootstraps inside the test
84+
body (verified). `2026-08-10.01`'s Testing section describes what was true when
85+
it shipped and is left as written — the access-logging tests keep recording
86+
through a handler on the `litestar` logger, which is more precise than reading
87+
captured stdout and does not depend on pytest's capture mode.

‎planning/releases/1.4.0.md‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -91,6 +91,11 @@ warning — set the flag to actually turn logging on.
9191
field themselves. The bootstrapper now fills it when the config leaves it unset; a
9292
caller's own value, including an explicit `None` for no limit, is untouched. Reported
9393
upstream as [litestar#4296](https://github.com/litestar-org/litestar/issues/4296).
94+
- **Structlog output follows a redirected stdout.** `_MemoryLoggerFactoryConfig.log_stream`
95+
bound `sys.stdout` once, at import time, so a process that replaced `sys.stdout` after
96+
importing `lite_bootstrap` but before bootstrapping kept logging to the stale stream —
97+
while the root-logger handler installed at bootstrap followed the new one. The stream is
98+
now resolved at bootstrap, so both agree. Affects every bootstrapper.
9499
- **The `litestar` extra's floor moved from `>=2.9` to `>=2.15`.** `AppConfig.request_max_body_size`,
95100
which the fix above now reads, was only added in litestar 2.13; and
96101
`litestar.middleware.ASGIMiddleware`, which the OpenTelemetry middleware already subclassed

‎tests/instruments/test_logging_instrument.py‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,4 @@
1+
import contextlib
12
import logging
23
from io import StringIO
34
from unittest.mock import patch
@@ -212,3 +213,17 @@ def test_logging_instrument_teardown_aggregates_handler_and_factory_errors() ->
212213
assert any("handler boom" in m for m in error_msgs), error_msgs
213214
assert any("factory boom" in m for m in error_msgs), error_msgs
214215
assert instrument._logger_factory is None # noqa: SLF001
216+
217+
218+
def test_logging_instrument_binds_log_stream_at_bootstrap() -> None:
219+
"""The memory logger writes to the stdout in effect at bootstrap, not the one bound at import."""
220+
redirected_stdout = StringIO()
221+
logging_instrument = LoggingInstrument(bootstrap_config=LoggingConfig(logging_buffer_capacity=0))
222+
try:
223+
with contextlib.redirect_stdout(redirected_stdout):
224+
logging_instrument.bootstrap()
225+
structlog.getLogger("log_stream_binding").info("bound at bootstrap")
226+
finally:
227+
logging_instrument.teardown()
228+
229+
assert "bound at bootstrap" in redirected_stdout.getvalue()

0 commit comments

Comments
 (0)