Fix max recursion bug by removing logging.log calls in emit (open-telemetry#4588)

* Fix max recursion bug by removing logging.log calls in emit

* Update opentelemetry-sdk/src/opentelemetry/sdk/_shared_internal/__init__.py

Co-authored-by: Emídio Neto <[email protected]>

* Add changelog

* Fix linter

* Respond to comments in PR

* Remove log line

* Fix lint issues

* Attach handler to SDK logger instead of root logger and remote it after test is done. Fix lint issues..

* Assert no logs emitted. ADd try/except block for cleanup

* Skip test on <python3.10

* Run precommit

* Apply suggestions from code review

* use try/finally instead of try/except

---------

Co-authored-by: Emídio Neto <[email protected]>
Co-authored-by: Aaron Abbott <[email protected]>

Author: 3 people

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

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()

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