Skip to content

Commit 57cb935

Browse files
authored
Fix issue where deadlock can occur over logging._lock (#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 14401e1 commit 57cb935

File tree

4 files changed

+151
-70
lines changed

4 files changed

+151
-70
lines changed

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: 23 additions & 16 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
@@ -268,31 +269,37 @@ def _init_logging(
268269
set_event_logger_provider(event_logger_provider)
269270

270271
if setup_logging_handler:
271-
_patch_basic_config()
272-
273272
# Add OTel handler
274273
handler = LoggingHandler(
275274
level=logging.NOTSET, logger_provider=provider
276275
)
277276
logging.getLogger().addHandler(handler)
277+
_overwrite_logging_config_fns(handler)
278278

279279

280-
def _patch_basic_config():
281-
original_basic_config = logging.basicConfig
280+
def _overwrite_logging_config_fns(handler: LoggingHandler) -> None:
281+
root = logging.getLogger()
282282

283-
def patched_basic_config(*args, **kwargs):
284-
root = logging.getLogger()
285-
has_only_otel = len(root.handlers) == 1 and isinstance(
286-
root.handlers[0], LoggingHandler
287-
)
288-
if has_only_otel:
289-
otel_handler = root.handlers.pop()
290-
original_basic_config(*args, **kwargs)
291-
root.addHandler(otel_handler)
292-
else:
293-
original_basic_config(*args, **kwargs)
283+
def wrapper(config_fn: Callable) -> Callable:
284+
def overwritten_config_fn(*args, **kwargs):
285+
removed_handler = False
286+
# We don't want the OTLP handler to be modified or deleted by the logging config functions.
287+
# So we remove it and then add it back after the function call.
288+
if handler in root.handlers:
289+
removed_handler = True
290+
root.handlers.remove(handler)
291+
try:
292+
config_fn(*args, **kwargs)
293+
finally:
294+
# Ensure handler is added back if logging function throws exception.
295+
if removed_handler:
296+
root.addHandler(handler)
297+
298+
return overwritten_config_fn
294299

295-
logging.basicConfig = patched_basic_config
300+
logging.config.fileConfig = wrapper(logging.config.fileConfig)
301+
logging.config.dictConfig = wrapper(logging.config.dictConfig)
302+
logging.basicConfig = wrapper(logging.basicConfig)
296303

297304

298305
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: 120 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@
1616
from __future__ import annotations
1717

1818
import logging
19+
import logging.config
1920
from logging import WARNING, getLogger
2021
from os import environ
2122
from typing import Iterable, Optional, Sequence
@@ -641,62 +642,65 @@ def tearDown(self):
641642
]
642643

643644
def test_logging_init_empty(self):
644-
auto_resource = Resource.create(
645-
{
646-
"telemetry.auto.version": "auto-version",
647-
}
648-
)
649-
_init_logging({}, resource=auto_resource)
650-
self.assertEqual(self.set_provider_mock.call_count, 1)
651-
provider = self.set_provider_mock.call_args[0][0]
652-
self.assertIsInstance(provider, DummyLoggerProvider)
653-
self.assertIsInstance(provider.resource, Resource)
654-
self.assertEqual(
655-
provider.resource.attributes.get("telemetry.auto.version"),
656-
"auto-version",
657-
)
658-
self.event_logger_provider_mock.assert_called_once_with(
659-
logger_provider=provider
660-
)
661-
self.set_event_logger_provider_mock.assert_called_once_with(
662-
self.event_logger_provider_instance_mock
663-
)
645+
with ResetGlobalLoggingState():
646+
auto_resource = Resource.create(
647+
{
648+
"telemetry.auto.version": "auto-version",
649+
}
650+
)
651+
_init_logging({}, resource=auto_resource)
652+
self.assertEqual(self.set_provider_mock.call_count, 1)
653+
provider = self.set_provider_mock.call_args[0][0]
654+
self.assertIsInstance(provider, DummyLoggerProvider)
655+
self.assertIsInstance(provider.resource, Resource)
656+
self.assertEqual(
657+
provider.resource.attributes.get("telemetry.auto.version"),
658+
"auto-version",
659+
)
660+
self.event_logger_provider_mock.assert_called_once_with(
661+
logger_provider=provider
662+
)
663+
self.set_event_logger_provider_mock.assert_called_once_with(
664+
self.event_logger_provider_instance_mock
665+
)
664666

665667
@patch.dict(
666668
environ,
667669
{"OTEL_RESOURCE_ATTRIBUTES": "service.name=otlp-service"},
668670
)
669671
def test_logging_init_exporter(self):
670-
resource = Resource.create({})
671-
_init_logging({"otlp": DummyOTLPLogExporter}, resource=resource)
672-
self.assertEqual(self.set_provider_mock.call_count, 1)
673-
provider = self.set_provider_mock.call_args[0][0]
674-
self.assertIsInstance(provider, DummyLoggerProvider)
675-
self.assertIsInstance(provider.resource, Resource)
676-
self.assertEqual(
677-
provider.resource.attributes.get("service.name"),
678-
"otlp-service",
679-
)
680-
self.assertIsInstance(provider.processor, DummyLogRecordProcessor)
681-
self.assertIsInstance(
682-
provider.processor.exporter, DummyOTLPLogExporter
683-
)
684-
getLogger(__name__).error("hello")
685-
self.assertTrue(provider.processor.exporter.export_called)
672+
with ResetGlobalLoggingState():
673+
resource = Resource.create({})
674+
_init_logging({"otlp": DummyOTLPLogExporter}, resource=resource)
675+
self.assertEqual(self.set_provider_mock.call_count, 1)
676+
provider = self.set_provider_mock.call_args[0][0]
677+
self.assertIsInstance(provider, DummyLoggerProvider)
678+
self.assertIsInstance(provider.resource, Resource)
679+
self.assertEqual(
680+
provider.resource.attributes.get("service.name"),
681+
"otlp-service",
682+
)
683+
self.assertIsInstance(provider.processor, DummyLogRecordProcessor)
684+
self.assertIsInstance(
685+
provider.processor.exporter, DummyOTLPLogExporter
686+
)
687+
getLogger(__name__).error("hello")
688+
self.assertTrue(provider.processor.exporter.export_called)
686689

687690
def test_logging_init_exporter_uses_exporter_args_map(self):
688-
resource = Resource.create({})
689-
_init_logging(
690-
{"otlp": DummyOTLPLogExporter},
691-
resource=resource,
692-
exporter_args_map={
693-
DummyOTLPLogExporter: {"compression": "gzip"},
694-
DummyOTLPMetricExporter: {"compression": "no"},
695-
},
696-
)
697-
self.assertEqual(self.set_provider_mock.call_count, 1)
698-
provider = self.set_provider_mock.call_args[0][0]
699-
self.assertEqual(provider.processor.exporter.compression, "gzip")
691+
with ResetGlobalLoggingState():
692+
resource = Resource.create({})
693+
_init_logging(
694+
{"otlp": DummyOTLPLogExporter},
695+
resource=resource,
696+
exporter_args_map={
697+
DummyOTLPLogExporter: {"compression": "gzip"},
698+
DummyOTLPMetricExporter: {"compression": "no"},
699+
},
700+
)
701+
self.assertEqual(self.set_provider_mock.call_count, 1)
702+
provider = self.set_provider_mock.call_args[0][0]
703+
self.assertEqual(provider.processor.exporter.compression, "gzip")
700704

701705
@patch.dict(
702706
environ,
@@ -883,7 +887,7 @@ def test_initialize_components_kwargs(
883887
)
884888

885889
def test_basicConfig_works_with_otel_handler(self):
886-
with ClearLoggingHandlers():
890+
with ResetGlobalLoggingState():
887891
_init_logging(
888892
{"otlp": DummyOTLPLogExporter},
889893
Resource.create({}),
@@ -905,7 +909,7 @@ def test_basicConfig_works_with_otel_handler(self):
905909
)
906910

907911
def test_basicConfig_preserves_otel_handler(self):
908-
with ClearLoggingHandlers():
912+
with ResetGlobalLoggingState():
909913
_init_logging(
910914
{"otlp": DummyOTLPLogExporter},
911915
Resource.create({}),
@@ -920,7 +924,6 @@ def test_basicConfig_preserves_otel_handler(self):
920924
)
921925
handler = root_logger.handlers[0]
922926
self.assertIsInstance(handler, LoggingHandler)
923-
924927
logging.basicConfig()
925928

926929
self.assertGreater(len(root_logger.handlers), 1)
@@ -936,6 +939,49 @@ def test_basicConfig_preserves_otel_handler(self):
936939
"Should still have exactly one OpenTelemetry LoggingHandler",
937940
)
938941

942+
def test_dictConfig_preserves_otel_handler(self):
943+
with ResetGlobalLoggingState():
944+
_init_logging(
945+
{"otlp": DummyOTLPLogExporter},
946+
Resource.create({}),
947+
setup_logging_handler=True,
948+
)
949+
950+
root = logging.getLogger()
951+
self.assertEqual(
952+
len(root.handlers),
953+
1,
954+
"Should be exactly one OpenTelemetry LoggingHandler",
955+
)
956+
logging.config.dictConfig(
957+
{
958+
"version": 1,
959+
"disable_existing_loggers": False, # If this is True all loggers are disabled. Many unit tests assert loggers emit logs.
960+
"handlers": {
961+
"console": {
962+
"class": "logging.StreamHandler",
963+
"level": "DEBUG",
964+
"stream": "ext://sys.stdout",
965+
},
966+
},
967+
"loggers": {
968+
"": { # root logger
969+
"handlers": ["console"],
970+
},
971+
},
972+
}
973+
)
974+
self.assertEqual(len(root.handlers), 2)
975+
976+
logging_handlers = [
977+
h for h in root.handlers if isinstance(h, LoggingHandler)
978+
]
979+
self.assertEqual(
980+
len(logging_handlers),
981+
1,
982+
"Should still have exactly one OpenTelemetry LoggingHandler",
983+
)
984+
939985

940986
class TestMetricsInit(TestCase):
941987
def setUp(self):
@@ -1187,8 +1233,14 @@ def test_custom_configurator(self, mock_init_comp):
11871233
mock_init_comp.assert_called_once_with(**kwargs)
11881234

11891235

1190-
class ClearLoggingHandlers:
1236+
# Any test that calls _init_logging with setup_logging_handler=True
1237+
# should call _init_logging within this context manager, to
1238+
# ensure the global logging state is reset after the test.
1239+
class ResetGlobalLoggingState:
11911240
def __init__(self):
1241+
self.original_basic_config = logging.basicConfig
1242+
self.original_dict_config = logging.config.dictConfig
1243+
self.original_file_config = logging.config.fileConfig
11921244
self.root_logger = getLogger()
11931245
self.original_handlers = None
11941246

@@ -1201,6 +1253,9 @@ def __exit__(self, exc_type, exc_val, exc_tb):
12011253
self.root_logger.handlers = []
12021254
for handler in self.original_handlers:
12031255
self.root_logger.addHandler(handler)
1256+
logging.basicConfig = self.original_basic_config
1257+
logging.config.dictConfig = self.original_dict_config
1258+
logging.config.fileConfig = self.original_file_config
12041259

12051260

12061261
class TestClearLoggingHandlers(TestCase):
@@ -1212,7 +1267,7 @@ def test_preserves_handlers(self):
12121267
root_logger.addHandler(test_handler)
12131268
expected_handlers = initial_handlers + [test_handler]
12141269

1215-
with ClearLoggingHandlers():
1270+
with ResetGlobalLoggingState():
12161271
self.assertEqual(len(root_logger.handlers), 0)
12171272
temp_handler = logging.StreamHandler()
12181273
root_logger.addHandler(temp_handler)
@@ -1222,3 +1277,15 @@ def test_preserves_handlers(self):
12221277
self.assertIs(h1, h2)
12231278

12241279
root_logger.removeHandler(test_handler)
1280+
1281+
def test_preserves_original_logging_fns(self):
1282+
def f(x):
1283+
print("f")
1284+
1285+
with ResetGlobalLoggingState():
1286+
logging.basicConfig = f
1287+
logging.config.dictConfig = f
1288+
logging.config.fileConfig = f
1289+
self.assertEqual(logging.config.dictConfig.__name__, "dictConfig")
1290+
self.assertEqual(logging.basicConfig.__name__, "basicConfig")
1291+
self.assertEqual(logging.config.fileConfig.__name__, "fileConfig")

0 commit comments

Comments
 (0)