diff --git a/CHANGELOG.md b/CHANGELOG.md index 35010a1c35d..2c776317990 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,11 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## Unreleased + +- Remove log messages from `BatchLogRecordProcessor.emit`, this caused the program + to crash at shutdown with a max recursion error ([#4586](https://github.com/open-telemetry/opentelemetry-python/pull/4586)). + ## Version 1.33.0/0.54b0 (2025-05-09) - Fix intermittent `Connection aborted` error when using otlp/http exporters diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/export/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/export/__init__.py index 254c5f6b96d..506a71eb168 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/export/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/export/__init__.py @@ -286,15 +286,16 @@ def _export(self, batch_strategy: BatchLogExportStrategy) -> None: _logger.exception("Exception while exporting logs.") detach(token) + # Do not add any logging.log statements to this function, they can be being routed back to this `emit` function, + # resulting in endless recursive calls that crash the program. + # See https://github.com/open-telemetry/opentelemetry-python/issues/4261 def emit(self, log_data: LogData) -> None: if self._shutdown: - _logger.info("Shutdown called, ignoring log.") return if self._pid != os.getpid(): _BSP_RESET_ONCE.do_once(self._at_fork_reinit) - if len(self._queue) == self._max_queue_size: - _logger.warning("Queue full, dropping log.") + # This will drop a log from the right side if the queue is at _max_queue_length. self._queue.appendleft(log_data) if len(self._queue) >= self._max_export_batch_size: self._worker_awaken.set() diff --git a/opentelemetry-sdk/tests/logs/test_export.py b/opentelemetry-sdk/tests/logs/test_export.py index 6511b137a92..bc8c1c20068 100644 --- a/opentelemetry-sdk/tests/logs/test_export.py +++ b/opentelemetry-sdk/tests/logs/test_export.py @@ -21,8 +21,11 @@ import unittest import weakref from concurrent.futures import ThreadPoolExecutor +from sys import version_info from unittest.mock import Mock, patch +from pytest import mark + from opentelemetry._logs import SeverityNumber from opentelemetry.sdk import trace from opentelemetry.sdk._logs import ( @@ -347,6 +350,39 @@ def test_emit_call_log_record(self): logger.error("error") self.assertEqual(log_record_processor.emit.call_count, 1) + @mark.skipif( + version_info < (3, 10), + reason="assertNoLogs only exists in python 3.10+.", + ) + def test_logging_lib_not_invoked_in_batch_log_record_emit(self): # pylint: disable=no-self-use + # See https://github.com/open-telemetry/opentelemetry-python/issues/4261 + exporter = Mock() + processor = BatchLogRecordProcessor(exporter) + logger_provider = LoggerProvider( + resource=SDKResource.create( + { + "service.name": "shoppingcart", + "service.instance.id": "instance-12", + } + ), + ) + logger_provider.add_log_record_processor(processor) + handler = LoggingHandler( + level=logging.INFO, logger_provider=logger_provider + ) + sdk_logger = logging.getLogger("opentelemetry.sdk") + # Attach OTLP handler to SDK logger + sdk_logger.addHandler(handler) + # If `emit` calls logging.log then this test will throw a maximum recursion depth exceeded exception and fail. + try: + with self.assertNoLogs(sdk_logger, logging.NOTSET): + processor.emit(EMPTY_LOG) + processor.shutdown() + with self.assertNoLogs(sdk_logger, logging.NOTSET): + processor.emit(EMPTY_LOG) + finally: + sdk_logger.removeHandler(handler) + def test_args(self): exporter = InMemoryLogExporter() log_record_processor = BatchLogRecordProcessor( @@ -517,12 +553,6 @@ def test_logs_flushed_before_shutdown_and_dropped_after_shutdown(self): exporter.export.assert_called_once_with([EMPTY_LOG]) self.assertTrue(exporter._stopped) - with self.assertLogs(level="INFO") as log: - # This log should not be flushed. - log_record_processor.emit(EMPTY_LOG) - self.assertEqual(len(log.output), 1) - self.assertEqual(len(log.records), 1) - self.assertIn("Shutdown called, ignoring log.", log.output[0]) exporter.export.assert_called_once() # pylint: disable=no-self-use