Adapt structlog logs for Sentry (#119)

* Add structlog integration and debug changes to litestar example

* Remove and re-add filter_by_level, add Sentry before_send hook with JSON processing

* Refactor Sentry instrument to improve log processing and type safety

* Remove debug param and enhance Sentry event processing

* Refactor Sentry instrument and add tests for structlog event enrichment

* Clean up unused imports and simplify app creation in litestar example

Author: vrslev

microbootstrap/instruments/logging_instrument.py

@@ -73,7 +73,6 @@ def tracer_injection(_: WrappedLogger, __: str, event_dict: EventDict) -> EventD
 
 
 STRUCTLOG_PRE_CHAIN_PROCESSORS: typing.Final[list[typing.Any]] = [
-    structlog.stdlib.filter_by_level,
     structlog.stdlib.add_log_level,
     structlog.stdlib.add_logger_name,
     tracer_injection,
@@ -162,6 +161,7 @@ def _unset_handlers(self) -> None:
     def _configure_structlog_loggers(self) -> None:
         structlog.configure(
             processors=[
+                structlog.stdlib.filter_by_level,
                 *STRUCTLOG_PRE_CHAIN_PROCESSORS,
                 *self.instrument_config.logging_extra_processors,
                 STRUCTLOG_FORMATTER_PROCESSOR,

microbootstrap/instruments/sentry_instrument.py

@@ -2,8 +2,10 @@
 import contextlib
 import typing
 
+import orjson
 import pydantic
 import sentry_sdk
+from sentry_sdk import _types as sentry_types
 from sentry_sdk.integrations import Integration  # noqa: TC002
 
 from microbootstrap.instruments.base import BaseInstrumentConfig, Instrument
@@ -21,6 +23,53 @@ class SentryConfig(BaseInstrumentConfig):
     sentry_integrations: list[Integration] = pydantic.Field(default_factory=list)
     sentry_additional_params: dict[str, typing.Any] = pydantic.Field(default_factory=dict)
     sentry_tags: dict[str, str] | None = None
+    sentry_before_send: typing.Callable[[typing.Any, typing.Any], typing.Any | None] | None = None
+
+
+IGNORED_STRUCTLOG_ATTRIBUTES: typing.Final = frozenset({"event", "level", "logger", "tracing", "timestamp"})
+
+
+def enrich_sentry_event_from_structlog_log(event: sentry_types.Event, _hint: sentry_types.Hint) -> sentry_types.Event:
+    if (
+        (logentry := event.get("logentry"))
+        and (formatted_message := logentry.get("formatted"))
+        and (isinstance(formatted_message, str))
+        and formatted_message.startswith("{")
+        and (isinstance(event.get("contexts"), dict))
+    ):
+        try:
+            loaded_formatted_log = orjson.loads(formatted_message)
+        except orjson.JSONDecodeError:
+            return event
+        if not isinstance(loaded_formatted_log, dict):
+            return event
+
+        if event_name := loaded_formatted_log.get("event"):
+            event["logentry"]["formatted"] = event_name  # type: ignore[index]
+        else:
+            return event
+
+        additional_extra = loaded_formatted_log
+        for one_attr in IGNORED_STRUCTLOG_ATTRIBUTES:
+            additional_extra.pop(one_attr, None)
+        if additional_extra:
+            event["contexts"]["structlog"] = additional_extra
+
+    return event
+
+
+def wrap_before_send_callbacks(*callbacks: sentry_types.EventProcessor | None) -> sentry_types.EventProcessor:
+    def run_before_send(event: sentry_types.Event, hint: sentry_types.Hint) -> sentry_types.Event | None:
+        for callback in callbacks:
+            if not callback:
+                continue
+            temp_event = callback(event, hint)
+            if temp_event is None:
+                return None
+            event = temp_event
+        return event
+
+    return run_before_send
 
 
 class SentryInstrument(Instrument[SentryConfig]):
@@ -39,6 +88,9 @@ def bootstrap(self) -> None:
             max_breadcrumbs=self.instrument_config.sentry_max_breadcrumbs,
             max_value_length=self.instrument_config.sentry_max_value_length,
             attach_stacktrace=self.instrument_config.sentry_attach_stacktrace,
+            before_send=wrap_before_send_callbacks(
+                enrich_sentry_event_from_structlog_log, self.instrument_config.sentry_before_send
+            ),
             integrations=self.instrument_config.sentry_integrations,
             **self.instrument_config.sentry_additional_params,
         )

tests/instruments/test_sentry.py

@@ -1,12 +1,21 @@
+from __future__ import annotations
+import copy
 import typing
+from unittest import mock
 from unittest.mock import patch
 
 import litestar
+import pytest
 from litestar.testing import TestClient as LitestarTestClient
 
-from microbootstrap import SentryConfig
 from microbootstrap.bootstrappers.litestar import LitestarSentryInstrument
-from microbootstrap.instruments.sentry_instrument import SentryInstrument
+from microbootstrap.instruments.sentry_instrument import SentryInstrument, enrich_sentry_event_from_structlog_log
+
+
+if typing.TYPE_CHECKING:
+    from sentry_sdk import _types as sentry_types
+
+    from microbootstrap import SentryConfig
 
 
 def test_sentry_is_ready(minimal_sentry_config: SentryConfig) -> None:
@@ -57,3 +66,47 @@ async def error_handler() -> None:
             test_client.get("/test-error-handler")
 
         assert mock_capture_event.called
+
+
+class TestSentryEnrichEventFromStructlog:
+    @pytest.mark.parametrize(
+        "event",
+        [
+            {},
+            {"logentry": None},
+            {"logentry": {}},
+            {"logentry": {"formatted": b""}},
+            {"logentry": {"formatted": ""}},
+            {"logentry": {"formatted": "hi"}},
+            {"logentry": {"formatted": "[]"}},
+            {"logentry": {"formatted": "[{}]"}},
+            {"logentry": {"formatted": "{"}, "contexts": {}},
+            {"logentry": {"formatted": "{}"}, "contexts": {}},
+        ],
+    )
+    def test_skip(self, event: sentry_types.Event) -> None:
+        assert enrich_sentry_event_from_structlog_log(copy.deepcopy(event), mock.Mock()) == event
+
+    @pytest.mark.parametrize(
+        ("event_before", "event_after"),
+        [
+            (
+                {"logentry": {"formatted": '{"event": "event name"}'}, "contexts": {}},
+                {"logentry": {"formatted": "event name"}, "contexts": {}},
+            ),
+            (
+                {
+                    "logentry": {
+                        "formatted": '{"event": "event name", "timestamp": 1, "level": "error", "logger": "event.logger", "tracing": {}, "foo": "bar"}'  # noqa: E501
+                    },
+                    "contexts": {},
+                },
+                {
+                    "logentry": {"formatted": "event name"},
+                    "contexts": {"structlog": {"foo": "bar"}},
+                },
+            ),
+        ],
+    )
+    def test_modify(self, event_before: sentry_types.Event, event_after: sentry_types.Event) -> None:
+        assert enrich_sentry_event_from_structlog_log(event_before, mock.Mock()) == event_after