Merge pull request #67 from modern-python/format-logs-sentry

format logs for sentry

Author: lesnik512

README.md

@@ -25,6 +25,11 @@ Those instruments can be bootstrapped for:
 - [services and scripts without frameworks](https://lite-bootstrap.readthedocs.io/integrations/free)
 ---
 
+Usage examples:
+
+- with LiteStar - [litestar-sqlalchemy-template](https://github.com/modern-python/litestar-sqlalchemy-template)
+- with FastAPI - [fastapi-sqlalchemy-template](https://github.com/modern-python/fastapi-sqlalchemy-template)
+
 ## 📚 [Documentation](https://lite-bootstrap.readthedocs.io)
 
 ## 📦 [PyPi](https://pypi.org/project/lite-bootstrap)

lite_bootstrap/instruments/sentry_instrument.py

@@ -1,18 +1,26 @@
 import dataclasses
 import typing
 
+import orjson
+
 from lite_bootstrap import import_checker
 from lite_bootstrap.instruments.base import BaseConfig, BaseInstrument
 
 
 if typing.TYPE_CHECKING:
+    from sentry_sdk import _types as sentry_types
     from sentry_sdk.integrations import Integration
 
 
 if import_checker.is_sentry_installed:
     import sentry_sdk
 
 
+IGNORED_STRUCTLOG_ATTRIBUTES: typing.Final = frozenset(
+    {"event", "level", "logger", "tracing", "timestamp", "exception"}
+)
+
+
 @dataclasses.dataclass(kw_only=True, frozen=True)
 class SentryConfig(BaseConfig):
     sentry_dsn: str | None = None
@@ -25,6 +33,62 @@ class SentryConfig(BaseConfig):
     sentry_additional_params: dict[str, typing.Any] = dataclasses.field(default_factory=dict)
     sentry_tags: dict[str, str] | None = None
     sentry_default_integrations: bool = True
+    sentry_before_send: typing.Callable[[typing.Any, typing.Any], typing.Any | None] | None = None
+
+
+def enrich_sentry_event_from_structlog_log(
+    event: "sentry_types.Event", _: "sentry_types.Hint"
+) -> typing.Optional["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):  # pragma: no cover
+            return event
+
+        if loaded_formatted_log.get("skip_sentry"):
+            return None
+
+        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: typing.Optional["sentry_types.EventProcessor"],
+) -> "sentry_types.EventProcessor":
+    def run_before_send(
+        event: "sentry_types.Event", hint: "sentry_types.Hint"
+    ) -> typing.Optional["sentry_types.Event"]:
+        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
 
 
 @dataclasses.dataclass(kw_only=True, slots=True, frozen=True)
@@ -50,6 +114,9 @@ def bootstrap(self) -> None:
             max_value_length=self.bootstrap_config.sentry_max_value_length,
             attach_stacktrace=self.bootstrap_config.sentry_attach_stacktrace,
             integrations=self.bootstrap_config.sentry_integrations,
+            before_send=wrap_before_send_callbacks(
+                enrich_sentry_event_from_structlog_log, self.bootstrap_config.sentry_before_send
+            ),
             **self.bootstrap_config.sentry_additional_params,
         )
         tags: dict[str, str] = self.bootstrap_config.sentry_tags or {}

tests/conftest.py

@@ -6,8 +6,7 @@
 import pytest
 import sentry_sdk
 from opentelemetry.instrumentation.instrumentor import BaseInstrumentor  # type: ignore[attr-defined]
-from structlog.testing import capture_logs
-from structlog.typing import EventDict
+from structlog.typing import EventDict, WrappedLogger
 
 from lite_bootstrap import import_checker
 
@@ -20,9 +19,6 @@ def _uninstrument(self, **kwargs: typing.Mapping[str, typing.Any]) -> None:
         pass
 
 
-P = typing.ParamSpec("P")
-
-
 class SentryTestTransport(sentry_sdk.Transport):
     def __init__(self, *args: typing.Any, **kwargs: typing.Any) -> None:  # noqa: ANN401
         super().__init__(*args, **kwargs)
@@ -37,6 +33,20 @@ def sentry_mock() -> SentryTestTransport:
     return SentryTestTransport()
 
 
+class LoggingMock:
+    def __init__(self) -> None:
+        self.entries: list[EventDict] = []
+
+    def __call__(self, _: WrappedLogger, __: str, event_dict: EventDict) -> EventDict:
+        self.entries.append(event_dict)
+        return event_dict
+
+
+@pytest.fixture
+def logging_mock() -> LoggingMock:
+    return LoggingMock()
+
+
 @contextlib.contextmanager
 def emulate_package_missing(package_name: str) -> typing.Iterator[None]:
     old_module = sys.modules[package_name]
@@ -47,9 +57,3 @@ def emulate_package_missing(package_name: str) -> typing.Iterator[None]:
     finally:
         sys.modules[package_name] = old_module
         reload(import_checker)
-
-
-@pytest.fixture(name="log_output")
-def fixture_log_output() -> typing.Iterator[list[EventDict]]:
-    with capture_logs() as cap_logs:
-        yield cap_logs

tests/instruments/test_logging_instrument.py

@@ -3,50 +3,48 @@
 
 import structlog
 from opentelemetry.trace import get_tracer
-from structlog.testing import LogCapture
 
 from lite_bootstrap.instruments.logging_instrument import LoggingConfig, LoggingInstrument, MemoryLoggerFactory
 from lite_bootstrap.instruments.opentelemetry_instrument import OpentelemetryConfig, OpenTelemetryInstrument
+from tests.conftest import LoggingMock
 
 
-std_logger = logging.getLogger(__name__)
-
-
-def test_logging_instrument_simple() -> None:
-    log_capture = LogCapture()
+def test_logging_instrument_simple(logging_mock: LoggingMock) -> None:
     logging_instrument = LoggingInstrument(
         bootstrap_config=LoggingConfig(
             logging_unset_handlers=["uvicorn"],
             logging_buffer_capacity=0,
             service_debug=False,
-            logging_extra_processors=[log_capture],
+            logging_extra_processors=[logging_mock],
         )
     )
     try:
         logging_instrument.bootstrap()
 
+        std_logger = logging.getLogger(__name__)
+        std_logger.info("testing std logger", extra={"key": "value"})
+
         logger = structlog.getLogger(__name__)
         logger.info("testing structlog", key="value")
-        std_logger.info("testing std logger", extra={"key": "value"})
+
         try:
             msg = "some error"
             raise ValueError(msg)  # noqa: TRY301
         except ValueError:
             logger.exception("logging error")
 
-        events_number = 2
-        assert len(log_capture.entries) == events_number
+        events_number = 3
+        assert len(logging_mock.entries) == events_number
     finally:
         logging_instrument.teardown()
 
 
-def test_logging_instrument_tracer_injection() -> None:
-    log_capture = LogCapture()
+def test_logging_instrument_tracer_injection(logging_mock: LoggingMock) -> None:
     logging_instrument = LoggingInstrument(
         bootstrap_config=LoggingConfig(
             logging_unset_handlers=["uvicorn"],
             logging_buffer_capacity=0,
-            logging_extra_processors=[log_capture],
+            logging_extra_processors=[logging_mock],
         )
     )
     opentelemetry_instrument = OpenTelemetryInstrument(
@@ -67,13 +65,13 @@ def test_logging_instrument_tracer_injection() -> None:
             span.add_event("example_event", {"event_attr": 1})
             logger.info("testing tracer injection with span attributes")
 
-        assert log_capture.entries[0]["event"] == "testing tracer injection without spans"
+        assert logging_mock.entries[0]["event"] == "testing tracer injection without spans"
 
-        assert log_capture.entries[1]["event"] == "testing tracer injection without span attributes"
-        assert log_capture.entries[2]["event"] == "testing tracer injection with span attributes"
+        assert logging_mock.entries[1]["event"] == "testing tracer injection without span attributes"
+        assert logging_mock.entries[2]["event"] == "testing tracer injection with span attributes"
 
-        tracing1 = log_capture.entries[1]["tracing"]
-        tracing2 = log_capture.entries[2]["tracing"]
+        tracing1 = logging_mock.entries[1]["tracing"]
+        tracing2 = logging_mock.entries[2]["tracing"]
         assert tracing1
         assert tracing1 == tracing2
     finally:

tests/instruments/test_sentry_instrument.py

@@ -1,22 +1,28 @@
+import copy
 import logging
 import typing
 
 import pytest
 import sentry_sdk
+import structlog
+from sentry_sdk.integrations.logging import LoggingIntegration
 
-from tests.conftest import SentryTestTransport
+from lite_bootstrap.instruments.logging_instrument import LoggingConfig, LoggingInstrument
+from tests.conftest import LoggingMock, SentryTestTransport
 
 
 if typing.TYPE_CHECKING:
-    pass
+    from sentry_sdk import _types as sentry_types
 
 from lite_bootstrap.instruments.sentry_instrument import (
     SentryConfig,
     SentryInstrument,
+    enrich_sentry_event_from_structlog_log,
 )
 
 
-logger = logging.getLogger(__name__)
+std_logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 
 @pytest.fixture
@@ -31,12 +37,80 @@ def minimal_sentry_config(sentry_mock: SentryTestTransport) -> SentryConfig:
 def test_sentry_instrument_with_raise(minimal_sentry_config: SentryConfig, sentry_mock: SentryTestTransport) -> None:
     SentryInstrument(bootstrap_config=minimal_sentry_config).bootstrap()
 
+    try:
+        std_logger.error("some error")
+        assert len(sentry_mock.mock_envelopes) == 1
+    finally:
+        sentry_sdk.init()
+
+
+def test_sentry_instrument_with_structlog_error(
+    minimal_sentry_config: SentryConfig, sentry_mock: SentryTestTransport, logging_mock: LoggingMock
+) -> None:
+    SentryInstrument(bootstrap_config=minimal_sentry_config).bootstrap()
+    logging_instrument = LoggingInstrument(
+        bootstrap_config=LoggingConfig(
+            logging_unset_handlers=["uvicorn"],
+            logging_buffer_capacity=0,
+            service_debug=False,
+            logging_extra_processors=[logging_mock],
+        )
+    )
+    logging_instrument.bootstrap()
+
     try:
         logger.error("some error")
+        logger.error("some error, skipping sentry", skip_sentry=True)
         assert len(sentry_mock.mock_envelopes) == 1
+        LoggingIntegration()
     finally:
         sentry_sdk.init()
+        logging_instrument.teardown()
 
 
 def test_sentry_instrument_empty_dsn() -> None:
     SentryInstrument(bootstrap_config=SentryConfig(sentry_dsn="")).bootstrap()
+
+
+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), {}) == 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, {}) == event_after