Fix logging integrations with non-string messages (#179)

Author: alexmojaki

logfire/_internal/main.py

@@ -564,6 +564,11 @@ def log(
                 # Only do this if extra_attrs is not empty since the copy of `attributes` might be expensive.
                 # We update both because attributes_json_schema_properties looks at `attributes`.
                 attributes = {**attributes, **extra_attrs}
+        else:
+            # The message has already been filled in, presumably by a logging integration.
+            # Make sure it's a string.
+            msg = merged_attributes[ATTRIBUTES_MESSAGE_KEY] = str(msg)
+            msg_template = str(msg_template)
 
         otlp_attributes = user_attributes(merged_attributes)
         otlp_attributes = {

logfire/integrations/loguru.py

@@ -38,7 +38,7 @@ def fill_attributes(self, record: LogRecord) -> dict[str, Any]:
             while frame:  # pragma: no branch
                 if frame.f_code is _LOG_METHOD_CODE:
                     msg_template = frame.f_locals.get('message')
-                    if isinstance(msg_template, str):
+                    if msg_template is not None:
                         attributes[ATTRIBUTES_MESSAGE_TEMPLATE_KEY] = msg_template
                     else:  # pragma: no cover
                         _warn_inspection_failure()

logfire/integrations/structlog.py

@@ -4,6 +4,7 @@
 
 import logfire
 
+from .._internal.constants import ATTRIBUTES_MESSAGE_KEY
 from .logging import RESERVED_ATTRS as LOGGING_RESERVED_ATTRS
 
 RESERVED_ATTRS = LOGGING_RESERVED_ATTRS | {'level', 'event', 'timestamp'}
@@ -21,10 +22,10 @@ def __call__(self, logger: WrappedLogger, name: str, event_dict: EventDict) -> E
         attributes = {k: v for k, v in event_dict.items() if k not in RESERVED_ATTRS}
         level = event_dict.get('level', 'info').lower()
         # NOTE: An event can be `None` in structlog. We may want to create a default msg in those cases.
-        msg_template = event_dict.get('event') or 'structlog event'
+        attributes[ATTRIBUTES_MESSAGE_KEY] = message = event_dict.get('event') or 'structlog event'
         logfire.log(
             level=level,  # type: ignore
-            msg_template=msg_template,
+            msg_template=message,
             attributes=attributes,
             console_log=self.console_log,
             custom_scope_suffix='structlog',

tests/test_loguru.py

@@ -22,8 +22,10 @@ def test_loguru(exporter: TestExporter) -> None:
 
     try:
         raise ValueError('This is a test exception')
-    except ValueError:
+    except ValueError as e:
         logger.exception('An exception was raised: {foo}', foo='bar')
+        # Test logging a non-string message.
+        logger.warning(e)
 
     assert exporter.exported_spans_as_dict(fixed_line_number=None) == snapshot(
         [
@@ -93,5 +95,21 @@ def test_loguru(exporter: TestExporter) -> None:
                     }
                 ],
             },
+            {
+                'name': 'This is a test exception',
+                'context': {'trace_id': 4, 'span_id': 4, 'is_remote': False},
+                'parent': None,
+                'start_time': 5000000000,
+                'end_time': 5000000000,
+                'attributes': {
+                    'logfire.span_type': 'log',
+                    'logfire.level_num': 13,
+                    'logfire.msg_template': 'This is a test exception',
+                    'logfire.msg': 'This is a test exception',
+                    'code.filepath': 'test_loguru.py',
+                    'code.function': 'test_loguru',
+                    'code.lineno': 28,
+                },
+            },
         ]
     )

tests/test_stdlib_logging.py

@@ -277,3 +277,28 @@ def test_logging_from_opentelemetry(exporter: TestExporter) -> None:
             },
         ]
     )
+
+
+def test_logging_non_string(exporter: TestExporter, logger: Logger):
+    logger.error(123)
+
+    assert exporter.exported_spans_as_dict() == snapshot(
+        [
+            {
+                'name': '123',
+                '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': '123',
+                    'logfire.msg': '123',
+                    'code.filepath': 'test_stdlib_logging.py',
+                    'code.function': 'test_logging_non_string',
+                    'code.lineno': 123,
+                },
+            }
+        ]
+    )

tests/test_structlog.py

@@ -30,25 +30,44 @@ def logger() -> Any:
 
 
 def test_structlog(exporter: TestExporter, logger: Logger) -> None:
-    logger.info('This is now being logged.')
+    logger.info('This is now being logged: %s', 123)
+    logger.error(456)
+
     assert exporter.exported_spans_as_dict(fixed_line_number=None) == snapshot(
         [
             {
-                'name': 'This is now being logged.',
+                'name': 'This is now being logged: 123',
                 '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': 9,
-                    'logfire.msg_template': 'This is now being logged.',
-                    'logfire.msg': 'This is now being logged.',
+                    'logfire.msg_template': 'This is now being logged: 123',
+                    'logfire.msg': 'This is now being logged: 123',
                     'code.filepath': 'test_structlog.py',
                     'code.function': 'test_structlog',
                     'code.lineno': 33,
                     'logfire.disable_console_log': True,
                 },
-            }
+            },
+            {
+                'name': '456',
+                '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': 17,
+                    'logfire.msg_template': '456',
+                    'logfire.msg': '456',
+                    'code.filepath': 'test_structlog.py',
+                    'code.function': 'test_structlog',
+                    'code.lineno': 34,
+                    'logfire.disable_console_log': True,
+                },
+            },
         ]
     )