Add log level on on_start for ASGI send and receive messages (#94)

logfire/_internal/exporters/processor_wrapper.py

@@ -4,6 +4,7 @@
 
 from opentelemetry import context
 from opentelemetry.sdk.trace import ReadableSpan, Span, SpanProcessor
+from opentelemetry.sdk.util.instrumentation import InstrumentationScope
 from opentelemetry.semconv.trace import SpanAttributes
 
 from ..constants import (
@@ -35,13 +36,14 @@ def on_start(
     ) -> None:
         if context.get_value('suppress_instrumentation'):  # pragma: no cover
             return
+        _set_log_level_on_asgi_send_receive_spans(span)
         self.processor.on_start(span, parent_context)
 
     def on_end(self, span: ReadableSpan) -> None:
         if context.get_value('suppress_instrumentation'):  # pragma: no cover
             return
         span_dict = span_to_dict(span)
-        _tweak_asgi_send_recieve_spans(span_dict)
+        _tweak_asgi_send_receive_spans(span_dict)
         _tweak_http_spans(span_dict)
         self.scrubber.scrub_span(span_dict)
         span = ReadableSpan(**span_dict)
@@ -54,53 +56,51 @@ def force_flush(self, timeout_millis: int = 30000) -> bool:
         return self.processor.force_flush(timeout_millis)  # pragma: no cover
 
 
-def _tweak_asgi_send_recieve_spans(span: ReadableSpanDict):
-    """Make the name/message/level of spans generated by OTEL's ASGI middleware more useful.
+def _set_log_level_on_asgi_send_receive_spans(span: Span) -> None:
+    """Set the log level of ASGI send/receive spans to debug.
+
+    If a span doesn't have a level set, it defaults to 'info'. This is too high for ASGI send/receive spans,
+    which are generated for every request and are not particularly interesting.
+    """
+    if _is_asgi_send_receive_span(span.name, span.instrumentation_scope):
+        span.set_attributes(log_level_attributes('debug'))
+
+
+def _tweak_asgi_send_receive_spans(span: ReadableSpanDict) -> None:
+    """Make the name/message of spans generated by OTEL's ASGI middleware more useful.
 
     For example, a single request will typically generate two 'send' spans with the same message,
     e.g. 'GET /foo http send'. This function may add part of the ASGI event type to the name to make it more useful,
     so instead it shows e.g. 'http send response.start' and 'http send response.body'.
-
-    The log level of these spans is also set to debug, as they are not usually interesting to the user.
     """
-    instrumentation_scope = span['instrumentation_scope']
-    if not (instrumentation_scope and instrumentation_scope.name == 'opentelemetry.instrumentation.asgi'):
-        return
+    name = span['name']
+    if _is_asgi_send_receive_span(name, span['instrumentation_scope']):
+        attributes = span['attributes']
+        # The attribute name should be `asgi.event.type` after this is merged and released:
+        # https://github.com/open-telemetry/opentelemetry-python-contrib/pull/2300
+        typ = attributes.get('asgi.event.type') or attributes.get('type')
+        if not (
+            isinstance(typ, str)
+            and typ.startswith(('http.', 'websocket.'))
+            and attributes.get(ATTRIBUTES_MESSAGE_KEY) == name
+        ):  # pragma: no cover
+            return
 
-    if not (name := span['name']).endswith(
-        (
-            ' http send',
-            ' http receive',
-            ' websocket send',
-            ' websocket receive',
-        )
-    ):
-        return
+        # Strip the 'http.' or 'websocket.' prefix from the event type and add it to the span name.
+        if typ in ('websocket.send', 'websocket.receive'):
+            # No point in adding anything in this case, otherwise it'd say e.g. 'websocket send send'.
+            # No other event types in https://asgi.readthedocs.io/en/latest/specs/www.html are redundant like this.
+            new_name = name
+        else:
+            span['name'] = new_name = f'{name} {typ.split(".", 1)[1]}'
+
+        span['attributes'] = {**attributes, ATTRIBUTES_MESSAGE_KEY: new_name}
 
-    attributes = span['attributes']
-    # The attribute name should be `asgi.event.type` after this is merged and released:
-    # https://github.com/open-telemetry/opentelemetry-python-contrib/pull/2300
-    typ = attributes.get('asgi.event.type') or attributes.get('type')
-    if not (
-        isinstance(typ, str)
-        and typ.startswith(('http.', 'websocket.'))
-        and attributes.get(ATTRIBUTES_MESSAGE_KEY) == name
-    ):  # pragma: no cover
-        return
 
-    # Strip the 'http.' or 'websocket.' prefix from the event type and add it to the span name.
-    if typ in ('websocket.send', 'websocket.receive'):
-        # No point in adding anything in this case, otherwise it'd say e.g. 'websocket send send'.
-        # No other event types in https://asgi.readthedocs.io/en/latest/specs/www.html are redundant like this.
-        new_name = name
-    else:
-        span['name'] = new_name = f'{name} {typ.split(".", 1)[1]}'
-
-    span['attributes'] = {
-        **attributes,
-        ATTRIBUTES_MESSAGE_KEY: new_name,
-        **log_level_attributes('debug'),
-    }
+def _is_asgi_send_receive_span(name: str, instrumentation_scope: InstrumentationScope | None) -> bool:
+    return (
+        instrumentation_scope is not None and instrumentation_scope.name == 'opentelemetry.instrumentation.asgi'
+    ) and (name.endswith((' http send', ' http receive', ' websocket send', ' websocket receive')))
 
 
 def _tweak_http_spans(span: ReadableSpanDict):

tests/otel_integrations/test_fastapi.py

@@ -234,6 +234,7 @@ def test_path_param(client: TestClient, exporter: TestExporter) -> None:
                 'attributes': {
                     'logfire.span_type': 'pending_span',
                     'logfire.msg': 'GET /with_path_param/{param} http send',
+                    'logfire.level_num': 5,
                     'logfire.pending_parent_id': '0000000000000001',
                 },
             },
@@ -260,6 +261,7 @@ def test_path_param(client: TestClient, exporter: TestExporter) -> None:
                 'attributes': {
                     'logfire.span_type': 'pending_span',
                     'logfire.msg': 'GET /with_path_param/{param} http send',
+                    'logfire.level_num': 5,
                     'logfire.pending_parent_id': '0000000000000001',
                 },
             },
@@ -421,6 +423,7 @@ def test_fastapi_instrumentation(client: TestClient, exporter: TestExporter) ->
                 'attributes': {
                     'logfire.span_type': 'pending_span',
                     'logfire.pending_parent_id': '0000000000000003',
+                    'logfire.level_num': 5,
                     'logfire.msg': 'GET / http send',
                 },
             },
@@ -447,6 +450,7 @@ def test_fastapi_instrumentation(client: TestClient, exporter: TestExporter) ->
                 'attributes': {
                     'logfire.span_type': 'pending_span',
                     'logfire.pending_parent_id': '0000000000000003',
+                    'logfire.level_num': 5,
                     'logfire.msg': 'GET / http send',
                 },
             },