Logs SDK: *LogRecordProcessor logs exceptions via python logging leading to recursion

[lmolkova]

If log exporter raises an exception, it fails the process with RecursionError: maximum recursion depth exceeded

class MyExporter(LogExporter):
    def export(self, datas: Sequence[LogData]):
        raise Exception("Some exception")

    def shutdown(self):
        pass

    def force_flush(self, timeout_millis: int):
        pass

logger_provider = LoggerProvider(resource=resource)
logger_provider.add_log_record_processor(SimpleLogRecordProcessor(MyExporter()))
set_logger_provider(logger_provider)

handler = LoggingHandler(level=logging.NOTSET, logger_provider=logger_provider)
logging.getLogger().addHandler(handler)
logger1 = logging.getLogger("myapp.area1")
logger1.warning("Hello, World!")

You'd see something like

  ....
  File "path/to\Lib\logging\__init__.py", line 1684, in _log
    self.handle(record)
  File "path/to\Lib\logging\__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "path/to\Lib\logging\__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "path/to\Lib\logging\__init__.py", line 1028, in handle
    self.emit(record)
  File "C:\Users\limolkova\AppData\Local\Packages\PythonSoftwareFoundation.Python.3.12_qbz5n2kfra8p0\LocalCache\local-packages\Python312\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 580, in emit
    logger.emit(self._translate(record))
  File "C:\Users\limolkova\AppData\Local\Packages\PythonSoftwareFoundation.Python.3.12_qbz5n2kfra8p0\LocalCache\local-packages\Python312\site-packages\opentelemetry\sdk\_logs\_internal\__init__.py", line 621, in emit
    self._multi_log_record_processor.emit(log_data)
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 322, in emit
    lp.emit(log_data)
  File "path/to\opentelemetry\sdk\_logs\_internal\export\__init__.py", line 131, in emit
    _logger.exception("Exception while exporting logs.")
  File "path/to\Lib\logging\__init__.py", line 1574, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "path/to\Lib\logging\__init__.py", line 1568, in error
    self._log(ERROR, msg, args, **kwargs)
  File "path/to\Lib\logging\__init__.py", line 1684, in _log
    self.handle(record)
  File "path/to\Lib\logging\__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "path/to\Lib\logging\__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "path/to\Lib\logging\__init__.py", line 1028, in handle
    self.emit(record)
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 580, in emit
    logger.emit(self._translate(record))
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 621, in emit
    self._multi_log_record_processor.emit(log_data)
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 322, in emit
    lp.emit(log_data)
  File "path/to\opentelemetry\sdk\_logs\_internal\export\__init__.py", line 131, in emit
    _logger.exception("Exception while exporting logs.")
  File "path/to\Lib\logging\__init__.py", line 1574, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "path/to\Lib\logging\__init__.py", line 1568, in error
    self._log(ERROR, msg, args, **kwargs)
  File "path/to\Lib\logging\__init__.py", line 1684, in _log
    self.handle(record)
  File "path/to\Lib\logging\__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "path/to\Lib\logging\__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "path/to\Lib\logging\__init__.py", line 1028, in handle
    self.emit(record)
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 580, in emit
    logger.emit(self._translate(record))
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 621, in emit
    self._multi_log_record_processor.emit(log_data)
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 322, in emit
    lp.emit(log_data)
  File "path/to\opentelemetry\sdk\_logs\_internal\export\__init__.py", line 131, in emit
    _logger.exception("Exception while exporting logs.")
  File "path/to\Lib\logging\__init__.py", line 1574, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "path/to\Lib\logging\__init__.py", line 1568, in error
    self._log(ERROR, msg, args, **kwargs)
  File "path/to\Lib\logging\__init__.py", line 1684, in _log
    self.handle(record)
  File "path/to\Lib\logging\__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "path/to\Lib\logging\__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "path/to\Lib\logging\__init__.py", line 1028, in handle
    self.emit(record)
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 580, in emit
    logger.emit(self._translate(record))
                ^^^^^^^^^^^^^^^^^^^^^^^
  File "path/to\opentelemetry\sdk\_logs\_internal\__init__.py", line 504, in _translate
    span_context = get_current_span().get_span_context()
                   ^^^^^^^^^^^^^^^^^^
  File "path/to\opentelemetry\trace\propagation\__init__.py", line 48, in get_current_span
    span = get_value(_SPAN_KEY, context=context)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "path/to\opentelemetry\context\__init__.py", line 94, in get_value
    return context.get(key) if context is not None else get_current().get(key)
                                                        ^^^^^^^^^^^^^
RecursionError: maximum recursion depth exceeded

This issue is originally discovered in a natural case of dependency version conflict and mismatch between exporter and the SDK.
While the exporter and/or app is to blame, we should handle it gracefully and avoid killing the app process.

The recommendation:

• use a different channel to report SDK issues (not python logging) and keep it off by default.
  AND/OR
• throttle self-reporting logs when publishing them to python.logging (e.g. log once and, if throttling, add a message on how to enable internal logging)

Related to open-telemetry/opentelemetry-python-contrib#2813

Part of open-telemetry/community#1751

[aabmass]

Yes, this problem keeps coming up. We have a "meta" bug here for it #4261 and I agree we need to rethink the approach like the recommendations you mentioned:

The recommendation:

• use a different channel to report SDK issues (not python logging) and keep it off by default.
  AND/OR
• throttle self-reporting logs when publishing them to python.logging (e.g. log once and, if throttling, add a message on how to enable internal logging)