Skip to content

gh-150818: Wire logger parent before publishing it in getLogger()#150941

Open
gaborbernat wants to merge 1 commit into
python:mainfrom
gaborbernat:fix/getLogger-fastpath-parent-wiring
Open

gh-150818: Wire logger parent before publishing it in getLogger()#150941
gaborbernat wants to merge 1 commit into
python:mainfrom
gaborbernat:fix/getLogger-fastpath-parent-wiring

Conversation

@gaborbernat
Copy link
Copy Markdown
Contributor

@gaborbernat gaborbernat commented Jun 5, 2026

The lock-free fast path added in GH-150825 reads loggerDict without the lock and returns any non-placeholder logger it finds. The slow path, however, inserted a freshly created logger into loggerDict before calling _fixupParents(), which assigns its parent. A caller hitting the fast path during that window receives a logger whose parent is still None: getEffectiveLevel() returns NOTSET and records do not propagate to ancestors until the creating thread finishes.

Both slow-path branches now publish the logger to loggerDict only after _fixupParents() (and _fixupChildren() for the placeholder case) have wired it. Neither helper reads loggerDict[name], so the move is safe, and the fast path is unchanged.

The added regression test forces the publish/wire interleaving deterministically and fails without this change.

The reorder is confined to the locked creation path, so the fast path is unaffected. Median of 5 runs against GH-150825 as merged (PGO build, same interpreter, swapping Lib/logging/__init__.py):

Benchmark base (GH-150825) patched
getLogger, 23 existing loggers 2.68 us 2.65 us: 1.01x faster

The difference is within the run-to-run noise floor (base 2.66-2.76 us, patched 2.64-2.65 us); pyperf compare_to reports it as not significant.

Benchmark (pyperf)
import logging, pyperf

names = ["elastic_transport.transport", "peewee.pool", "LiteLLM", "httpx",
    "uvicorn.error", "uvicorn.access", "fsspec", "boto3", "posthog", "amqp",
    "nox", "tldextract.cache", "dulwich.lfs", "urllib3.connectionpool",
    "asyncio", "sqlalchemy.engine", "werkzeug", "django.request", "celery.worker",
    "kafka.conn", "redis.client", "paramiko.transport", "matplotlib.font_manager"]
for n in names:
    logging.getLogger(n)

runner = pyperf.Runner()
runner.bench_func("getLogger %d existing loggers" % len(names),
                  lambda: [logging.getLogger(n) for n in names])

Base is Lib/logging/__init__.py at GH-150825; patched swaps in this PR's version on the same interpreter. Run base vs patched with pyperf compare_to base.json patched.json.

Thanks to @methane for catching this in review of GH-150825.

getLogger() returns existing loggers through a lock-free fast path that
reads loggerDict without the lock (added in pythonGH-150825). The slow path
inserted a freshly created logger into loggerDict before _fixupParents()
assigned its parent, so a concurrent caller could fetch a logger whose
parent was still None and see it detached from the hierarchy:
getEffectiveLevel() returns NOTSET and records do not propagate until the
creating thread finishes.

Publish the logger only after its parent and children are wired. Neither
_fixupParents() nor _fixupChildren() reads loggerDict[name], so the
reorder is safe; the fast path is unchanged and confined to the locked
creation path taken once per logger.
@vsajip
Copy link
Copy Markdown
Member

vsajip commented Jun 5, 2026

The new test is failing under Emscripten/WASI due to an inability to start a new thread - I'm not sure if this a transient problem or a platform restriction of those environments. It may be an idea to skip that test in those environments, at least for now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants