Console logging for OTel logs

logfire/_internal/config.py

@@ -81,6 +81,7 @@
 )
 from .exporters.console import (
     ConsoleColorsValues,
+    ConsoleLogExporter,
     IndentedConsoleSpanExporter,
     ShowParentsConsoleSpanExporter,
     SimpleConsoleSpanExporter,
@@ -822,6 +823,8 @@ def add_span_processor(span_processor: SpanProcessor) -> None:
                 for processor in self.additional_span_processors:
                     add_span_processor(processor)
 
+            log_record_processors = list(self.advanced.log_record_processors)
+
             if self.console:
                 if self.console.span_style == 'simple':  # pragma: no cover
                     exporter_cls = SimpleConsoleSpanExporter
@@ -830,24 +833,20 @@ def add_span_processor(span_processor: SpanProcessor) -> None:
                 else:
                     assert self.console.span_style == 'show-parents'
                     exporter_cls = ShowParentsConsoleSpanExporter
-                add_span_processor(
-                    SimpleSpanProcessor(
-                        exporter_cls(
-                            colors=self.console.colors,
-                            include_timestamp=self.console.include_timestamps,
-                            include_tags=self.console.include_tags,
-                            verbose=self.console.verbose,
-                            min_log_level=self.console.min_log_level,
-                        ),
-                    )
+                console_span_exporter = exporter_cls(
+                    colors=self.console.colors,
+                    include_timestamp=self.console.include_timestamps,
+                    include_tags=self.console.include_tags,
+                    verbose=self.console.verbose,
+                    min_log_level=self.console.min_log_level,
                 )
+                add_span_processor(SimpleSpanProcessor(console_span_exporter))
+                log_record_processors.append(SimpleLogRecordProcessor(ConsoleLogExporter(console_span_exporter)))
 
             metric_readers: list[MetricReader] | None = None
             if isinstance(self.metrics, MetricsOptions):
                 metric_readers = list(self.metrics.additional_readers)
 
-            log_record_processors = list(self.advanced.log_record_processors)
-
             if self.send_to_logfire:
                 credentials: LogfireCredentials | None = None
                 show_project_link: bool = self.console and self.console.show_project_link or False

logfire/_internal/exporters/console.py

@@ -9,10 +9,13 @@
 import os
 import sys
 from collections.abc import Sequence
+from dataclasses import dataclass
 from datetime import datetime, timezone
 from textwrap import indent as indent_text
 from typing import Any, List, Literal, Mapping, TextIO, Tuple, cast
 
+from opentelemetry.sdk._logs import LogData, LogRecord
+from opentelemetry.sdk._logs.export import LogExporter, LogExportResult
 from opentelemetry.sdk.trace import Event, ReadableSpan
 from opentelemetry.sdk.trace.export import SpanExporter, SpanExportResult
 from opentelemetry.util import types as otel_types
@@ -35,6 +38,7 @@
     LevelName,
 )
 from ..json_formatter import json_args_value_formatter
+from ..utils import truncate_string
 
 ConsoleColorsValues = Literal['auto', 'always', 'never']
 _INFO_LEVEL = LEVEL_NUMBERS['info']
@@ -46,6 +50,59 @@
 TextParts = List[Tuple[str, str]]
 
 
+@dataclass
+class Record:
+    attributes: Mapping[str, otel_types.AttributeValue]
+    timestamp: int
+    message: str
+    events: Sequence[Event]
+    span_id: int | None
+    parent_span_id: int | None
+    kind: str
+    level: int
+
+    @classmethod
+    def from_span(cls, span: ReadableSpan) -> Record:
+        attributes = span.attributes or {}
+        return cls(
+            attributes=attributes,
+            timestamp=span.start_time or 0,
+            message=attributes.get(ATTRIBUTES_MESSAGE_KEY) or span.name,  # type: ignore
+            events=span.events,
+            span_id=span.context and span.context.span_id,
+            parent_span_id=span.parent and span.parent.span_id,
+            kind=attributes.get(ATTRIBUTES_SPAN_TYPE_KEY, 'span'),  # type: ignore
+            level=attributes.get(ATTRIBUTES_LOG_LEVEL_NUM_KEY, _INFO_LEVEL),  # type: ignore
+        )
+
+    @classmethod
+    def from_log(cls, log: LogRecord) -> Record:
+        attributes = log.attributes or {}
+        message: str = attributes.get(ATTRIBUTES_MESSAGE_KEY)  # type: ignore
+        if not message:
+            # TODO: this message could be better, for now we just want to have *something*
+            # TODO: this message should be constructed in a wrapper processor so that it's also used in the UI
+            parts: list[str] = []
+            if event_name := attributes.get('event.name'):
+                parts.append(str(event_name))
+            if body := log.body:
+                parts.append(truncate_string(str(body), max_length=100))
+            else:
+                other_attributes = {k: v for k, v in attributes.items() if k != 'event.name'}
+                parts.append(truncate_string(str(other_attributes), max_length=100))
+            message = ': '.join(parts)
+        return cls(
+            attributes=attributes,
+            timestamp=log.timestamp or log.observed_timestamp or 0,
+            message=message,
+            events=[],
+            span_id=None,
+            parent_span_id=log.span_id,
+            kind='log',
+            level=log.severity_number.value if log.severity_number else _INFO_LEVEL,
+        )
+
+
 class SimpleConsoleSpanExporter(SpanExporter):
     """The ConsoleSpanExporter prints spans to the console.
 
@@ -89,29 +146,26 @@ def __init__(
     def export(self, spans: Sequence[ReadableSpan]) -> SpanExportResult:
         """Export the spans to the console."""
         for span in spans:
-            self._log_span(span)
+            self.export_record(Record.from_span(span))
 
         return SpanExportResult.SUCCESS
 
-    def _log_span(self, span: ReadableSpan) -> None:
+    def export_record(self, span: Record) -> None:
         """Print a summary of the span, this method can be overridden to customize how spans are displayed.
 
         In this simple case we just print the span if its type is not "span" - e.g. the message at the end of a span.
         """
         self._print_span(span)
 
-    def _print_span(self, span: ReadableSpan, indent: int = 0):
+    def _print_span(self, span: Record, indent: int = 0):
         """Build up a summary of the span, including formatting for rich, then print it."""
         _msg, parts = self._span_text_parts(span, indent)
 
-        if span.attributes:  # pragma: no branch
-            span_type = span.attributes.get(ATTRIBUTES_SPAN_TYPE_KEY, 'span')
-            # only print for "pending_span" (received at the start of a span) and "log" (spans with no duration)
-            if span_type == 'span' or span.attributes.get(DISABLE_CONSOLE_KEY):
-                return
-            log_level: int = span.attributes.get(ATTRIBUTES_LOG_LEVEL_NUM_KEY, _INFO_LEVEL)  # type: ignore
-            if log_level < self._min_log_level_num:
-                return
+        # only print for "pending_span" (received at the start of a span) and "log" (spans with no duration)
+        if span.kind == 'span' or span.attributes.get(DISABLE_CONSOLE_KEY):
+            return
+        if span.level < self._min_log_level_num:
+            return
 
         indent_str = (self._timestamp_indent + indent * 2) * ' '
         details_parts = self._details_parts(span, indent_str)
@@ -130,7 +184,7 @@ def _print_span(self, span: ReadableSpan, indent: int = 0):
         exc_event = next((event for event in span.events or [] if event.name == 'exception'), None)
         self._print_exc_info(exc_event, indent_str)
 
-    def _span_text_parts(self, span: ReadableSpan, indent: int) -> tuple[str, TextParts]:
+    def _span_text_parts(self, span: Record, indent: int) -> tuple[str, TextParts]:
         """Return the formatted message or span name and parts containing basic span information.
 
         The following information is included:
@@ -142,22 +196,16 @@ def _span_text_parts(self, span: ReadableSpan, indent: int) -> tuple[str, TextPa
         """
         parts: TextParts = []
         if self._include_timestamp:
-            ts = datetime.fromtimestamp((span.start_time or 0) / ONE_SECOND_IN_NANOSECONDS, tz=timezone.utc)
+            ts = datetime.fromtimestamp(span.timestamp / ONE_SECOND_IN_NANOSECONDS, tz=timezone.utc)
             # ugly though it is, `[:-3]` is the simplest way to convert microseconds -> milliseconds
             ts_str = f'{ts:%H:%M:%S.%f}'[:-3]
             parts += [(ts_str, 'green'), (' ', '')]
 
         if indent:
             parts += [(indent * '  ', '')]
 
-        if span.attributes:  # pragma: no branch
-            formatted_message: str | None = span.attributes.get(ATTRIBUTES_MESSAGE_KEY)  # type: ignore
-            msg = formatted_message or span.name
-            level: int = span.attributes.get(ATTRIBUTES_LOG_LEVEL_NUM_KEY) or 0  # type: ignore
-        else:  # pragma: no cover
-            msg = span.name
-            level = 0
-
+        msg = span.message
+        level = span.level
         if level >= _ERROR_LEVEL:
             # add the message in red if it's an error or worse
             parts += [(msg, 'red')]
@@ -168,13 +216,13 @@ def _span_text_parts(self, span: ReadableSpan, indent: int) -> tuple[str, TextPa
             parts += [(msg, '')]
 
         if self._include_tags:
-            if tags := span.attributes and span.attributes.get(ATTRIBUTES_TAGS_KEY):
+            if tags := span.attributes.get(ATTRIBUTES_TAGS_KEY):
                 tags_str = ','.join(cast('list[str]', tags))
                 parts += [(' ', ''), (f'[{tags_str}]', 'cyan')]
 
         return msg, parts
 
-    def _details_parts(self, span: ReadableSpan, indent_str: str) -> TextParts:
+    def _details_parts(self, span: Record, indent_str: str) -> TextParts:
         """Return parts containing details for the span if `self._verbose` is True.
 
         The following details are returned:
@@ -204,7 +252,7 @@ def _details_parts(self, span: ReadableSpan, indent_str: str) -> TextParts:
         else:
             return []
 
-    def _print_arguments(self, span: ReadableSpan, indent_str: str):
+    def _print_arguments(self, span: Record, indent_str: str):
         """Pretty-print formatted logfire arguments for the span if `self._verbose` is True."""
         if not self._verbose or not span.attributes:
             return
@@ -307,27 +355,25 @@ def __init__(
         # lookup from span ID to indent level
         self._indent_level: dict[int, int] = {}
 
-    def _log_span(self, span: ReadableSpan) -> None:
+    def export_record(self, span: Record) -> None:
         """Get the span indent based on `self._indent_level`, then print the span with that indent."""
-        attributes = span.attributes or {}
-        span_type = attributes.get(ATTRIBUTES_SPAN_TYPE_KEY, 'span')
-        if span_type == 'span':
+        if span.kind == 'span':
             # this is the end of a span, remove it from `self._indent_level` and don't print
-            if span.context:  # pragma: no branch
-                self._indent_level.pop(span.context.span_id, None)
+            if span.span_id is not None:  # pragma: no branch
+                self._indent_level.pop(span.span_id, None)
             return
 
-        if span_type == 'pending_span':
-            parent_id = _pending_span_parent(attributes)
+        block_span_id = span.parent_span_id
+        if span.kind == 'pending_span':
+            parent_id = _pending_span_parent(span.attributes)
             indent = self._indent_level.get(parent_id, 0) if parent_id else 0
 
             # block_span_id will be the parent_id for all subsequent spans and logs in this block
-            if block_span_id := span.parent.span_id if span.parent else None:  # pragma: no branch
+            if block_span_id is not None:  # pragma: no branch
                 self._indent_level[block_span_id] = indent + 1
         else:
             # this is a log, we just get the indent level from the parent span
-            parent_id = span.parent.span_id if span.parent else None
-            indent = self._indent_level.get(parent_id, 0) if parent_id else 0
+            indent = self._indent_level.get(block_span_id, 0) if block_span_id else 0
 
         self._print_span(span, indent)
 
@@ -356,41 +402,36 @@ def __init__(
         # current open span ids
         self._span_stack: list[int] = []
 
-    def _log_span(self, span: ReadableSpan) -> None:
+    def export_record(self, span: Record) -> None:
         """Print any parent spans which aren't in the current stack of displayed spans, then print this span."""
-        attributes = span.attributes or {}
-        span_type = attributes.get(ATTRIBUTES_SPAN_TYPE_KEY, 'span')
-        if span_type == 'span':
+        if span.kind == 'span':
             # this is the end of a span, remove it from `self._span_history` and `self._span_stack`, don't print
-            if span.context:  # pragma: no branch
-                self._span_history.pop(span.context.span_id, None)
-                if self._span_stack and self._span_stack[-1] == span.context.span_id:
+            if span.span_id is not None:  # pragma: no branch
+                self._span_history.pop(span.span_id, None)
+                if self._span_stack and self._span_stack[-1] == span.span_id:
                     self._span_stack.pop()
             return
 
         self._print_span(span)
 
-    def _span_text_parts(self, span: ReadableSpan, indent: int) -> tuple[str, TextParts]:
+    def _span_text_parts(self, span: Record, indent: int) -> tuple[str, TextParts]:
         """Parts for any parent spans which aren't in the current stack of displayed spans, then parts for this span."""
-        attributes = span.attributes or {}
-        span_type = attributes.get(ATTRIBUTES_SPAN_TYPE_KEY, 'span')
-
         parts: TextParts = []
-        if span_type == 'pending_span':
-            parent_id = _pending_span_parent(attributes)
+        block_span_id = span.parent_span_id
+        if span.kind == 'pending_span':
+            parent_id = _pending_span_parent(span.attributes)
             parts += self._parent_stack_text_parts(parent_id)
 
             indent = len(self._span_stack)
             msg, span_parts = super()._span_text_parts(span, indent)
             parts += span_parts
 
-            if block_span_id := span.parent and span.parent.span_id:  # pragma: no branch
+            if block_span_id is not None:  # pragma: no branch
                 self._span_history[block_span_id] = (indent, msg, parent_id or 0)
                 self._span_stack.append(block_span_id)
         else:
             # this is a log
-            parent_id = span.parent.span_id if span.parent else None
-            parts += self._parent_stack_text_parts(parent_id)
+            parts += self._parent_stack_text_parts(block_span_id)
             msg, span_parts = super()._span_text_parts(span, indent=len(self._span_stack))
             parts += span_parts
         return msg, parts
@@ -446,3 +487,17 @@ def _pending_span_parent(attributes: Mapping[str, otel_types.AttributeValue]) ->
     """
     if parent_id_str := attributes.get(ATTRIBUTES_PENDING_SPAN_REAL_PARENT_KEY):
         return int(parent_id_str, 16)  # type: ignore
+
+
+@dataclass
+class ConsoleLogExporter(LogExporter):
+    span_exporter: SimpleConsoleSpanExporter
+
+    def export(self, batch: Sequence[LogData]) -> LogExportResult:  # type: ignore
+        for log_data in batch:
+            self.span_exporter.export_record(Record.from_log(log_data.log_record))
+
+        return LogExportResult.SUCCESS
+
+    def shutdown(self):
+        self.span_exporter.shutdown()

tests/test_configure.py

@@ -27,7 +27,7 @@
 from opentelemetry.propagators.composite import CompositePropagator
 from opentelemetry.sdk._logs import LogRecordProcessor
 from opentelemetry.sdk._logs._internal import SynchronousMultiLogRecordProcessor
-from opentelemetry.sdk._logs.export import BatchLogRecordProcessor
+from opentelemetry.sdk._logs.export import BatchLogRecordProcessor, SimpleLogRecordProcessor
 from opentelemetry.sdk.metrics._internal.export import PeriodicExportingMetricReader
 from opentelemetry.sdk.metrics.export import InMemoryMetricReader
 from opentelemetry.sdk.trace import ReadableSpan, SpanProcessor, SynchronousMultiSpanProcessor
@@ -52,7 +52,7 @@
     LogfireCredentials,
     sanitize_project_name,
 )
-from logfire._internal.exporters.console import ShowParentsConsoleSpanExporter
+from logfire._internal.exporters.console import ConsoleLogExporter, ShowParentsConsoleSpanExporter
 from logfire._internal.exporters.logs import CheckSuppressInstrumentationLogProcessorWrapper
 from logfire._internal.exporters.otlp import QuietLogExporter, QuietSpanExporter
 from logfire._internal.exporters.processor_wrapper import (
@@ -1442,10 +1442,10 @@ def test_default_exporters(monkeypatch: pytest.MonkeyPatch):
     logfire.configure(send_to_logfire=True, token='foo')
     wait_for_check_token_thread()
 
-    [console_processor, send_to_logfire_processor, pending_span_processor] = get_span_processors()
+    [console_span_processor, send_to_logfire_processor, pending_span_processor] = get_span_processors()
 
-    assert isinstance(console_processor, SimpleSpanProcessor)
-    assert isinstance(console_processor.span_exporter, ShowParentsConsoleSpanExporter)
+    assert isinstance(console_span_processor, SimpleSpanProcessor)
+    assert isinstance(console_span_processor.span_exporter, ShowParentsConsoleSpanExporter)
 
     assert isinstance(send_to_logfire_processor, BatchSpanProcessor)
     assert isinstance(send_to_logfire_processor.span_exporter, RemovePendingSpansExporter)
@@ -1454,15 +1454,20 @@ def test_default_exporters(monkeypatch: pytest.MonkeyPatch):
     assert isinstance(pending_span_processor.processor, MainSpanProcessorWrapper)
     assert isinstance(pending_span_processor.processor.processor, SynchronousMultiSpanProcessor)
     assert pending_span_processor.processor.processor._span_processors == (  # type: ignore
-        console_processor,
+        console_span_processor,
         send_to_logfire_processor,
     )
 
     [logfire_metric_reader] = get_metric_readers()
     assert isinstance(logfire_metric_reader, PeriodicExportingMetricReader)
     assert isinstance(logfire_metric_reader._exporter, QuietMetricExporter)  # type: ignore
 
-    [logfire_log_processor] = get_log_record_processors()
+    [console_log_processor, logfire_log_processor] = get_log_record_processors()
+
+    assert isinstance(console_log_processor, SimpleLogRecordProcessor)
+    assert isinstance(console_log_processor._exporter, ConsoleLogExporter)  # type: ignore
+    assert console_log_processor._exporter.span_exporter is console_span_processor.span_exporter  # type: ignore
+
     assert isinstance(logfire_log_processor, BatchLogRecordProcessor)
     assert isinstance(logfire_log_processor._exporter, QuietLogExporter)  # type: ignore
     assert isinstance(logfire_log_processor._exporter.exporter, OTLPLogExporter)  # type: ignore