feat(logs): Add alpha version of Sentry logs

sentry_sdk/__init__.py

@@ -45,6 +45,7 @@
     "start_transaction",
     "trace",
     "monitor",
+    "_experimental_logger.py",
 ]
 
 # Initialize the debug support after everything is loaded

sentry_sdk/_experimental_logger.py

@@ -0,0 +1,20 @@
+# NOTE: this is the logger sentry exposes to users, not some generic logger.
+import functools
+from typing import Any
+
+from sentry_sdk import get_client, get_current_scope
+
+
+def _capture_log(severity_text, severity_number, template, **kwargs):
+    # type: (str, int, str, **Any) -> None
+    client = get_client()
+    scope = get_current_scope()
+    client.capture_log(scope, severity_text, severity_number, template, **kwargs)
+
+
+trace = functools.partial(_capture_log, "trace", 1)
+debug = functools.partial(_capture_log, "debug", 5)
+info = functools.partial(_capture_log, "info", 9)
+warn = functools.partial(_capture_log, "warn", 13)
+error = functools.partial(_capture_log, "error", 17)
+fatal = functools.partial(_capture_log, "fatal", 21)

sentry_sdk/_types.py

@@ -207,6 +207,17 @@ class SDKInfo(TypedDict):
     ]
 
     Hint = Dict[str, Any]
+    Log = TypedDict(
+        "Log",
+        {
+            "severity_text": str,
+            "severity_number": int,
+            "body": str,
+            "attributes": dict[str, str | bool | float | int],
+            "time_unix_nano": int,
+            "trace_id": Optional[str],
+        },
+    )
 
     Breadcrumb = Dict[str, Any]
     BreadcrumbHint = Dict[str, Any]
@@ -217,6 +228,7 @@ class SDKInfo(TypedDict):
     ErrorProcessor = Callable[[Event, ExcInfo], Optional[Event]]
     BreadcrumbProcessor = Callable[[Breadcrumb, BreadcrumbHint], Optional[Breadcrumb]]
     TransactionProcessor = Callable[[Event, Hint], Optional[Event]]
+    LogProcessor = Callable[[Log, Hint], Optional[Log]]
 
     TracesSampler = Callable[[SamplingContext], Union[float, int, bool]]
 
@@ -237,6 +249,7 @@ class SDKInfo(TypedDict):
         "metric_bucket",
         "monitor",
         "span",
+        "log",
     ]
     SessionStatus = Literal["ok", "exited", "crashed", "abnormal"]
 

sentry_sdk/client.py

@@ -1,7 +1,10 @@
+import json
 import os
+import time
 import uuid
 import random
 import socket
+import logging
 from collections.abc import Mapping
 from datetime import datetime, timezone
 from importlib import import_module
@@ -55,7 +58,7 @@
     from typing import Union
     from typing import TypeVar
 
-    from sentry_sdk._types import Event, Hint, SDKInfo
+    from sentry_sdk._types import Event, Hint, SDKInfo, Log
     from sentry_sdk.integrations import Integration
     from sentry_sdk.metrics import MetricsAggregator
     from sentry_sdk.scope import Scope
@@ -206,6 +209,10 @@ def capture_event(self, *args, **kwargs):
         # type: (*Any, **Any) -> Optional[str]
         return None
 
+    def capture_log(self, scope, severity_text, severity_number, template, **kwargs):
+        # type: (Scope, str, int, str, **Any) -> None
+        pass
+
     def capture_session(self, *args, **kwargs):
         # type: (*Any, **Any) -> None
         return None
@@ -847,6 +854,110 @@ def capture_event(
 
         return return_value
 
+    def capture_log(self, scope, severity_text, severity_number, template, **kwargs):
+        # type: (Scope, str, int, str, **Any) -> None
+        logs_enabled = self.options["_experiments"].get("enable_sentry_logs", False)
+        if not logs_enabled:
+            return
+
+        headers = {
+            "sent_at": format_timestamp(datetime.now(timezone.utc)),
+        }  # type: dict[str, object]
+
+        attrs = {
+            "sentry.message.template": template,
+        }  # type: dict[str, str | bool | float | int]
+
+        kwargs_attributes = kwargs.get("attributes")
+        if kwargs_attributes is not None:
+            attrs.update(kwargs_attributes)
+
+        environment = self.options.get("environment")
+        if environment is not None:
+            attrs["sentry.environment"] = environment
+
+        release = self.options.get("release")
+        if release is not None:
+            attrs["sentry.release"] = release
+
+        span = scope.span
+        if span is not None:
+            attrs["sentry.trace.parent_span_id"] = span.span_id
+
+        for k, v in kwargs.items():
+            attrs[f"sentry.message.parameters.{k}"] = v
+
+        log = {
+            "severity_text": severity_text,
+            "severity_number": severity_number,
+            "body": template.format(**kwargs),
+            "attributes": attrs,
+            "time_unix_nano": time.time_ns(),
+            "trace_id": None,
+        }  # type: Log
+
+        # If debug is enabled, log the log to the console
+        debug = self.options.get("debug", False)
+        if debug:
+            severity_text_to_logging_level = {
+                "trace": logging.DEBUG,
+                "debug": logging.DEBUG,
+                "info": logging.INFO,
+                "warn": logging.WARNING,
+                "error": logging.ERROR,
+                "fatal": logging.CRITICAL,
+            }
+            logger.log(
+                severity_text_to_logging_level.get(severity_text, logging.DEBUG),
+                f'[Sentry Logs] {log["body"]}',
+            )
+
+        propagation_context = scope.get_active_propagation_context()
+        if propagation_context is not None:
+            headers["trace_id"] = propagation_context.trace_id
+            log["trace_id"] = propagation_context.trace_id
+
+        envelope = Envelope(headers=headers)
+
+        before_emit_log = self.options["_experiments"].get("before_emit_log")
+        if before_emit_log is not None:
+            log = before_emit_log(log, {})
+        if log is None:
+            return
+
+        def format_attribute(key, val):
+            # type: (str, int | float | str | bool) -> Any
+            if isinstance(val, bool):
+                return {"key": key, "value": {"boolValue": val}}
+            if isinstance(val, int):
+                return {"key": key, "value": {"intValue": str(val)}}
+            if isinstance(val, float):
+                return {"key": key, "value": {"doubleValue": val}}
+            if isinstance(val, str):
+                return {"key": key, "value": {"stringValue": val}}
+            return {"key": key, "value": {"stringValue": json.dumps(val)}}
+
+        otel_log = {
+            "severityText": log["severity_text"],
+            "severityNumber": log["severity_number"],
+            "body": {"stringValue": log["body"]},
+            "timeUnixNano": str(log["time_unix_nano"]),
+            "attributes": [
+                format_attribute(k, v) for (k, v) in log["attributes"].items()
+            ],
+        }
+
+        if "trace_id" in log:
+            otel_log["traceId"] = log["trace_id"]
+
+        envelope.add_log(otel_log)  # TODO: batch these
+
+        if self.spotlight:
+            self.spotlight.capture_envelope(envelope)
+
+        if self.transport is not None:
+            self.transport.capture_envelope(envelope)
+
     def capture_session(
         self, session  # type: Session
     ):

sentry_sdk/envelope.py

@@ -102,6 +102,12 @@ def add_sessions(
         # type: (...) -> None
         self.add_item(Item(payload=PayloadRef(json=sessions), type="sessions"))
 
+    def add_log(
+        self, log  # type: Any
+    ):
+        # type: (...) -> None
+        self.add_item(Item(payload=PayloadRef(json=log), type="otel_log"))
+
     def add_item(
         self, item  # type: Item
     ):
@@ -268,6 +274,8 @@ def data_category(self):
             return "transaction"
         elif ty == "event":
             return "error"
+        elif ty == "otel_log":
+            return "log"
         elif ty == "client_report":
             return "internal"
         elif ty == "profile":

tests/test_logs.py

@@ -0,0 +1,242 @@
+import sys
+from unittest import mock
+import pytest
+
+import sentry_sdk
+from sentry_sdk import _experimental_logger as sentry_logger
+
+
+minimum_python_37 = pytest.mark.skipif(
+    sys.version_info < (3, 7), reason="Asyncio tests need Python >= 3.7"
+)
+
+
+@minimum_python_37
+def test_logs_disabled_by_default(sentry_init, capture_envelopes):
+    sentry_init()
+    envelopes = capture_envelopes()
+
+    sentry_logger.trace("This is a 'trace' log.")
+    sentry_logger.debug("This is a 'debug' log...")
+    sentry_logger.info("This is a 'info' log...")
+    sentry_logger.warn("This is a 'warn' log...")
+    sentry_logger.error("This is a 'error' log...")
+    sentry_logger.fatal("This is a 'fatal' log...")
+
+    assert len(envelopes) == 0
+
+
+@minimum_python_37
+def test_logs_basics(sentry_init, capture_envelopes):
+    sentry_init(_experiments={"enable_sentry_logs": True})
+    envelopes = capture_envelopes()
+
+    sentry_logger.trace("This is a 'trace' log...")
+    sentry_logger.debug("This is a 'debug' log...")
+    sentry_logger.info("This is a 'info' log...")
+    sentry_logger.warn("This is a 'warn' log...")
+    sentry_logger.error("This is a 'error' log...")
+    sentry_logger.fatal("This is a 'fatal' log...")
+
+    assert (
+        len(envelopes) == 6
+    )  # We will batch those log items into a single envelope at some point
+
+    assert envelopes[0].items[0].payload.json["severityText"] == "trace"
+    assert envelopes[0].items[0].payload.json["severityNumber"] == 1
+
+    assert envelopes[1].items[0].payload.json["severityText"] == "debug"
+    assert envelopes[1].items[0].payload.json["severityNumber"] == 5
+
+    assert envelopes[2].items[0].payload.json["severityText"] == "info"
+    assert envelopes[2].items[0].payload.json["severityNumber"] == 9
+
+    assert envelopes[3].items[0].payload.json["severityText"] == "warn"
+    assert envelopes[3].items[0].payload.json["severityNumber"] == 13
+
+    assert envelopes[4].items[0].payload.json["severityText"] == "error"
+    assert envelopes[4].items[0].payload.json["severityNumber"] == 17
+
+    assert envelopes[5].items[0].payload.json["severityText"] == "fatal"
+    assert envelopes[5].items[0].payload.json["severityNumber"] == 21
+
+
+@minimum_python_37
+def test_logs_before_emit_log(sentry_init, capture_envelopes):
+    def _before_log(record, hint):
+        assert list(record.keys()) == [
+            "severity_text",
+            "severity_number",
+            "body",
+            "attributes",
+            "time_unix_nano",
+            "trace_id",
+        ]
+
+        if record["severity_text"] in ["fatal", "error"]:
+            return None
+
+        return record
+
+    sentry_init(
+        _experiments={
+            "enable_sentry_logs": True,
+            "before_emit_log": _before_log,
+        }
+    )
+    envelopes = capture_envelopes()
+
+    sentry_logger.trace("This is a 'trace' log...")
+    sentry_logger.debug("This is a 'debug' log...")
+    sentry_logger.info("This is a 'info' log...")
+    sentry_logger.warn("This is a 'warn' log...")
+    sentry_logger.error("This is a 'error' log...")
+    sentry_logger.fatal("This is a 'fatal' log...")
+
+    assert len(envelopes) == 4
+
+    assert envelopes[0].items[0].payload.json["severityText"] == "trace"
+    assert envelopes[1].items[0].payload.json["severityText"] == "debug"
+    assert envelopes[2].items[0].payload.json["severityText"] == "info"
+    assert envelopes[3].items[0].payload.json["severityText"] == "warn"
+
+
+@minimum_python_37
+def test_logs_attributes(sentry_init, capture_envelopes):
+    """
+    Passing arbitrary attributes to log messages.
+    """
+    sentry_init(_experiments={"enable_sentry_logs": True})
+    envelopes = capture_envelopes()
+
+    attrs = {
+        "attr_int": 1,
+        "attr_float": 2.0,
+        "attr_bool": True,
+        "attr_string": "string attribute",
+    }
+
+    sentry_logger.warn(
+        "The recorded value was '{my_var}'", my_var="some value", attributes=attrs
+    )
+
+    log_item = envelopes[0].items[0].payload.json
+    assert log_item["body"]["stringValue"] == "The recorded value was 'some value'"
+
+    assert log_item["attributes"][1] == {
+        "key": "attr_int",
+        "value": {"intValue": "1"},
+    }  # TODO: this is strange.
+    assert log_item["attributes"][2] == {
+        "key": "attr_float",
+        "value": {"doubleValue": 2.0},
+    }
+    assert log_item["attributes"][3] == {
+        "key": "attr_bool",
+        "value": {"boolValue": True},
+    }
+    assert log_item["attributes"][4] == {
+        "key": "attr_string",
+        "value": {"stringValue": "string attribute"},
+    }
+    assert log_item["attributes"][5] == {
+        "key": "sentry.environment",
+        "value": {"stringValue": "production"},
+    }
+    assert log_item["attributes"][6] == {
+        "key": "sentry.release",
+        "value": {"stringValue": mock.ANY},
+    }
+    assert log_item["attributes"][7] == {
+        "key": "sentry.message.parameters.my_var",
+        "value": {"stringValue": "some value"},
+    }
+
+
+@minimum_python_37
+def test_logs_message_params(sentry_init, capture_envelopes):
+    """
+    This is the official way of how to pass vars to log messages.
+    """
+    sentry_init(_experiments={"enable_sentry_logs": True})
+    envelopes = capture_envelopes()
+
+    sentry_logger.warn("The recorded value was '{int_var}'", int_var=1)
+    sentry_logger.warn("The recorded value was '{float_var}'", float_var=2.0)
+    sentry_logger.warn("The recorded value was '{bool_var}'", bool_var=False)
+    sentry_logger.warn(
+        "The recorded value was '{string_var}'", string_var="some string value"
+    )
+
+    assert (
+        envelopes[0].items[0].payload.json["body"]["stringValue"]
+        == "The recorded value was '1'"
+    )
+    assert envelopes[0].items[0].payload.json["attributes"][-1] == {
+        "key": "sentry.message.parameters.int_var",
+        "value": {"intValue": "1"},
+    }  # TODO: this is strange.
+
+    assert (
+        envelopes[1].items[0].payload.json["body"]["stringValue"]
+        == "The recorded value was '2.0'"
+    )
+    assert envelopes[1].items[0].payload.json["attributes"][-1] == {
+        "key": "sentry.message.parameters.float_var",
+        "value": {"doubleValue": 2.0},
+    }
+
+    assert (
+        envelopes[2].items[0].payload.json["body"]["stringValue"]
+        == "The recorded value was 'False'"
+    )
+    assert envelopes[2].items[0].payload.json["attributes"][-1] == {
+        "key": "sentry.message.parameters.bool_var",
+        "value": {"boolValue": False},
+    }
+
+    assert (
+        envelopes[3].items[0].payload.json["body"]["stringValue"]
+        == "The recorded value was 'some string value'"
+    )
+    assert envelopes[3].items[0].payload.json["attributes"][-1] == {
+        "key": "sentry.message.parameters.string_var",
+        "value": {"stringValue": "some string value"},
+    }
+
+
+@minimum_python_37
+def test_logs_tied_to_transactions(sentry_init, capture_envelopes):
+    """
+    Log messages are also tied to transactions.
+    """
+    sentry_init(_experiments={"enable_sentry_logs": True})
+    envelopes = capture_envelopes()
+
+    with sentry_sdk.start_transaction(name="test-transaction") as trx:
+        sentry_logger.warn("This is a log tied to a transaction")
+
+    log_entry = envelopes[0].items[0].payload.json
+    assert log_entry["attributes"][-1] == {
+        "key": "sentry.trace.parent_span_id",
+        "value": {"stringValue": trx.span_id},
+    }
+
+
+@minimum_python_37
+def test_logs_tied_to_spans(sentry_init, capture_envelopes):
+    """
+    Log messages are also tied to spans.
+    """
+    sentry_init(_experiments={"enable_sentry_logs": True})
+    envelopes = capture_envelopes()
+
+    with sentry_sdk.start_transaction(name="test-transaction"):
+        with sentry_sdk.start_span(description="test-span") as span:
+            sentry_logger.warn("This is a log tied to a span")
+
+    log_entry = envelopes[0].items[0].payload.json
+    assert log_entry["attributes"][-1] == {
+        "key": "sentry.trace.parent_span_id",
+        "value": {"stringValue": span.span_id},
+    }