From 87efdddf0c2e1390e81732d6ed8bcc817a84fa42 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Fri, 13 Jun 2025 19:54:12 +0000 Subject: [PATCH 01/13] Fix deadlock bug --- .../sdk/_logs/_internal/__init__.py | 4 ++- opentelemetry-sdk/tests/logs/test_handler.py | 28 +++++++++++++++++++ 2 files changed, 31 insertions(+), 1 deletion(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index 8c0be234508..11a2c7fd64e 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -489,6 +489,7 @@ def __init__( ) -> None: super().__init__(level=level) self._logger_provider = logger_provider or get_logger_provider() + # self.flushOnClose = False @staticmethod def _get_attributes(record: logging.LogRecord) -> _ExtendedAttributes: @@ -584,7 +585,8 @@ def flush(self) -> None: if hasattr(self._logger_provider, "force_flush") and callable( self._logger_provider.force_flush ): - self._logger_provider.force_flush() + thread = threading.Thread(target=self._logger_provider.force_flush) + thread.start() class Logger(APILogger): diff --git a/opentelemetry-sdk/tests/logs/test_handler.py b/opentelemetry-sdk/tests/logs/test_handler.py index 3817c440258..157dde649dd 100644 --- a/opentelemetry-sdk/tests/logs/test_handler.py +++ b/opentelemetry-sdk/tests/logs/test_handler.py @@ -59,6 +59,34 @@ def test_handler_custom_log_level(self): logger.critical("No Time For Caution") self.assertEqual(processor.emit_count(), 2) + def test_handler_calling_flush_does_not_cause_deadlock(self): + class LogProcessorThatAccessesLockOnFlush(LogRecordProcessor): + def emit(self, log_data: LogData): + pass + + def shutdown(self): + pass + + def force_flush(self, timeout_millis: int = 30000): + # Deadlock will happen here IF `flush` starts a new thread + # and then blocks, if it just starts a thread and then returns + # we don't seem to encounter the issue.. + logging._lock.acquire() + # assert logging._lock.acquire(False) is True + logging._lock.release() + + logger_provider = LoggerProvider() + processor = LogProcessorThatAccessesLockOnFlush() + logger_provider.add_log_record_processor(processor) + handler = LoggingHandler(logger_provider=logger_provider) + logging.getLogger().addHandler(handler) + # The below code is essentially recreating what is causing the problem inside + # logging.config.dictConfig. Actually calling logging.config.dictConfig will modify + # global state inside the logging module and break lots of tests. + with logging._lock: + for handler in logging.getLogger().handlers: + handler.flush() + # pylint: disable=protected-access def test_log_record_emit_noop(self): noop_logger_provder = NoOpLoggerProvider() From c45220472939bef31cceddd4c7e5ac25b6cd0935 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Wed, 25 Jun 2025 13:29:24 +0000 Subject: [PATCH 02/13] Overwrite logging config functions with patched versions.. --- .../sdk/_configuration/__init__.py | 41 +++++++------- opentelemetry-sdk/tests/test_configurator.py | 56 ++++++++++++++++++- 2 files changed, 76 insertions(+), 21 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py index 745a83385f9..85080284273 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py @@ -20,6 +20,7 @@ from __future__ import annotations import logging +import logging.config import os from abc import ABC, abstractmethod from os import environ @@ -253,31 +254,31 @@ def _init_logging( set_event_logger_provider(event_logger_provider) if setup_logging_handler: - _patch_basic_config() - # Add OTel handler handler = LoggingHandler( level=logging.NOTSET, logger_provider=provider ) logging.getLogger().addHandler(handler) - - -def _patch_basic_config(): - original_basic_config = logging.basicConfig - - def patched_basic_config(*args, **kwargs): - root = logging.getLogger() - has_only_otel = len(root.handlers) == 1 and isinstance( - root.handlers[0], LoggingHandler - ) - if has_only_otel: - otel_handler = root.handlers.pop() - original_basic_config(*args, **kwargs) - root.addHandler(otel_handler) - else: - original_basic_config(*args, **kwargs) - - logging.basicConfig = patched_basic_config + _overwrite_logging_config_fns(handler) + + +def _overwrite_logging_config_fns(handler): + root = logging.getLogger() + + def wrapper(config_fn): + def overwritten_config_fn(*args, **kwargs): + # This is needed for basicConfig only. basicConfig when called by + # the user's program will be a no-op if the root handler was configured. + if len(root.handlers) == 1 and root.handlers[0] == handler: + root.handlers.pop() + config_fn(*args, **kwargs) + if handler not in root.handlers: + root.addHandler(handler) + return overwritten_config_fn + + logging.config.fileConfig = wrapper(logging.config.fileConfig) + logging.config.dictConfig = wrapper(logging.config.dictConfig) + logging.basicConfig = wrapper(logging.basicConfig) def _import_exporters( diff --git a/opentelemetry-sdk/tests/test_configurator.py b/opentelemetry-sdk/tests/test_configurator.py index 9fda75b66f0..c13123828fc 100644 --- a/opentelemetry-sdk/tests/test_configurator.py +++ b/opentelemetry-sdk/tests/test_configurator.py @@ -16,12 +16,14 @@ from __future__ import annotations import logging +import logging.config from logging import WARNING, getLogger from os import environ from typing import Iterable, Optional, Sequence from unittest import TestCase, mock from unittest.mock import Mock, patch +import pytest from pytest import raises from opentelemetry import trace @@ -881,7 +883,6 @@ def test_basicConfig_preserves_otel_handler(self): ) handler = root_logger.handlers[0] self.assertIsInstance(handler, LoggingHandler) - logging.basicConfig() self.assertGreater(len(root_logger.handlers), 1) @@ -897,6 +898,51 @@ def test_basicConfig_preserves_otel_handler(self): "Should still have exactly one OpenTelemetry LoggingHandler", ) + def test_dictConfig_preserves_otel_handler(self): + with ClearLoggingHandlers(): + _init_logging( + {"otlp": DummyOTLPLogExporter}, + Resource.create({}), + setup_logging_handler=True, + ) + + root = logging.getLogger() + self.assertEqual( + len(root.handlers), + 1, + "Should be exactly one OpenTelemetry LoggingHandler", + ) + logging.config.dictConfig( + { + "version": 1, + "handlers": { + "default": { + "level": "INFO", + "class": "logging.StreamHandler", + "stream": "ext://sys.stdout", + }, + }, + "loggers": { + "": { # root logger + "handlers": ["default"], + "level": "WARNING", + "propagate": False, + }, + }, + } + ) + print(root.handlers) + self.assertEqual(len(root.handlers), 2) + + logging_handlers = [ + h for h in root.handlers if isinstance(h, LoggingHandler) + ] + self.assertEqual( + len(logging_handlers), + 1, + "Should still have exactly one OpenTelemetry LoggingHandler", + ) + class TestMetricsInit(TestCase): def setUp(self): @@ -1169,3 +1215,11 @@ def test_preserves_handlers(self): self.assertIs(h1, h2) root_logger.removeHandler(test_handler) + + +pytest.main( + [ + "-x", + "/usr/local/google/home/dylanrussell/archivist_backup_250529_133018/reinstate/opentelemetry-python/opentelemetry-sdk/tests/test_configurator.py", + ] +) From fc78d8e43c3191672b5c7593b9815871c03f7895 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Thu, 26 Jun 2025 16:03:09 +0000 Subject: [PATCH 03/13] Some change --- .../sdk/_configuration/__init__.py | 1 + opentelemetry-sdk/tests/test_configurator.py | 126 ++++++++++-------- 2 files changed, 72 insertions(+), 55 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py index 85080284273..415e1a3a3b2 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py @@ -274,6 +274,7 @@ def overwritten_config_fn(*args, **kwargs): config_fn(*args, **kwargs) if handler not in root.handlers: root.addHandler(handler) + return overwritten_config_fn logging.config.fileConfig = wrapper(logging.config.fileConfig) diff --git a/opentelemetry-sdk/tests/test_configurator.py b/opentelemetry-sdk/tests/test_configurator.py index c13123828fc..50528ef06fa 100644 --- a/opentelemetry-sdk/tests/test_configurator.py +++ b/opentelemetry-sdk/tests/test_configurator.py @@ -23,7 +23,6 @@ from unittest import TestCase, mock from unittest.mock import Mock, patch -import pytest from pytest import raises from opentelemetry import trace @@ -626,48 +625,50 @@ def tearDown(self): ] def test_logging_init_empty(self): - auto_resource = Resource.create( - { - "telemetry.auto.version": "auto-version", - } - ) - _init_logging({}, resource=auto_resource) - self.assertEqual(self.set_provider_mock.call_count, 1) - provider = self.set_provider_mock.call_args[0][0] - self.assertIsInstance(provider, DummyLoggerProvider) - self.assertIsInstance(provider.resource, Resource) - self.assertEqual( - provider.resource.attributes.get("telemetry.auto.version"), - "auto-version", - ) - self.event_logger_provider_mock.assert_called_once_with( - logger_provider=provider - ) - self.set_event_logger_provider_mock.assert_called_once_with( - self.event_logger_provider_instance_mock - ) + with ResetGlobalLoggingState(): + auto_resource = Resource.create( + { + "telemetry.auto.version": "auto-version", + } + ) + _init_logging({}, resource=auto_resource) + self.assertEqual(self.set_provider_mock.call_count, 1) + provider = self.set_provider_mock.call_args[0][0] + self.assertIsInstance(provider, DummyLoggerProvider) + self.assertIsInstance(provider.resource, Resource) + self.assertEqual( + provider.resource.attributes.get("telemetry.auto.version"), + "auto-version", + ) + self.event_logger_provider_mock.assert_called_once_with( + logger_provider=provider + ) + self.set_event_logger_provider_mock.assert_called_once_with( + self.event_logger_provider_instance_mock + ) @patch.dict( environ, {"OTEL_RESOURCE_ATTRIBUTES": "service.name=otlp-service"}, ) def test_logging_init_exporter(self): - resource = Resource.create({}) - _init_logging({"otlp": DummyOTLPLogExporter}, resource=resource) - self.assertEqual(self.set_provider_mock.call_count, 1) - provider = self.set_provider_mock.call_args[0][0] - self.assertIsInstance(provider, DummyLoggerProvider) - self.assertIsInstance(provider.resource, Resource) - self.assertEqual( - provider.resource.attributes.get("service.name"), - "otlp-service", - ) - self.assertIsInstance(provider.processor, DummyLogRecordProcessor) - self.assertIsInstance( - provider.processor.exporter, DummyOTLPLogExporter - ) - getLogger(__name__).error("hello") - self.assertTrue(provider.processor.exporter.export_called) + with ResetGlobalLoggingState(): + resource = Resource.create({}) + _init_logging({"otlp": DummyOTLPLogExporter}, resource=resource) + self.assertEqual(self.set_provider_mock.call_count, 1) + provider = self.set_provider_mock.call_args[0][0] + self.assertIsInstance(provider, DummyLoggerProvider) + self.assertIsInstance(provider.resource, Resource) + self.assertEqual( + provider.resource.attributes.get("service.name"), + "otlp-service", + ) + self.assertIsInstance(provider.processor, DummyLogRecordProcessor) + self.assertIsInstance( + provider.processor.exporter, DummyOTLPLogExporter + ) + getLogger(__name__).error("hello") + self.assertTrue(provider.processor.exporter.export_called) @patch.dict( environ, @@ -846,7 +847,7 @@ def test_initialize_components_kwargs( ) def test_basicConfig_works_with_otel_handler(self): - with ClearLoggingHandlers(): + with ResetGlobalLoggingState(): _init_logging( {"otlp": DummyOTLPLogExporter}, Resource.create({}), @@ -868,7 +869,7 @@ def test_basicConfig_works_with_otel_handler(self): ) def test_basicConfig_preserves_otel_handler(self): - with ClearLoggingHandlers(): + with ResetGlobalLoggingState(): _init_logging( {"otlp": DummyOTLPLogExporter}, Resource.create({}), @@ -899,7 +900,7 @@ def test_basicConfig_preserves_otel_handler(self): ) def test_dictConfig_preserves_otel_handler(self): - with ClearLoggingHandlers(): + with ResetGlobalLoggingState(): _init_logging( {"otlp": DummyOTLPLogExporter}, Resource.create({}), @@ -916,22 +917,20 @@ def test_dictConfig_preserves_otel_handler(self): { "version": 1, "handlers": { - "default": { - "level": "INFO", + "console": { "class": "logging.StreamHandler", + "level": "DEBUG", + "formatter": "simple", "stream": "ext://sys.stdout", }, }, "loggers": { "": { # root logger - "handlers": ["default"], - "level": "WARNING", - "propagate": False, + "handlers": ["console"], }, }, } ) - print(root.handlers) self.assertEqual(len(root.handlers), 2) logging_handlers = [ @@ -1180,12 +1179,18 @@ def test_custom_configurator(self, mock_init_comp): mock_init_comp.assert_called_once_with(**kwargs) -class ClearLoggingHandlers: +class ResetGlobalLoggingState: def __init__(self): + self.original_basic_config = logging.basicConfig + self.original_dict_config = logging.config.dictConfig + self.original_file_config = logging.config.fileConfig self.root_logger = getLogger() self.original_handlers = None def __enter__(self): + print(self.root_logger.handlers) + print(self.root_logger.filters) + print(self.root_logger.level) self.original_handlers = self.root_logger.handlers[:] self.root_logger.handlers = [] return self @@ -1194,6 +1199,13 @@ def __exit__(self, exc_type, exc_val, exc_tb): self.root_logger.handlers = [] for handler in self.original_handlers: self.root_logger.addHandler(handler) + logging.basicConfig = self.original_basic_config + logging.config.dictConfig = self.original_dict_config + logging.config.fileConfig = self.original_file_config + root = getLogger() + print(root.handlers) + print(root.filters) + print(root.level) class TestClearLoggingHandlers(TestCase): @@ -1205,7 +1217,7 @@ def test_preserves_handlers(self): root_logger.addHandler(test_handler) expected_handlers = initial_handlers + [test_handler] - with ClearLoggingHandlers(): + with ResetGlobalLoggingState(): self.assertEqual(len(root_logger.handlers), 0) temp_handler = logging.StreamHandler() root_logger.addHandler(temp_handler) @@ -1216,10 +1228,14 @@ def test_preserves_handlers(self): root_logger.removeHandler(test_handler) - -pytest.main( - [ - "-x", - "/usr/local/google/home/dylanrussell/archivist_backup_250529_133018/reinstate/opentelemetry-python/opentelemetry-sdk/tests/test_configurator.py", - ] -) + def test_preserves_original_logging_fns(self): + def f(x): + print("f") + + with ResetGlobalLoggingState(): + logging.basicConfig = lambda x: print("lambda") + logging.config.dictConfig = f + logging.config.fileConfig = f + self.assertEqual(logging.config.dictConfig.__name__, "dictConfig") + self.assertEqual(logging.basicConfig.__name__, "basicConfig") + self.assertEqual(logging.config.fileConfig.__name__, "fileConfig") From 1bbe3f1b8ed52e00eed25013f31c67f09a2aaf21 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Thu, 26 Jun 2025 17:30:46 +0000 Subject: [PATCH 04/13] Run precommit --- opentelemetry-sdk/tests/test_configurator.py | 9 +-------- 1 file changed, 1 insertion(+), 8 deletions(-) diff --git a/opentelemetry-sdk/tests/test_configurator.py b/opentelemetry-sdk/tests/test_configurator.py index 50528ef06fa..acc0d922489 100644 --- a/opentelemetry-sdk/tests/test_configurator.py +++ b/opentelemetry-sdk/tests/test_configurator.py @@ -916,11 +916,11 @@ def test_dictConfig_preserves_otel_handler(self): logging.config.dictConfig( { "version": 1, + "disable_existing_loggers": False, # If this is True all loggers are disabled. Many unit tests assert loggers emit logs. "handlers": { "console": { "class": "logging.StreamHandler", "level": "DEBUG", - "formatter": "simple", "stream": "ext://sys.stdout", }, }, @@ -1188,9 +1188,6 @@ def __init__(self): self.original_handlers = None def __enter__(self): - print(self.root_logger.handlers) - print(self.root_logger.filters) - print(self.root_logger.level) self.original_handlers = self.root_logger.handlers[:] self.root_logger.handlers = [] return self @@ -1202,10 +1199,6 @@ def __exit__(self, exc_type, exc_val, exc_tb): logging.basicConfig = self.original_basic_config logging.config.dictConfig = self.original_dict_config logging.config.fileConfig = self.original_file_config - root = getLogger() - print(root.handlers) - print(root.filters) - print(root.level) class TestClearLoggingHandlers(TestCase): From de3f40face57bc9431253f60c64a314763fb7641 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Thu, 26 Jun 2025 18:38:53 +0000 Subject: [PATCH 05/13] change emit to on_emit --- opentelemetry-sdk/tests/logs/test_handler.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/opentelemetry-sdk/tests/logs/test_handler.py b/opentelemetry-sdk/tests/logs/test_handler.py index 8e46c903539..ec0c8399b2b 100644 --- a/opentelemetry-sdk/tests/logs/test_handler.py +++ b/opentelemetry-sdk/tests/logs/test_handler.py @@ -64,7 +64,7 @@ def test_handler_custom_log_level(self): def test_handler_calling_flush_does_not_cause_deadlock(self): class LogProcessorThatAccessesLockOnFlush(LogRecordProcessor): - def emit(self, log_data: LogData): + def on_emit(self, log_data: LogData): pass def shutdown(self): From c6d4089c95ae05394f73330f001c0af624ef9c51 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Thu, 26 Jun 2025 18:48:12 +0000 Subject: [PATCH 06/13] Fix lint issues --- opentelemetry-sdk/tests/logs/test_handler.py | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/opentelemetry-sdk/tests/logs/test_handler.py b/opentelemetry-sdk/tests/logs/test_handler.py index ec0c8399b2b..9479851e0c8 100644 --- a/opentelemetry-sdk/tests/logs/test_handler.py +++ b/opentelemetry-sdk/tests/logs/test_handler.py @@ -62,7 +62,7 @@ def test_handler_custom_log_level(self): logger.critical("No Time For Caution") self.assertEqual(processor.emit_count(), 2) - def test_handler_calling_flush_does_not_cause_deadlock(self): + def test_handler_calling_flush_does_not_cause_deadlock(self): # pylint: disable=no-self-use class LogProcessorThatAccessesLockOnFlush(LogRecordProcessor): def on_emit(self, log_data: LogData): pass @@ -74,9 +74,8 @@ def force_flush(self, timeout_millis: int = 30000): # Deadlock will happen here IF `flush` starts a new thread # and then blocks, if it just starts a thread and then returns # we don't seem to encounter the issue.. - logging._lock.acquire() - # assert logging._lock.acquire(False) is True - logging._lock.release() + with logging._lock: # pylint: disable=protected-access + pass logger_provider = LoggerProvider() processor = LogProcessorThatAccessesLockOnFlush() @@ -86,7 +85,7 @@ def force_flush(self, timeout_millis: int = 30000): # The below code is essentially recreating what is causing the problem inside # logging.config.dictConfig. Actually calling logging.config.dictConfig will modify # global state inside the logging module and break lots of tests. - with logging._lock: + with logging._lock: # pylint: disable=protected-access for handler in logging.getLogger().handlers: handler.flush() From 6c9d23151b1d8005148d9f333ca8b32f9fb69f89 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Thu, 26 Jun 2025 18:52:10 +0000 Subject: [PATCH 07/13] Add changelog --- CHANGELOG.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index ba135db4f87..cf8c914e292 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## Unreleased +- Overwrite logging.config.fileConfig and logging.config.dictConfig to ensure +the OTLP `LogHandler` remains attached to the root logger. Fix a bug that +can cause a deadlock to occur over `logging._lock` in some cases ([#4636](https://github.com/open-telemetry/opentelemetry-python/pull/4636)). - Update OTLP proto to v1.7 [#4645](https://github.com/open-telemetry/opentelemetry-python/pull/4645). - Add `event_name` as a top level field in the `LogRecord`. Events are now simply logs with the `event_name` field set, the logs SDK should be used to emit events ([#4652](https://github.com/open-telemetry/opentelemetry-python/pull/4652)). From 3f7c4fd42eef414b5ef62f235c86af6d6b3bc6c2 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Wed, 9 Jul 2025 15:03:50 +0000 Subject: [PATCH 08/13] Get rid of test that may deadlock and flushOnClose approach --- .../tests/logs/test_log_record.py | 4 +++ .../sdk/_logs/_internal/__init__.py | 1 - opentelemetry-sdk/tests/logs/test_handler.py | 27 ------------------- 3 files changed, 4 insertions(+), 28 deletions(-) diff --git a/opentelemetry-api/tests/logs/test_log_record.py b/opentelemetry-api/tests/logs/test_log_record.py index a06ed8dabfc..200d61b63d2 100644 --- a/opentelemetry-api/tests/logs/test_log_record.py +++ b/opentelemetry-api/tests/logs/test_log_record.py @@ -25,3 +25,7 @@ class TestLogRecord(unittest.TestCase): def test_log_record_observed_timestamp_default(self, time_ns_mock): # type: ignore time_ns_mock.return_value = OBSERVED_TIMESTAMP self.assertEqual(LogRecord().observed_timestamp, OBSERVED_TIMESTAMP) + + def test_context_used_by_default(self): + record = LogRecord() + diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index 9a3d3b3b5fd..c617129dc08 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -551,7 +551,6 @@ def __init__( ) -> None: super().__init__(level=level) self._logger_provider = logger_provider or get_logger_provider() - # self.flushOnClose = False @staticmethod def _get_attributes(record: logging.LogRecord) -> _ExtendedAttributes: diff --git a/opentelemetry-sdk/tests/logs/test_handler.py b/opentelemetry-sdk/tests/logs/test_handler.py index 9479851e0c8..55526dc2b6a 100644 --- a/opentelemetry-sdk/tests/logs/test_handler.py +++ b/opentelemetry-sdk/tests/logs/test_handler.py @@ -62,33 +62,6 @@ def test_handler_custom_log_level(self): logger.critical("No Time For Caution") self.assertEqual(processor.emit_count(), 2) - def test_handler_calling_flush_does_not_cause_deadlock(self): # pylint: disable=no-self-use - class LogProcessorThatAccessesLockOnFlush(LogRecordProcessor): - def on_emit(self, log_data: LogData): - pass - - def shutdown(self): - pass - - def force_flush(self, timeout_millis: int = 30000): - # Deadlock will happen here IF `flush` starts a new thread - # and then blocks, if it just starts a thread and then returns - # we don't seem to encounter the issue.. - with logging._lock: # pylint: disable=protected-access - pass - - logger_provider = LoggerProvider() - processor = LogProcessorThatAccessesLockOnFlush() - logger_provider.add_log_record_processor(processor) - handler = LoggingHandler(logger_provider=logger_provider) - logging.getLogger().addHandler(handler) - # The below code is essentially recreating what is causing the problem inside - # logging.config.dictConfig. Actually calling logging.config.dictConfig will modify - # global state inside the logging module and break lots of tests. - with logging._lock: # pylint: disable=protected-access - for handler in logging.getLogger().handlers: - handler.flush() - # pylint: disable=protected-access def test_log_record_emit_noop(self): noop_logger_provder = NoOpLoggerProvider() From 9b45309193aa4e228d8ebefc5327ae061982f81c Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Wed, 9 Jul 2025 15:07:53 +0000 Subject: [PATCH 09/13] Run precommit --- opentelemetry-api/tests/logs/test_log_record.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/opentelemetry-api/tests/logs/test_log_record.py b/opentelemetry-api/tests/logs/test_log_record.py index 200d61b63d2..a06ed8dabfc 100644 --- a/opentelemetry-api/tests/logs/test_log_record.py +++ b/opentelemetry-api/tests/logs/test_log_record.py @@ -25,7 +25,3 @@ class TestLogRecord(unittest.TestCase): def test_log_record_observed_timestamp_default(self, time_ns_mock): # type: ignore time_ns_mock.return_value = OBSERVED_TIMESTAMP self.assertEqual(LogRecord().observed_timestamp, OBSERVED_TIMESTAMP) - - def test_context_used_by_default(self): - record = LogRecord() - From 6645b73456eb1205ac026b3fcfc195b5aa145eb5 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Mon, 14 Jul 2025 17:14:29 +0000 Subject: [PATCH 10/13] Respond to comments on PR --- .../opentelemetry/sdk/_configuration/__init__.py | 14 ++++++++------ .../opentelemetry/sdk/_logs/_internal/__init__.py | 2 ++ 2 files changed, 10 insertions(+), 6 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py index 415e1a3a3b2..f3f31de3080 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py @@ -267,13 +267,15 @@ def _overwrite_logging_config_fns(handler): def wrapper(config_fn): def overwritten_config_fn(*args, **kwargs): - # This is needed for basicConfig only. basicConfig when called by - # the user's program will be a no-op if the root handler was configured. - if len(root.handlers) == 1 and root.handlers[0] == handler: - root.handlers.pop() + removedHandler = False + # We don't want the OTLP handler to be modified or deleted by the logging config functions. + # So we remove it and then add it back after the function call. + if handler in root.handlers: + removedHandler = True + root.handlers.remove(handler) config_fn(*args, **kwargs) - if handler not in root.handlers: - root.addHandler(handler) + if removedHandler: + root.addHandler(handler) return overwritten_config_fn diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index c617129dc08..d5856077338 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -643,6 +643,8 @@ def flush(self) -> None: if hasattr(self._logger_provider, "force_flush") and callable( self._logger_provider.force_flush ): + # This is done in a separate thread to avoid a potential deadlock, for + # details see https://github.com/open-telemetry/opentelemetry-python/pull/4636. thread = threading.Thread(target=self._logger_provider.force_flush) thread.start() From 602c2dcbb10487f5f7a76f3fd0b933749cb23d37 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Wed, 16 Jul 2025 21:08:45 +0000 Subject: [PATCH 11/13] Respond to review comments.. --- .../opentelemetry/sdk/_configuration/__init__.py | 16 +++++++++------- opentelemetry-sdk/tests/test_configurator.py | 2 +- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py index f3f31de3080..42f30a49e44 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py @@ -262,20 +262,22 @@ def _init_logging( _overwrite_logging_config_fns(handler) -def _overwrite_logging_config_fns(handler): +def _overwrite_logging_config_fns(handler: LoggingHandler) -> None: root = logging.getLogger() - def wrapper(config_fn): + def wrapper(config_fn: Callable) -> Callable: def overwritten_config_fn(*args, **kwargs): - removedHandler = False + removed_handler = False # We don't want the OTLP handler to be modified or deleted by the logging config functions. # So we remove it and then add it back after the function call. if handler in root.handlers: - removedHandler = True + removed_handler = True root.handlers.remove(handler) - config_fn(*args, **kwargs) - if removedHandler: - root.addHandler(handler) + try: + config_fn(*args, **kwargs) + finally: + if removed_handler: + root.addHandler(handler) return overwritten_config_fn diff --git a/opentelemetry-sdk/tests/test_configurator.py b/opentelemetry-sdk/tests/test_configurator.py index acc0d922489..37ec2fa85f9 100644 --- a/opentelemetry-sdk/tests/test_configurator.py +++ b/opentelemetry-sdk/tests/test_configurator.py @@ -1226,7 +1226,7 @@ def f(x): print("f") with ResetGlobalLoggingState(): - logging.basicConfig = lambda x: print("lambda") + logging.basicConfig = f logging.config.dictConfig = f logging.config.fileConfig = f self.assertEqual(logging.config.dictConfig.__name__, "dictConfig") From c8bdc113dfde9efe8f48283a3fc588bf1758e983 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Thu, 17 Jul 2025 13:41:24 +0000 Subject: [PATCH 12/13] Add comment --- .../src/opentelemetry/sdk/_configuration/__init__.py | 1 + 1 file changed, 1 insertion(+) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py index 42f30a49e44..43aa7c9649e 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py @@ -276,6 +276,7 @@ def overwritten_config_fn(*args, **kwargs): try: config_fn(*args, **kwargs) finally: + # Ensure handler is added back if logging function throws exception. if removed_handler: root.addHandler(handler) From b5e344df675344fffcb085e1f3a38d10be83c3a1 Mon Sep 17 00:00:00 2001 From: Dylan Russell Date: Thu, 17 Jul 2025 13:56:29 +0000 Subject: [PATCH 13/13] Fix tests, add comment --- opentelemetry-sdk/tests/test_configurator.py | 28 +++++++++++--------- 1 file changed, 16 insertions(+), 12 deletions(-) diff --git a/opentelemetry-sdk/tests/test_configurator.py b/opentelemetry-sdk/tests/test_configurator.py index eb0897dcf66..6e9221b124d 100644 --- a/opentelemetry-sdk/tests/test_configurator.py +++ b/opentelemetry-sdk/tests/test_configurator.py @@ -688,18 +688,19 @@ def test_logging_init_exporter(self): self.assertTrue(provider.processor.exporter.export_called) def test_logging_init_exporter_uses_exporter_args_map(self): - resource = Resource.create({}) - _init_logging( - {"otlp": DummyOTLPLogExporter}, - resource=resource, - exporter_args_map={ - DummyOTLPLogExporter: {"compression": "gzip"}, - DummyOTLPMetricExporter: {"compression": "no"}, - }, - ) - self.assertEqual(self.set_provider_mock.call_count, 1) - provider = self.set_provider_mock.call_args[0][0] - self.assertEqual(provider.processor.exporter.compression, "gzip") + with ResetGlobalLoggingState(): + resource = Resource.create({}) + _init_logging( + {"otlp": DummyOTLPLogExporter}, + resource=resource, + exporter_args_map={ + DummyOTLPLogExporter: {"compression": "gzip"}, + DummyOTLPMetricExporter: {"compression": "no"}, + }, + ) + self.assertEqual(self.set_provider_mock.call_count, 1) + provider = self.set_provider_mock.call_args[0][0] + self.assertEqual(provider.processor.exporter.compression, "gzip") @patch.dict( environ, @@ -1232,6 +1233,9 @@ def test_custom_configurator(self, mock_init_comp): mock_init_comp.assert_called_once_with(**kwargs) +# Any test that calls _init_logging with setup_logging_handler=True +# should call _init_logging within this context manager, to +# ensure the global logging state is reset after the test. class ResetGlobalLoggingState: def __init__(self): self.original_basic_config = logging.basicConfig