Skip to content

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

Merged
vsajip merged 2 commits into
python:mainfrom
gaborbernat:fix/getLogger-fastpath-parent-wiring
Jun 5, 2026
Merged

gh-150818: Wire logger parent before publishing it in getLogger() (GH-150941)#150941
vsajip merged 2 commits 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.

WASI and Emscripten have no working threading, so guard the regression
test with requires_working_threading(), matching the other thread-using
tests in test_logging.
@vsajip vsajip changed the title gh-150818: Wire logger parent before publishing it in getLogger() gh-150818: Wire logger parent before publishing it in getLogger() (GH-150941) Jun 5, 2026
@vsajip vsajip merged commit 3835fca into python:main Jun 5, 2026
53 checks passed
@gaborbernat gaborbernat deleted the fix/getLogger-fastpath-parent-wiring branch June 5, 2026 16:02
@gaborbernat
Copy link
Copy Markdown
Contributor Author

@vsajip not sure if that backport landed but if it did we either need to backport this too, or back out the backports 🤔

@vsajip
Copy link
Copy Markdown
Member

vsajip commented Jun 5, 2026

No, as per discussion on d.p.o, the backport PRs were closed. Thanks for this! I took my eye off the ball a bit with the original PR.

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