Skip to content

Commit e1fbc0d

Browse files
deepanshuclickpostdeepanshu406xrmx
authored
fix: Add recursion guard in LoggingHandler.emit to prevent deadlock (#4302)
* fix: Add recursion guard in LoggingHandler.emit to prevent deadlock LoggingHandler.emit() can deadlock when _translate() triggers internal logging (e.g., _clean_extended_attribute calling _logger.warning() for invalid attribute types). The warning re-enters the handler chain on the same thread, creating infinite recursion that prevents the handler lock from ever being released, blocking all other threads. This adds a ContextVar-based guard that detects re-entrant calls to emit() on the same thread and skips the recursive call, preventing the deadlock while preserving all application logs. Fixes open-telemetry/opentelemetry-python#3858 Relates to open-telemetry/opentelemetry-python#3560 Relates to open-telemetry/opentelemetry-python#4585 * Update CHANGELOG.md --------- Co-authored-by: Deepanshu Kartikey <kartikey406@gmail.com> Co-authored-by: Riccardo Magliocchetti <riccardo.magliocchetti@gmail.com>
1 parent 2c758c7 commit e1fbc0d

File tree

3 files changed

+122
-3
lines changed

3 files changed

+122
-3
lines changed

CHANGELOG.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
2626
([#4305](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4305))
2727
- Don't import module in unwrap if not already imported
2828
([#4321](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4321))
29+
- `opentelemetry-instrumentation-logging`: Add recursion guard in LoggingHandler.emit to prevent deadlock
30+
([#4302](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4302))
2931

3032
### Breaking changes
3133

instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/handler.py

Lines changed: 29 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
import logging.config
1919
import threading
2020
import traceback
21+
from contextvars import ContextVar
2122
from time import time_ns
2223
from typing import Callable
2324

@@ -35,6 +36,10 @@
3536
from opentelemetry.semconv.attributes import exception_attributes
3637
from opentelemetry.util.types import _ExtendedAttributes
3738

39+
_internal_logger = logging.getLogger(__name__ + ".internal")
40+
_internal_logger.propagate = False
41+
_internal_logger.addHandler(logging.StreamHandler())
42+
3843

3944
def _setup_logging_handler(
4045
logger_provider: LoggerProvider, log_code_attributes: bool = False
@@ -112,6 +117,8 @@ class LoggingHandler(logging.Handler):
112117
https://docs.python.org/3/library/logging.html
113118
"""
114119

120+
_is_emitting: ContextVar[bool] = ContextVar("_is_emitting", default=False)
121+
115122
def __init__(
116123
self,
117124
level: int = logging.NOTSET,
@@ -203,9 +210,28 @@ def emit(self, record: logging.LogRecord) -> None:
203210
204211
The record is translated to OTel format, and then sent across the pipeline.
205212
"""
206-
logger = get_logger(record.name, logger_provider=self._logger_provider)
207-
if not isinstance(logger, NoOpLogger):
208-
logger.emit(self._translate(record))
213+
# Prevent recursive logging that can cause infinite recursion or deadlock.
214+
# During _translate(), internal OTel code (e.g., _clean_extended_attribute)
215+
# may call _logger.warning() for invalid attributes. If the OTel
216+
# LoggingHandler is in the logger chain, this warning re-enters emit(),
217+
# creating an infinite loop that prevents the handler lock from ever
218+
# being released, blocking all other threads.
219+
# See: https://github.com/open-telemetry/opentelemetry-python/issues/3858
220+
221+
if self._is_emitting.get():
222+
_internal_logger.warning(
223+
"LoggingHandler.emit detected recursive logging, skipping to prevent deadlock."
224+
)
225+
return
226+
token = self._is_emitting.set(True)
227+
try:
228+
logger = get_logger(
229+
record.name, logger_provider=self._logger_provider
230+
)
231+
if not isinstance(logger, NoOpLogger):
232+
logger.emit(self._translate(record))
233+
finally:
234+
self._is_emitting.reset(token)
209235

210236
def flush(self) -> None:
211237
"""
Lines changed: 91 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,91 @@
1+
# Copyright The OpenTelemetry Authors
2+
#
3+
# Licensed under the Apache License, Version 2.0 (the "License");
4+
# you may not use this file except in compliance with the License.
5+
# You may obtain a copy of the License at
6+
#
7+
# http://www.apache.org/licenses/LICENSE-2.0
8+
#
9+
# Unless required by applicable law or agreed to in writing, software
10+
# distributed under the License is distributed on an "AS IS" BASIS,
11+
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12+
# See the License for the specific language governing permissions and
13+
# limitations under the License.
14+
15+
import logging
16+
import threading
17+
import unittest
18+
19+
from opentelemetry.instrumentation.logging.handler import LoggingHandler
20+
from opentelemetry.sdk._logs import LoggerProvider
21+
from opentelemetry.sdk._logs.export import (
22+
InMemoryLogExporter,
23+
SimpleLogRecordProcessor,
24+
)
25+
26+
27+
class TestLoggingHandlerRecursionGuard(unittest.TestCase):
28+
@staticmethod
29+
def _create_handler():
30+
exporter = InMemoryLogExporter()
31+
provider = LoggerProvider()
32+
provider.add_log_record_processor(SimpleLogRecordProcessor(exporter))
33+
handler = LoggingHandler(logger_provider=provider)
34+
return handler, exporter
35+
36+
@staticmethod
37+
def _make_record(msg="test"):
38+
return logging.LogRecord(
39+
name="test",
40+
level=logging.INFO,
41+
pathname="",
42+
lineno=0,
43+
msg=msg,
44+
args=(),
45+
exc_info=None,
46+
)
47+
48+
def test_recursive_emit_is_skipped(self):
49+
"""Recursive emit() should be skipped to prevent deadlock.
50+
Regression test for https://github.com/open-telemetry/opentelemetry-python/issues/3858
51+
"""
52+
handler, exporter = self._create_handler()
53+
token = handler._is_emitting.set(True)
54+
handler.emit(self._make_record("should be skipped"))
55+
self.assertEqual(len(exporter.get_finished_logs()), 0)
56+
handler._is_emitting.reset(token)
57+
58+
def test_normal_emit_works(self):
59+
"""Non-recursive emit() should process logs normally."""
60+
handler, exporter = self._create_handler()
61+
handler.emit(self._make_record("should be captured"))
62+
logs = exporter.get_finished_logs()
63+
self.assertEqual(len(logs), 1)
64+
self.assertEqual(logs[0].log_record.body, "should be captured")
65+
66+
def test_is_emitting_resets_after_emit(self):
67+
"""Context must reset after emit(), allowing subsequent logs."""
68+
handler, exporter = self._create_handler()
69+
handler.emit(self._make_record("first"))
70+
self.assertFalse(handler._is_emitting.get())
71+
handler.emit(self._make_record("second"))
72+
self.assertEqual(len(exporter.get_finished_logs()), 2)
73+
74+
def test_is_emitting_is_isolated_across_threads(self):
75+
"""Emit context on one thread must not block other threads."""
76+
handler, exporter = self._create_handler()
77+
token = handler._is_emitting.set(True)
78+
79+
result = [False]
80+
81+
def log_from_other_thread():
82+
handler.emit(self._make_record("from other thread"))
83+
result[0] = True
84+
85+
thread = threading.Thread(target=log_from_other_thread)
86+
thread.start()
87+
thread.join(timeout=5)
88+
89+
self.assertTrue(result[0], "Other thread should not be blocked")
90+
self.assertEqual(len(exporter.get_finished_logs()), 1)
91+
handler._is_emitting.reset(token)

0 commit comments

Comments
 (0)