Repository navigation
Propagate structlog records to the root handler and remove MemoryLoggerFactory - #405
Merged
Merged
Conversation
…erFactory Stdlib records on a logger name structlog has used now come out as JSON, and concurrent first use of a name no longer adds a second handler. Closes #381.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #381.
MemoryLoggerFactorygave every stdlib logger that structlog used its ownStreamHandlerand setpropagate = False. Its formatter printedrecord.getMessage()as is, so once structlog had used a logger name, stdlib records on that logger and its children were printed as plain text, with no JSON and no traceback. FastStream hit this out of the box, because it logs throughstructlog.get_logger("faststream"). The check and theaddHandlerwere also not atomic, so concurrent first use of a name could add two handlers and print every line twice.structlog records now propagate to the root handler like any other record, and the factory is gone.
Code
_mark_rendered, afterJSONRenderer. It wraps the rendered line in_RenderedLine, an emptystrsubclass._RenderedLinePassthroughFormatter, aProcessorFormattersubclass. A record whosemsgis a_RenderedLineis emitted as is. Any other record goes through the foreign chain as before.LoggingInstrumentandLitestarLoggingInstrumentpass a plainstructlog.stdlib.LoggerFactory().MemoryLoggerFactory,_MemoryLoggerFactoryConfig,_RenderedLineFormatter,LoggingInstrument.memory_logger_factoryand the factory step inteardownare removed.propagate: Trueon thelitestarlogger. ItsFalsecame from fix: keep lite-bootstrap's root log handler on Litestar and write litestar records once #345, when lite-bootstrap's handler sat on that logger.FastStreamLoggingInstrumentsetspropagate = Trueon thefaststreamlogger after clearing its handlers, and restores the old value at teardown. FastStream ships that logger withpropagate = Falseand a stderr handler, so without this its lines would go nowhere.LoggingInstrumentsets tologging_log_level.Tests
Written first, failing on main:
test_stdlib_lines_on_a_structlog_logger_name_stay_json: the issue's repro. Every line is JSON, and theexceptionline carries the traceback.test_concurrent_first_use_of_a_logger_name_writes_each_line_once: 8 threads use a new name at once. The logger has no handlers, and each line appears once.test_faststream_logging_replaces_faststream_stderr_handlernow logs through structlog, thefaststreamstdlib logger and a child, checks all three reach stdout, and checks that handlers andpropagateare restored.test_litestar_access_log_is_written_oncereplacestest_litestar_access_log_has_one_handler: thelitestarlogger has no handlers, and the access log lines appear once on stdout.The five
test_memory_logger_factory_*tests and the two teardown tests that patchedclose_handlersare removed with the factory.test_unnamed_structlog_logger_is_named_after_its_callerkeeps the one factory behaviour that still matters.The suite passes, 587 tests at 100% coverage (
just test-ci).just lint(includingty),just adr-checkandjust docs-buildpass too. No floor changes.Performance
Per log call, on macOS (Apple M2, CPython 3.14.7), with only lite-bootstrap's handler on root and output to
/dev/null. Each value is the median of 7 rounds of 100,000 calls. Main and this branch were run alternately, 4 rounds each:structlog.get_logger("bench").info("did a thing", a=1)logging.getLogger("lib").info("did a thing %s", 1)One branch round was an outlier at 10.67 µs and 11.66 µs, and is left out of the ranges. A structlog line costs about 0.2 µs more, for the walk up to root and the formatter's type check. A stdlib line costs the same.
I tried passing the flag as
extrafirst. That cost about 0.7 µs per line, sincemakeRecordthen sets eachextrakey on every record. Thestrsubclass costs one string copy instead.benchmarks/frameworks/bench.py loggingcan't show this comparison.one.pycallslogging.basicConfig(stream=_Sink())before every suite, so root has a second handler with a defaultFormatter. structlog records skipped it on main and reach it now, and that sink adds about 2 µs, which is in the harness, not in lite-bootstrap. On main, stdlib records already went through the sink, so the stdlib rows in section 8f include it. Fixing the harness changes the baseline of every suite, so it is not part of this PR.Docs
configuration.md, "Structlog": says both kinds of record go through one root handler, so stdlib lines on a structlog name are JSON and a handler on root sees structlog records.benchmarks/README.md, 8f: the chain description says records go through the root handler.Breaking changes
MemoryLoggerFactory(lite_bootstrap.instruments.logging_instrument) andLoggingInstrument.memory_logger_factoryare removed.litestarlogger propagates to root. On FastStream, thefaststreamlogger propagates to root while bootstrapped.