Skip to content

Commit c56d46c

Browse files
DylanRussellJWinermaSplunk
authored andcommitted
Fix issue where deadlock can occur over logging._lock (open-telemetry#4636)
* Fix deadlock bug * Overwrite logging config functions with patched versions.. * Some change * Run precommit * change emit to on_emit * Fix lint issues * Add changelog * Get rid of test that may deadlock and flushOnClose approach * Run precommit * Respond to comments on PR * Respond to review comments.. * Add comment * Fix tests, add comment
1 parent 27652bd commit c56d46c

4 files changed

Lines changed: 157 additions & 83 deletions

File tree

CHANGELOG.md

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
77

88
## Unreleased
99

10+
- Overwrite logging.config.fileConfig and logging.config.dictConfig to ensure
11+
the OTLP `LogHandler` remains attached to the root logger. Fix a bug that
12+
can cause a deadlock to occur over `logging._lock` in some cases ([#4636](https://github.com/open-telemetry/opentelemetry-python/pull/4636)).
13+
1014
## Version 1.35.0/0.56b0 (2025-07-11)
1115

1216
- Update OTLP proto to v1.7 [#4645](https://github.com/open-telemetry/opentelemetry-python/pull/4645).

opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py

Lines changed: 28 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020
from __future__ import annotations
2121

2222
import logging
23+
import logging.config
2324
import os
2425
from abc import ABC, abstractmethod
2526
from os import environ
@@ -286,39 +287,37 @@ def _init_logging(
286287
set_event_logger_provider(event_logger_provider)
287288

288289
if setup_logging_handler:
289-
_patch_basic_config()
290-
291-
# Log Handler
292-
root_logger = logging.getLogger()
293-
handler = LoggingHandler(logger_provider=provider)
294-
# Log level
295-
if OTEL_PYTHON_LOG_LEVEL in environ:
296-
handler.setLevel(_get_log_level())
297-
# Log format
298-
if OTEL_PYTHON_LOG_FORMAT in environ:
299-
log_format = environ.get(
300-
OTEL_PYTHON_LOG_FORMAT, logging.BASIC_FORMAT
301-
)
302-
handler.setFormatter(logging.Formatter(log_format))
303-
root_logger.addHandler(handler)
290+
# Add OTel handler
291+
handler = LoggingHandler(
292+
level=logging.NOTSET, logger_provider=provider
293+
)
294+
logging.getLogger().addHandler(handler)
295+
_overwrite_logging_config_fns(handler)
304296

305297

306-
def _patch_basic_config():
307-
original_basic_config = logging.basicConfig
298+
def _overwrite_logging_config_fns(handler: LoggingHandler) -> None:
299+
root = logging.getLogger()
308300

309-
def patched_basic_config(*args, **kwargs):
310-
root = logging.getLogger()
311-
has_only_otel = len(root.handlers) == 1 and isinstance(
312-
root.handlers[0], LoggingHandler
313-
)
314-
if has_only_otel:
315-
otel_handler = root.handlers.pop()
316-
original_basic_config(*args, **kwargs)
317-
root.addHandler(otel_handler)
318-
else:
319-
original_basic_config(*args, **kwargs)
301+
def wrapper(config_fn: Callable) -> Callable:
302+
def overwritten_config_fn(*args, **kwargs):
303+
removed_handler = False
304+
# We don't want the OTLP handler to be modified or deleted by the logging config functions.
305+
# So we remove it and then add it back after the function call.
306+
if handler in root.handlers:
307+
removed_handler = True
308+
root.handlers.remove(handler)
309+
try:
310+
config_fn(*args, **kwargs)
311+
finally:
312+
# Ensure handler is added back if logging function throws exception.
313+
if removed_handler:
314+
root.addHandler(handler)
315+
316+
return overwritten_config_fn
320317

321-
logging.basicConfig = patched_basic_config
318+
logging.config.fileConfig = wrapper(logging.config.fileConfig)
319+
logging.config.dictConfig = wrapper(logging.config.dictConfig)
320+
logging.basicConfig = wrapper(logging.basicConfig)
322321

323322

324323
def _import_exporters(

opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -648,7 +648,10 @@ def flush(self) -> None:
648648
if hasattr(self._logger_provider, "force_flush") and callable(
649649
self._logger_provider.force_flush
650650
):
651-
self._logger_provider.force_flush()
651+
# This is done in a separate thread to avoid a potential deadlock, for
652+
# details see https://github.com/open-telemetry/opentelemetry-python/pull/4636.
653+
thread = threading.Thread(target=self._logger_provider.force_flush)
654+
thread.start()
652655

653656

654657
class Logger(APILogger):

opentelemetry-sdk/tests/test_configurator.py

Lines changed: 121 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,8 @@
1616
from __future__ import annotations
1717

1818
import logging
19+
import logging.config
20+
from logging import WARNING, getLogger
1921
from logging import (
2022
DEBUG,
2123
ERROR,
@@ -653,62 +655,65 @@ def tearDown(self):
653655
]
654656

655657
def test_logging_init_empty(self):
656-
auto_resource = Resource.create(
657-
{
658-
"telemetry.auto.version": "auto-version",
659-
}
660-
)
661-
_init_logging({}, resource=auto_resource)
662-
self.assertEqual(self.set_provider_mock.call_count, 1)
663-
provider = self.set_provider_mock.call_args[0][0]
664-
self.assertIsInstance(provider, DummyLoggerProvider)
665-
self.assertIsInstance(provider.resource, Resource)
666-
self.assertEqual(
667-
provider.resource.attributes.get("telemetry.auto.version"),
668-
"auto-version",
669-
)
670-
self.event_logger_provider_mock.assert_called_once_with(
671-
logger_provider=provider
672-
)
673-
self.set_event_logger_provider_mock.assert_called_once_with(
674-
self.event_logger_provider_instance_mock
675-
)
658+
with ResetGlobalLoggingState():
659+
auto_resource = Resource.create(
660+
{
661+
"telemetry.auto.version": "auto-version",
662+
}
663+
)
664+
_init_logging({}, resource=auto_resource)
665+
self.assertEqual(self.set_provider_mock.call_count, 1)
666+
provider = self.set_provider_mock.call_args[0][0]
667+
self.assertIsInstance(provider, DummyLoggerProvider)
668+
self.assertIsInstance(provider.resource, Resource)
669+
self.assertEqual(
670+
provider.resource.attributes.get("telemetry.auto.version"),
671+
"auto-version",
672+
)
673+
self.event_logger_provider_mock.assert_called_once_with(
674+
logger_provider=provider
675+
)
676+
self.set_event_logger_provider_mock.assert_called_once_with(
677+
self.event_logger_provider_instance_mock
678+
)
676679

677680
@patch.dict(
678681
environ,
679682
{"OTEL_RESOURCE_ATTRIBUTES": "service.name=otlp-service"},
680683
)
681684
def test_logging_init_exporter(self):
682-
resource = Resource.create({})
683-
_init_logging({"otlp": DummyOTLPLogExporter}, resource=resource)
684-
self.assertEqual(self.set_provider_mock.call_count, 1)
685-
provider = self.set_provider_mock.call_args[0][0]
686-
self.assertIsInstance(provider, DummyLoggerProvider)
687-
self.assertIsInstance(provider.resource, Resource)
688-
self.assertEqual(
689-
provider.resource.attributes.get("service.name"),
690-
"otlp-service",
691-
)
692-
self.assertIsInstance(provider.processor, DummyLogRecordProcessor)
693-
self.assertIsInstance(
694-
provider.processor.exporter, DummyOTLPLogExporter
695-
)
696-
getLogger(__name__).error("hello")
697-
self.assertTrue(provider.processor.exporter.export_called)
685+
with ResetGlobalLoggingState():
686+
resource = Resource.create({})
687+
_init_logging({"otlp": DummyOTLPLogExporter}, resource=resource)
688+
self.assertEqual(self.set_provider_mock.call_count, 1)
689+
provider = self.set_provider_mock.call_args[0][0]
690+
self.assertIsInstance(provider, DummyLoggerProvider)
691+
self.assertIsInstance(provider.resource, Resource)
692+
self.assertEqual(
693+
provider.resource.attributes.get("service.name"),
694+
"otlp-service",
695+
)
696+
self.assertIsInstance(provider.processor, DummyLogRecordProcessor)
697+
self.assertIsInstance(
698+
provider.processor.exporter, DummyOTLPLogExporter
699+
)
700+
getLogger(__name__).error("hello")
701+
self.assertTrue(provider.processor.exporter.export_called)
698702

699703
def test_logging_init_exporter_uses_exporter_args_map(self):
700-
resource = Resource.create({})
701-
_init_logging(
702-
{"otlp": DummyOTLPLogExporter},
703-
resource=resource,
704-
exporter_args_map={
705-
DummyOTLPLogExporter: {"compression": "gzip"},
706-
DummyOTLPMetricExporter: {"compression": "no"},
707-
},
708-
)
709-
self.assertEqual(self.set_provider_mock.call_count, 1)
710-
provider = self.set_provider_mock.call_args[0][0]
711-
self.assertEqual(provider.processor.exporter.compression, "gzip")
704+
with ResetGlobalLoggingState():
705+
resource = Resource.create({})
706+
_init_logging(
707+
{"otlp": DummyOTLPLogExporter},
708+
resource=resource,
709+
exporter_args_map={
710+
DummyOTLPLogExporter: {"compression": "gzip"},
711+
DummyOTLPMetricExporter: {"compression": "no"},
712+
},
713+
)
714+
self.assertEqual(self.set_provider_mock.call_count, 1)
715+
provider = self.set_provider_mock.call_args[0][0]
716+
self.assertEqual(provider.processor.exporter.compression, "gzip")
712717

713718
@patch.dict(
714719
environ,
@@ -1135,7 +1140,7 @@ def test_initialize_components_kwargs_disable_logging_handler(
11351140
)
11361141

11371142
def test_basicConfig_works_with_otel_handler(self):
1138-
with ClearLoggingHandlers():
1143+
with ResetGlobalLoggingState():
11391144
_init_logging(
11401145
{"otlp": DummyOTLPLogExporter},
11411146
Resource.create({}),
@@ -1157,7 +1162,7 @@ def test_basicConfig_works_with_otel_handler(self):
11571162
)
11581163

11591164
def test_basicConfig_preserves_otel_handler(self):
1160-
with ClearLoggingHandlers():
1165+
with ResetGlobalLoggingState():
11611166
_init_logging(
11621167
{"otlp": DummyOTLPLogExporter},
11631168
Resource.create({}),
@@ -1172,7 +1177,6 @@ def test_basicConfig_preserves_otel_handler(self):
11721177
)
11731178
handler = root_logger.handlers[0]
11741179
self.assertIsInstance(handler, LoggingHandler)
1175-
11761180
logging.basicConfig()
11771181

11781182
self.assertGreater(len(root_logger.handlers), 1)
@@ -1188,6 +1192,49 @@ def test_basicConfig_preserves_otel_handler(self):
11881192
"Should still have exactly one OpenTelemetry LoggingHandler",
11891193
)
11901194

1195+
def test_dictConfig_preserves_otel_handler(self):
1196+
with ResetGlobalLoggingState():
1197+
_init_logging(
1198+
{"otlp": DummyOTLPLogExporter},
1199+
Resource.create({}),
1200+
setup_logging_handler=True,
1201+
)
1202+
1203+
root = logging.getLogger()
1204+
self.assertEqual(
1205+
len(root.handlers),
1206+
1,
1207+
"Should be exactly one OpenTelemetry LoggingHandler",
1208+
)
1209+
logging.config.dictConfig(
1210+
{
1211+
"version": 1,
1212+
"disable_existing_loggers": False, # If this is True all loggers are disabled. Many unit tests assert loggers emit logs.
1213+
"handlers": {
1214+
"console": {
1215+
"class": "logging.StreamHandler",
1216+
"level": "DEBUG",
1217+
"stream": "ext://sys.stdout",
1218+
},
1219+
},
1220+
"loggers": {
1221+
"": { # root logger
1222+
"handlers": ["console"],
1223+
},
1224+
},
1225+
}
1226+
)
1227+
self.assertEqual(len(root.handlers), 2)
1228+
1229+
logging_handlers = [
1230+
h for h in root.handlers if isinstance(h, LoggingHandler)
1231+
]
1232+
self.assertEqual(
1233+
len(logging_handlers),
1234+
1,
1235+
"Should still have exactly one OpenTelemetry LoggingHandler",
1236+
)
1237+
11911238

11921239
class TestMetricsInit(TestCase):
11931240
def setUp(self):
@@ -1439,8 +1486,14 @@ def test_custom_configurator(self, mock_init_comp):
14391486
mock_init_comp.assert_called_once_with(**kwargs)
14401487

14411488

1442-
class ClearLoggingHandlers:
1489+
# Any test that calls _init_logging with setup_logging_handler=True
1490+
# should call _init_logging within this context manager, to
1491+
# ensure the global logging state is reset after the test.
1492+
class ResetGlobalLoggingState:
14431493
def __init__(self):
1494+
self.original_basic_config = logging.basicConfig
1495+
self.original_dict_config = logging.config.dictConfig
1496+
self.original_file_config = logging.config.fileConfig
14441497
self.root_logger = getLogger()
14451498
self.original_handlers = None
14461499

@@ -1453,6 +1506,9 @@ def __exit__(self, exc_type, exc_val, exc_tb):
14531506
self.root_logger.handlers = []
14541507
for handler in self.original_handlers:
14551508
self.root_logger.addHandler(handler)
1509+
logging.basicConfig = self.original_basic_config
1510+
logging.config.dictConfig = self.original_dict_config
1511+
logging.config.fileConfig = self.original_file_config
14561512

14571513

14581514
class TestClearLoggingHandlers(TestCase):
@@ -1464,7 +1520,7 @@ def test_preserves_handlers(self):
14641520
root_logger.addHandler(test_handler)
14651521
expected_handlers = initial_handlers + [test_handler]
14661522

1467-
with ClearLoggingHandlers():
1523+
with ResetGlobalLoggingState():
14681524
self.assertEqual(len(root_logger.handlers), 0)
14691525
temp_handler = logging.StreamHandler()
14701526
root_logger.addHandler(temp_handler)
@@ -1474,3 +1530,15 @@ def test_preserves_handlers(self):
14741530
self.assertIs(h1, h2)
14751531

14761532
root_logger.removeHandler(test_handler)
1533+
1534+
def test_preserves_original_logging_fns(self):
1535+
def f(x):
1536+
print("f")
1537+
1538+
with ResetGlobalLoggingState():
1539+
logging.basicConfig = f
1540+
logging.config.dictConfig = f
1541+
logging.config.fileConfig = f
1542+
self.assertEqual(logging.config.dictConfig.__name__, "dictConfig")
1543+
self.assertEqual(logging.basicConfig.__name__, "basicConfig")
1544+
self.assertEqual(logging.config.fileConfig.__name__, "fileConfig")

0 commit comments

Comments
 (0)