Skip to content

fix: remove FastStream's stderr handler while lite-bootstrap logs FastStream records - #346

Merged
lesnik512 merged 1 commit into
mainfrom
fix-faststream-duplicate-handler
Oct 28, 2026
Merged

lesnik512 merged 1 commit into
mainfrom
fix-faststream-duplicate-handler

Conversation

@lesnik512

Copy link
Copy Markdown
Member

Fixes #336.

At import time, FastStream puts a StreamHandler(sys.stderr) with its own text format on the faststream logger. FastStreamLoggingInstrument hands brokers structlog.get_logger("faststream"), and lite-bootstrap's logger factory then adds its MemoryHandler to that same stdlib logger without removing FastStream's handler. As a result, every FastStream record was written twice: once as lite-bootstrap JSON on stdout and once in FastStream's format on stderr.

With this change, FastStreamLoggingInstrument.bootstrap saves the handlers already on the faststream logger and clears them before lite-bootstrap's handler goes on. teardown() puts them back after the parent teardown has closed lite-bootstrap's handler, so a torn-down process logs the way it did before bootstrap. Nothing changes when the application has no brokers, because the instrument leaves the logger alone in that case.

The issue also raised clearing existing handlers in MemoryLoggerFactory.__call__ for every logger it creates. I didn't do that, because it would reach into loggers lite-bootstrap does not own.

Test, written first and failing on main:

  • test_faststream_logging_replaces_faststream_stderr_handler: while bootstrapped, the faststream logger has no handler writing to sys.stderr and has exactly one MemoryHandler. After teardown, its handlers are the ones it had before. The test doesn't compare the full handler list, because pytest attaches its own capture handlers to that logger.

Measured with benchmarks/frameworks on macOS (Apple M2, CPython 3.14) against a local Redis, in-process, per consumed message. Both columns use the same venv with only this file swapped, over 3 interleaved runs of 5 repeats:

scenario main this branch
log (default faststream_log_level=WARNING, nothing logged) 46.8 µs 46.8 µs
log_info (faststream_log_level=logging.INFO, 2 records per message) 84.6 µs 72.2 µs

That saves about 12 µs per message, or 6 µs per record. #336's Linux prototype measured 10 µs. The +35.2 FastStream row and the paragraph after the consume table in benchmarks/README.md describe main at the commit they were measured on. I left them as they are, as #345 did for its Litestar rows, until the next Linux run.

Checked locally:

  • Lint and ty are clean, all 393 tests pass, and coverage is 100%.
  • The floors steps for the FastStream target pass on 3.11 and 3.14 (faststream 0.6.0).

Behaviour change: FastStream's colourized lines on stderr stop while lite-bootstrap is bootstrapped with brokers. The same records still come out as lite-bootstrap JSON on stdout. The logging_unset_handlers=["faststream"] workaround is no longer needed, and it still works. No config changes.

…tStream records

FastStream puts a StreamHandler(sys.stderr) on the faststream logger at import time, and the MemoryHandler lite-bootstrap adds sat next to it, so every FastStream record was written twice. Take the existing handlers off while bootstrapped and put them back on teardown.

Fixes #336.
@lesnik512
lesnik512 merged commit 8b12711 into main Oct 28, 2026
35 checks passed
@lesnik512
lesnik512 deleted the fix-faststream-duplicate-handler branch October 28, 2026 07:05
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.

FastStream keeps its own stderr handler next to lite-bootstrap's, so every FastStream log line is written twice

1 participant