Infinit recursion in log shutdown code

[jenshnielsen]

Describe your environment

OS: Windows 11
Python version: 3.12
SDK version: 1.33.0
API version: 1.33.0

What happened?

With the release of opentelemetry 1.33.0 I am seeing infinit recursion errors on code that tries to log a message during shutdown. This means that code that previously would generate a single error now fills the screen with errors.

As far as I can see this is caused by BatchLogRecordProcessor.emit logging failures to export logs
here

In main this has moved to BatchProcessor.emit https://github.com/open-telemetry/opentelemetry-python/blob/release/v1.33.x-0.54bx/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/export/init.py#L291 but I expect the result to be the same.

Steps to Reproduce

Run the following example with pytest and otel 1.33.0

import atexit
import logging

from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
from opentelemetry.sdk._logs.export import (
    BatchLogRecordProcessor,
    ConsoleLogExporter,
)
from opentelemetry.sdk.resources import Resource

_LOGGER = logging.getLogger(__name__)


def log_something():
    print("Logging something...")
    _LOGGER.warning("This is a test warning message.")


atexit.register(log_something)


# Set up OpenTelemetry logging to a local file
resource = Resource.create({"service.name": "otelbug-demo"})
logger_provider = LoggerProvider(resource=resource)
log_exporter = ConsoleLogExporter()
logger_provider.add_log_record_processor(BatchLogRecordProcessor(log_exporter))

# Attach OpenTelemetry logging handler to Python logging
otel_handler = LoggingHandler(level=logging.NOTSET, logger_provider=logger_provider)
logging.getLogger().addHandler(otel_handler)
logging.getLogger().setLevel(logging.DEBUG)

_console_handler = logging.StreamHandler()
logging.getLogger().addHandler(_console_handler)
logging.getLogger().setLevel(logging.DEBUG)


def test_logging() -> None:
    # Test logging
    print("OpenTelemetry logging set up. Logs will be sent to the console.")


if __name__ == "__main__":
    # Set up OpenTelemetry logging
    test_logging()

e.g.

pytest nameoffile.py

Expected Result

Code runs as before with single error about message being logged about IOErrror

============================================================================================================================ test session starts ============================================================================================================================
platform win32 -- Python 3.12.10, pytest-8.3.5, pluggy-1.5.0
rootdir: D:\source\repos\project
configfile: pyproject.toml
plugins: hypothesis-6.131.17, cov-6.1.1, mock-3.14.0, timeout-2.4.0, xdist-3.6.1
collected 1 item

otelbug.py .                                                                                                                                                                                                                                                           [100%]

============================================================================================================================= 1 passed in 0.62s =============================================================================================================================
Logging something...
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "D:\source\repos\project\otelbug.py", line 16, in log_something
    _LOGGER.warning("This is a test warning message.")
Message: 'This is a test warning message.'
Arguments: ()

This is what happens with otel 1.32.1

Note that this ValueError is due to an interaction between pytest, atexit and the the non otel console handler in the example above

Actual Result

Python exiting with an infinit recursion error

❯ pytest otelbug.py -n 0
============================================================================================================================ test session starts ============================================================================================================================
platform win32 -- Python 3.12.10, pytest-8.3.5, pluggy-1.5.0
rootdir: D:\source\repos\project
configfile: pyproject.toml
plugins: hypothesis-6.131.17, cov-6.1.1, mock-3.14.0, timeout-2.4.0, xdist-3.6.1
collected 1 item

otelbug.py .                                                                                                                                                                                                                                                           [100%]

============================================================================================================================= 1 passed in 0.89s =============================================================================================================================
Logging something...
Exception ignored in atexit callback: <function log_something at 0x0000025243060400>
Traceback (most recent call last):
  File "D:\source\repos\project\otelbug.py", line 16, in log_something
    _LOGGER.warning("This is a test warning message.")
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1551, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1684, in _log
    self.handle(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1028, in handle
    self.emit(record)
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 569, in emit
    logger.emit(self._translate(record))
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 610, in emit
    self._multi_log_record_processor.emit(log_data)
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 330, in emit
    lp.emit(log_data)
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\export\__init__.py", line 291, in emit
    _logger.info("Shutdown called, ignoring log.")
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1539, in info
    self._log(INFO, msg, args, **kwargs)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1684, in _log
    self.handle(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1028, in handle
    self.emit(record)
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 569, in emit
    logger.emit(self._translate(record))
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 610, in emit
    self._multi_log_record_processor.emit(log_data)
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 330, in emit
    lp.emit(log_data)
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\export\__init__.py", line 291, in emit
    _logger.info("Shutdown called, ignoring log.")
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1539, in info
    self._log(INFO, msg, args, **kwargs)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1684, in _log
    self.handle(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "C:\Users\jenielse\AppData\Roaming\uv\python\cpython-3.12.10-windows-x86_64-none\Lib\logging\__init__.py", line 1028, in handle
    self.emit(record)
  File "D:\source\repos\project\.venv\Lib\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 569, in emit

Additional context

No response

Would you like to implement a fix?

None

[jenshnielsen]

Note that the general issue here #4261 may be relevant

[aabmass]

Thanks you for the detailed report and repro. @DylanRussell will send a quick PR to fix this and we're planning to make a patch release.

Long term we need to make this less error prone, I'll leave some thoughts on the general issue.

[DylanRussell]

Sent out #4586

[aabmass]

This is released in https://github.com/open-telemetry/opentelemetry-python/releases/tag/v1.33.1

[jenshnielsen]

Thanks @DylanRussell and @aabmass for the quick fix :)