diff --git a/logfire/integrations/logging.py b/logfire/integrations/logging.py index 01328b87f..4051bff25 100644 --- a/logfire/integrations/logging.py +++ b/logfire/integrations/logging.py @@ -2,7 +2,8 @@ from __future__ import annotations -from logging import Handler as LoggingHandler, LogRecord +import inspect +from logging import NOTSET, Handler as LoggingHandler, LogRecord, StreamHandler from typing import Any, ClassVar, Mapping, cast from logfire import log @@ -45,12 +46,31 @@ class LogfireLoggingHandler(LoggingHandler): custom_scope_suffix: ClassVar[str] = 'stdlib.logging' + def __init__(self, level: int | str = NOTSET, fallback: LoggingHandler = StreamHandler()) -> None: + super().__init__(level=level) + self.fallback = fallback + def emit(self, record: LogRecord) -> None: """Send the log to Logfire. Args: record: The log record to send. """ + if record.name.startswith('opentelemetry.'): + # This method can lead to OTEL calling logging methods which recursively calls this again. + # If we detect recursion, use the fallback handler instead. + # TODO find a better way to handle this, + # or document the fallback clearly and nudge the user to configure it. + frame = inspect.currentframe() + assert frame is not None + code_here = frame.f_code + frame = frame.f_back + while frame: + if frame.f_code is code_here: + self.fallback.emit(record) + return + frame = frame.f_back + attributes = self.fill_attributes(record) log( diff --git a/tests/test_stdlib_logging.py b/tests/test_stdlib_logging.py index 69900eb01..35e1d5351 100644 --- a/tests/test_stdlib_logging.py +++ b/tests/test_stdlib_logging.py @@ -1,9 +1,17 @@ +from __future__ import annotations + +import logging from logging import Logger, getLogger +from typing import Sequence import pytest from dirty_equals import IsJson, IsPositiveInt from inline_snapshot import snapshot +from opentelemetry.sdk.trace import ReadableSpan +from opentelemetry.sdk.trace.export import SimpleSpanProcessor, SpanExporter +from opentelemetry.trace import Status +import logfire from logfire.integrations.logging import LogfireLoggingHandler from logfire.testing import TestExporter @@ -173,3 +181,94 @@ def test_stdlib_logging_warning(exporter: TestExporter, logger: Logger) -> None: }, } ] + + +def test_recursive_logging_from_opentelemetry() -> None: + class ExceptionExporter(SpanExporter): + def export(self, spans: Sequence[ReadableSpan]): + raise Exception() + + logfire.configure( + send_to_logfire=False, + processors=[SimpleSpanProcessor(ExceptionExporter())], + ) + + class TestLoggingHandler(logging.Handler): + def __init__(self): + super().__init__() + self.logs: list[logging.LogRecord] = [] + self.emit = self.logs.append # type: ignore + + # Add our handler to the root logger (not the logger fixture) to get internal logs from OTEL. + logger = getLogger() + test_logging_handler = TestLoggingHandler() + logfire_logging_handler = LogfireLoggingHandler(fallback=test_logging_handler) + logger.addHandler(logfire_logging_handler) + + try: + # This calls ExceptionExporter.export which causes OTEL to log an exception. + # That log call goes to LogfireLoggingHandler.emit, which tries to emit another logfire log, + # causing another stdlib log from OTEL, potentially leading to infinite recursion. + # This tests that we handle that by using the fallback test_logging_handler when recursion is detected. + logfire.info('test') + finally: + # Don't mess with the root logger longer than needed. + logger.removeHandler(logfire_logging_handler) + + [record] = test_logging_handler.logs + # This is the message logged by OTEL. + assert record.message == 'Exception while exporting Span.' + + +def test_logging_from_opentelemetry(exporter: TestExporter) -> None: + # Add our handler to the root logger (not the logger fixture) to get internal logs from OTEL. + logger = getLogger() + logfire_logging_handler = LogfireLoggingHandler() + logger.addHandler(logfire_logging_handler) + try: + logger.error('test') # sanity check + + # This causes OTEL to log a warning. + # Unlike the test above, there's no risk of recursion since the exporter doesn't raise errors. + # So the log appears in the exported spans below. + Status(description=4) # type: ignore + finally: + # Don't mess with the root logger longer than needed. + logger.removeHandler(logfire_logging_handler) + + assert exporter.exported_spans_as_dict() == snapshot( + [ + { + 'name': 'test', + 'context': {'trace_id': 1, 'span_id': 1, 'is_remote': False}, + 'parent': None, + 'start_time': 1000000000, + 'end_time': 1000000000, + 'attributes': { + 'logfire.span_type': 'log', + 'logfire.level_num': 17, + 'logfire.msg_template': 'test', + 'logfire.msg': 'test', + 'code.filepath': 'test_stdlib_logging.py', + 'code.function': 'test_logging_from_opentelemetry', + 'code.lineno': 123, + }, + }, + { + 'name': 'Invalid status description type, expected str', + 'context': {'trace_id': 2, 'span_id': 2, 'is_remote': False}, + 'parent': None, + 'start_time': 2000000000, + 'end_time': 2000000000, + 'attributes': { + 'logfire.span_type': 'log', + 'logfire.level_num': 13, + 'logfire.msg_template': 'Invalid status description type, expected str', + 'logfire.msg': 'Invalid status description type, expected str', + 'code.filepath': 'status.py', + 'code.function': '__init__', + 'code.lineno': 123, + }, + }, + ] + )