fix(sdk): re-instantiate ConcurrentMultiLogRecordProcessor's executor after a fork by Vivek1898 · Pull Request #5774 · open-telemetry/opentelemetry-python

Vivek1898 · 2026-10-12T10:49:33Z

Description

ConcurrentMultiLogRecordProcessor keeps a ThreadPoolExecutor and never
re-instantiates it after a fork. A child inherits the executor's bookkeeping
but none of its worker threads, and the inherited _idle_semaphore still
reports a worker as available — so _adjust_thread_count() starts no thread,
the submitted call is never run, and the child's first emit blocks forever on
future.result(). No exception, no timeout.

ConcurrentMultiSpanProcessor in sdk/trace/__init__.py already handles
exactly this: it holds the pool behind _init_executor() and registers
os.register_at_fork(after_in_child=...) to re-instantiate it, guarded by a
WeakMethod so the processor stays collectable. This applies the same shape to
the logs processor — same helper name, same guard, same comment — so the two
stay consistent.

Scope note: the self._lock guarding add_log_record_processor is also
inherited and could in principle be held at fork time. LoggerProvider
re-creates its own locks in _handle_fork, while ConcurrentMultiSpanProcessor
does not touch its lock. I left it alone to keep this to the reported defect
and consistent with the span twin — happy to add it if you'd like it covered.

Type of change

Bug fix (non-breaking change which fixes an issue)

How Has This Been Tested?

Verified on Linux (the issue is os.fork-only). Python 3.14, running against
the working tree.

The reporter's repro script, unchanged:

before: pid=... emitted parent, before fork then child still blocked after 5s
after: pid=... emitted parent, before fork, pid=... emitted child, child exited

Two tests added in opentelemetry-sdk/tests/logs/test_multi_log_processor.py:

test_emit_in_child_after_fork — runs
scripts/concurrent_multi_log_record_processor_after_fork.py in a
subprocess, mirroring the existing logger_provider_resource_after_fork.py
harness. It asserts the child's own emit ran and that the parent's executor
still works afterwards. Skipped where os.fork/os.register_at_fork are
missing, and it passes a timeout= to subprocess.run so a regression fails
the test instead of hanging CI.
test_init_executor_hands_out_a_fresh_pool — runs everywhere; asserts the
re-instantiation yields a different executor, preserves max_workers, and
that the processor still forwards an emit afterwards.

The fork script talks to its parent over an os.pipe() rather than the shared
stdout, because parent and child writing to one inherited stdout buffer
interleaved non-deterministically while I was building it.

Results: whole file, 15 tests, pass. Both new tests fail without the source
change (the fork one times out on the child's emit, which is the bug).

… after a fork A child inherits the processor's ThreadPoolExecutor bookkeeping but none of its worker threads, and the inherited idle semaphore still reports a worker as available. _adjust_thread_count() therefore starts no thread, the submitted call is never run, and the child's first emit blocks forever on future.result() with no exception and no timeout. ConcurrentMultiSpanProcessor already guards against this by holding the pool behind _init_executor() and re-instantiating it from an os.register_at_fork(after_in_child=...) handler, kept collectable with a WeakMethod. Apply the same shape to the logs processor. Adds a subprocess fork test mirroring the existing logger_provider_resource_after_fork.py harness, and a test that runs everywhere asserting the re-instantiation hands out a fresh pool.

linux-foundation-easycla · 2026-10-12T10:49:41Z

The committers listed above are authorized under a signed CLA.

✅ login: Vivek1898 / name: Vivek Singh (665164b)
✅ login: Vivek1898 / name: Vivek1898 (262a57e, 470a54f, 926b26b)

opentelemetry-pr-dashboard · 2026-10-12T10:50:13Z

Pull request dashboard status

Waiting on reviewers · refreshed 2026-11-05 07:46 UTC

Review the latest changes.

Status above doesn't look right?

Just replied or pushed? Anything around or after the refresh time above may not be picked up yet — give it a few minutes.
Anything look wrong? Report it with what you expected; it helps us improve the dashboard.

JoeyPatricio

Thanks for picking this up. The source change matches ConcurrentMultiSpanProcessor (sdk/trace/__init__.py:238-257), and I agree with leaving _lock alone to stay consistent with it. I ran the new tests on Linux / Python 3.14: 15 pass with the change, and both new tests fail on the parent commit. Two suggestions on the tests inline.

EasyCLA is the only failing check, so it needs signing before this can merge.

JoeyPatricio · 2026-10-15T05:24:10Z

+        script_path = Path(__file__).parent / "scripts" / "concurrent_multi_log_record_processor_after_fork.py"
+
+        try:
+            result = subprocess.run(


On a regression this leaves the hung child running. subprocess.run(timeout=60) kills the script but not the child it forked. I reverted the source change and ran the test, and the child process was still alive after pytest exited. The failure also takes 60s.

Could this mirror test_batch_span_processor_fork in tests/trace/test_span_processor.py? It uses a multiprocessing fork context and a pipe with a 5s poll, and kills the child when nothing comes back. That would also remove the 81-line script.

Taken in 262a57e — answering here too, since I'd only replied in the PR comment and this thread still reads as open.

You were right that subprocess.run(timeout=60) kills the script but not the process the script forked, so a regression left a hung child behind. Rewritten to the test_batch_span_processor_fork shape: fork context, pipe, 5 s poll, process.kill() when nothing comes back. The 81-line script under scripts/ is deleted.

Against the parent commit:

FAILED ...::test_concurrent_multi_log_record_processor_fork E AssertionError: The child process did not send any message after 5 seconds, it's very probably locked 1 failed, 1 passed in 7.64s

7.6 s instead of 60, and nothing survives the run. I kept one point from the old version as a comment: the main process has to emit before the fork so the ThreadPoolExecutor has actually started a worker — otherwise the child inherits an unused pool and the test passes without reaching the defect.

JoeyPatricio · 2026-10-15T05:24:10Z

            self.assertEqual(1, mock.force_flush.call_count)
        multi_log_record_processor.shutdown()
+
+    def test_init_executor_hands_out_a_fresh_pool(self):


This calls the private helper directly, and the fork test already covers what it checks. It also never shuts down the first executor. A test like the span side's test_processor_gc would cover the one part of the change the fork test doesn't, the WeakMethod guard that keeps the processor collectable.

Agreed on both counts, done in 262a57e — replying here as well, since I'd only covered it in the PR comment.

It did duplicate the fork test's coverage and it never shut the first executor down. Replaced with a test_processor_gc mirroring the trace side.

One thing worth stating plainly, because it changes how you read the evidence: that test passes on the parent commit. No fork handler is registered there, so nothing retains the processor. It isn't a second regression test — it guards the WeakMethod specifically, which I verified by mutation rather than assertion:

# weak_reinit = WeakMethod(self._init_executor) -> a strong reference FAILED ...::test_processor_gc E AssertionError: <...ConcurrentMultiLogRecordProcessor object at 0x...> is not None : The ConcurrentMultiLogRecordProcessor object created by this test wasn't garbage collected

So of the two: the fork test pins the bug, the gc test pins the part of the fix the fork test can't see.

…cess The subprocess harness left a hung child running on a regression: subprocess.run(timeout=60) kills the script it launched but not the process that script forked, and the failure took the full 60 s to surface. Use a fork context with a pipe and a 5 s poll, killing the child when nothing comes back, the same shape as test_batch_span_processor_fork on the trace side. The 81-line script is no longer needed. Against the parent commit the test now fails in 7.6 s with "the child process did not send any message after 5 seconds", and leaves nothing behind. Replace the test that called _init_executor directly with a test_processor_gc mirroring the trace side. The old one duplicated what the fork test already covers and never shut its first executor down, while the collectability of the processor was untested: the fork handler lives for the life of the process, so holding _init_executor as anything but a WeakMethod leaks every processor constructed. Swapping the WeakMethod for a strong reference fails the new test; it passes on the parent commit, where no handler is registered at all.

Vivek1898 · 2026-10-16T07:17:18Z

Thanks — both suggestions taken in 262a57e, and both were better than what I had.

The fork test now uses a `multiprocessing` fork context

You were right that subprocess.run(timeout=60) kills the script but not the process the script forked, so a regression left a hung child behind. Rewritten to the test_batch_span_processor_fork shape: fork context, pipe, 5 s poll, process.kill() when nothing comes back. The 81-line script in scripts/ is deleted.

Against the parent commit:

FAILED ...::test_concurrent_multi_log_record_processor_fork
E  AssertionError: The child process did not send any message after 5 seconds, it's very probably locked
1 failed, 1 passed in 7.64s

7.6 s instead of 60, and nothing survives the run. I kept one thing from the old version as a comment: the main process has to emit before the fork, so the ThreadPoolExecutor has actually started a worker — otherwise the child inherits an unused pool and the test passes without reaching the defect at all.

`_init_executor` test replaced with `test_processor_gc`

Agreed on both counts — it duplicated the fork test's coverage and never shut the first executor down. Replaced with a test_processor_gc mirroring the trace side.

One correction worth stating plainly, since it affects how you read the evidence: this test passes on the parent commit, because no fork handler is registered there, so there is nothing to retain the processor. It isn't a second regression test — it guards the WeakMethod specifically. I verified that by mutation rather than claiming it:

# weak_reinit = WeakMethod(self._init_executor)  ->  a strong reference
FAILED ...::test_processor_gc
E  AssertionError: <...ConcurrentMultiLogRecordProcessor object at 0x...> is not None :
   The ConcurrentMultiLogRecordProcessor object created by this test wasn't garbage collected

So of the two tests: the fork test pins the bug, and the gc test pins the part of the fix the fork test can't see. That matches what you asked for, but I didn't want to leave the impression both go red on the parent.

Verification

On Linux / Python 3.14: test_multi_log_processor.py 15 passed in 2.3 s (was dominated by the subprocess spawn), and the whole opentelemetry-sdk/tests/logs/ directory is 122 passed. ruff check and ruff format --check clean at the pinned v0.16.0.

EasyCLA is still the only failing check and is with the account owner.

Vivek1898 · 2026-10-16T13:02:24Z

EasyCLA is signed and now reads pass — "You are authorized to contribute."

That clears the only failing check. One thing I can't do from here: EasyCLA is still the only check that has run on this PR. On other recent PRs (#5772, #5769, #5768) there is also a check job plus the contrib matrix, and none of those have started here — which looks like the first-time-contributor workflow-approval gate rather than anything about the branch. Could someone approve the run so CI actually reports?

State of the PR otherwise, so nothing is waiting on me:

both of @JoeyPatricio's review suggestions taken in 262a57e — the fork test rewritten to the test_batch_span_processor_fork shape (5 s poll, process.kill(), 7.6 s instead of 60 and no surviving child), and the _init_executor test replaced with a test_processor_gc mirroring the trace side
the branch is up to date with main, no conflicts
locally on Linux / Python 3.14: test_multi_log_processor.py 15 passed, the whole opentelemetry-sdk/tests/logs/ 122 passed, ruff check and ruff format --check clean at the pinned v0.16.0

chrikrah

@Vivek1898 I'd merge this at cd7796d. Your parent-commit and strong-reference results reproduce on CPython 3.12 as well as your 3.14.

$ .venv/bin/python -m pytest opentelemetry-sdk/tests/logs -q -p no:cacheprovider   # cd7796d, Linux, CPython 3.12.6
122 passed, 41 warnings, 4 subtests passed in 3.03s

$ .venv/bin/python -m pytest opentelemetry-sdk/tests/logs/test_multi_log_processor.py -q -p no:cacheprovider
# _logs/_internal/__init__.py from 2fa016b (merge base), your tests kept
FAILED opentelemetry-sdk/tests/logs/test_multi_log_processor.py::TestConcurrentMultiLogRecordProcessor::test_concurrent_multi_log_record_processor_fork
1 failed, 14 passed, 2 warnings in 5.33s

# same command, cd7796d with your mutation re-run: WeakMethod(self._init_executor) -> a strong reference
FAILED opentelemetry-sdk/tests/logs/test_multi_log_processor.py::TestConcurrentMultiLogRecordProcessor::test_processor_gc
1 failed, 14 passed, 2 warnings in 0.32s
# not run: tox across the Python matrix, and any platform other than Linux

@emdneto the CI, changelog and Zizmor runs on cd7796d are all waiting on first-time-contributor approval, so EasyCLA is the only check that has reported here. Could you approve them so this can get a maintainer review?

Vivek1898 · 2026-10-23T07:04:02Z

Thanks for reproducing it on 3.12 as well as 3.14 — the strong-reference mutation result is the one I most wanted a second pair of eyes on, since that is the assertion doing the work in test_processor_gc.

To be precise about the head: you reviewed cd7796d, and the current head is ac9fe00a3. The only thing between them is a merge from main (2026-10-22). It touches no file in this fix — not opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py and not opentelemetry-sdk/tests/logs/test_multi_log_processor.py — so your runs still describe the current diff. The branch has gone BEHIND again since; happy to merge main once more if that is wanted, but I would rather not keep adding merge commits unless it blocks something.

Nothing is pending on me:

both of @JoeyPatricio's suggestions taken in 262a57e
EasyCLA signed and passing
the fix and its tests unchanged since your review

The one thing I still cannot do from here is the CI. EasyCLA remains the only check that has reported on this PR; the check job and the contrib matrix that run on other recent PRs have never started here, which looks like the first-time-contributor workflow-approval gate rather than anything about the branch. @emdneto — could someone approve the run so the suite actually reports?

/dashboard route:reviewers

…ulti-log-processor-fork

Vivek1898 · 2026-10-29T07:41:38Z

Merged current main (925ffc8) at c5402dd. Both red checks were the branch being behind, not the change — here is what each one actually was, since neither message says so plainly.

`misc / public-symbols-check`

griffe reported four breakages, and every one of them is in metrics:

opentelemetry-sdk/.../metrics/_internal/export/__init__.py:381: InMemoryMetricReader.__init__(metric_producers): Parameter was removed
opentelemetry-sdk/.../metrics/export/__init__.py:0: MetricProducer: Public object was removed
opentelemetry-sdk/.../metrics/_internal/export/__init__.py:205: MetricReader.__init__(metric_producers): Parameter was removed
opentelemetry-sdk/.../metrics/_internal/export/__init__.py:426: PeriodicExportingMetricReader.__init__(metric_producers): Parameter was removed

This PR touches _logs/_internal/__init__.py and tests/logs/test_multi_log_processor.py and nothing else. scripts/griffe_check.py loads the working tree as base and --against main as against, so "Public object was removed" means present on main, absent in this branch's tree. The branch's merge base was 74544f0 (2026-10-22), from before those symbols were on main, so the check was reporting the gap between the branch's base and main rather than anything in the diff. After the merge, MetricProducer and the three metric_producers parameters are present in the tree and there is nothing for griffe to report.

check is the alls-green gate over misc/lint/tests/contrib. lint, tests and contrib were all green; it failed only because misc did.

`changelog`

.changelog/5774.fixed has been on the branch since cd7796d, so the job's closing line — "No changelog fragment found for this PR" — is the workflow's fallback text, not the finding. The finding is three lines above it:

subprocess.CalledProcessError: Command '['git', 'diff', '--name-only', 'origin/main...']' returned non-zero exit status 128

towncrier check --compare-with origin/main resolves origin/main... through a merge base, and the workflow's "Fetch base branch" step runs git fetch origin "$BASE_REF" --depth=1. At depth 1 that merge base is only reachable when the branch already contains main's tip. It didn't, so git exited 128 and towncrier propagated it. git merge-base HEAD origin/main is now 925ffc8, which is main's tip, so the triple-dot resolves.

What changed in the diff

Nothing. The patch is byte-identical to what you reviewed apart from one hunk header offset:

-@@ -494,6 +494,20 @@ class ConcurrentMultiLogRecordProcessor(LogRecordProcessor):
+@@ -498,6 +498,20 @@ class ConcurrentMultiLogRecordProcessor(LogRecordProcessor):

git diff main...HEAD --stat is still 3 files, +81/−0.

One thing worth flagging rather than leaving for you to find: main has since refactored the same file (110dc14, #5784 — logs perf improvements), and emit now calls self._multi_log_record_processor.enabled(...) and returns early before building the record. That does not short-circuit test_concurrent_multi_log_record_processor_fork, because the test calls multi_log_record_processor.on_emit(...) directly, so it still reaches _submit_and_wait and the executor. I checked that specifically — an early return in Logger.emit is exactly the shape that would have turned this into a test that can no longer reach the defect. ConcurrentMultiLogRecordProcessor.__init__, _submit_and_wait and shutdown are untouched by that refactor.

@chrikrah — the head is now c5402dd; the three files are the same ones you read at cd7796d.

chrikrah

@Vivek1898 still approving at c5402dd. Your point about #5784 holds here: with the new enabled() early return on main, the fork test still fails once the fix is gone.

$ .venv/bin/python -m pytest opentelemetry-sdk/tests/logs -q -p no:cacheprovider   # export of c5402dd, CPython 3.12.6
129 passed, 41 warnings, 8 subtests passed in 5.74s
# _logs/_internal/__init__.py from merge base 925ffc8, your tests kept
$ .venv/bin/python -m pytest opentelemetry-sdk/tests/logs/test_multi_log_processor.py -q -p no:cacheprovider
FAILED ...::TestConcurrentMultiLogRecordProcessor::test_concurrent_multi_log_record_processor_fork
1 failed, 14 passed, 2 warnings in 5.92s
# not run: tox across the Python matrix, platforms other than Linux

I'll re-run it if main moves this file again before a merge.

Vivek1898 · 2026-11-05T07:43:04Z

Thanks for re-running it against c5402dd, and for checking the fork test still fails without the fix now that enabled() returns early on main. That was the one interaction I could not rule out from the diff alone. Nothing is pending on my side; the branch is current with main and the two files are unchanged since your first review.

Vivek1898 requested a review from a team as a code owner October 12, 2026 10:49

otelbot-python Bot added this to Python PR digest Oct 12, 2026

chore: add changelog fragment for open-telemetry#5774

470a54f

opentelemetry-pr-dashboard Bot mentioned this pull request Oct 12, 2026

Pull Request Dashboard #5550

Open

JoeyPatricio reviewed Oct 15, 2026

View reviewed changes

Merge branch 'main' into fix/5770-concurrent-multi-log-processor-fork

665164b

Merge branch 'main' into fix/5770-concurrent-multi-log-processor-fork

cd7796d

chrikrah approved these changes Oct 22, 2026

View reviewed changes

Merge branch 'main' into fix/5770-concurrent-multi-log-processor-fork

ac9fe00

This comment has been minimized.

Sign in to view

Merge remote-tracking branch 'origin/main' into fix/5770-concurrent-m…

c5402dd

…ulti-log-processor-fork

chrikrah approved these changes Nov 5, 2026

View reviewed changes

tammy-baylis-swi moved this to Ready for review in Python PR digest Nov 5, 2026

Conversation

Vivek1898 commented Oct 12, 2026

Description

Type of change

How Has This Been Tested?

Uh oh!

linux-foundation-easycla Bot commented Oct 12, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

opentelemetry-pr-dashboard Bot commented Oct 12, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Pull request dashboard status

Uh oh!

JoeyPatricio left a comment

Choose a reason for hiding this comment

Uh oh!

JoeyPatricio Oct 15, 2026

Choose a reason for hiding this comment

Uh oh!

Vivek1898 Oct 18, 2026

Choose a reason for hiding this comment

Uh oh!

JoeyPatricio Oct 15, 2026

Choose a reason for hiding this comment

Uh oh!

Vivek1898 Oct 18, 2026

Choose a reason for hiding this comment

Uh oh!

Vivek1898 commented Oct 16, 2026

The fork test now uses a multiprocessing fork context

_init_executor test replaced with test_processor_gc

Verification

Uh oh!

Vivek1898 commented Oct 16, 2026

Uh oh!

chrikrah left a comment

Choose a reason for hiding this comment

Uh oh!

Vivek1898 commented Oct 23, 2026

Uh oh!

This comment has been minimized.

Vivek1898 commented Oct 29, 2026

misc / public-symbols-check

changelog

What changed in the diff

Uh oh!

chrikrah left a comment

Choose a reason for hiding this comment

Uh oh!

Vivek1898 commented Nov 5, 2026

Uh oh!

This branch has not been deployed

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

linux-foundation-easycla Bot commented Oct 12, 2026 •

edited

Loading

opentelemetry-pr-dashboard Bot commented Oct 12, 2026 •

edited

Loading

The fork test now uses a `multiprocessing` fork context

`_init_executor` test replaced with `test_processor_gc`

`misc / public-symbols-check`

`changelog`