clean up a bit, add some tests

Author: colin-sentry

sentry_sdk/_experimental_logger.py

@@ -1,5 +1,6 @@
 # NOTE: this is the logger sentry exposes to users, not some generic logger.
 import functools
+from time import time_ns
 from typing import Any
 
 from sentry_sdk import get_client, get_current_scope
@@ -9,9 +10,24 @@ def _capture_log(severity_text, severity_number, template, **kwargs):
     # type: (str, int, str, **Any) -> None
     client = get_client()
     scope = get_current_scope()
-    kwargs["sentry.message.template"] = template
-    client.capture_log(
-        scope, severity_text, severity_number, template.format(**kwargs), **kwargs
+
+    attrs = {
+        "sentry.message.template": template,
+    }
+    for k, v in kwargs.items():
+        attrs[f"sentry.message.parameters.{k}"] = v
+
+    # noinspection PyProtectedMember
+    client._capture_experimental_log(
+        scope,
+        {
+            "severity_text": severity_text,
+            "severity_number": severity_number,
+            "attributes": attrs,
+            "body": template.format(**kwargs),
+            "time_unix_nano": time_ns(),
+            "trace_id": None,
+        },
     )
 
 

sentry_sdk/client.py

@@ -1,6 +1,5 @@
 import json
 import os
-import time
 import uuid
 import random
 import socket
@@ -209,10 +208,8 @@ def capture_event(self, *args, **kwargs):
         # type: (*Any, **Any) -> Optional[str]
         return None
 
-    def _capture_experimental_log(
-        self, scope, severity_text, severity_number, body, time_unix_nano=None, **kwargs
-    ):
-        # type: (Scope, str, int, str, Optional[int], **Any) -> None
+    def _capture_experimental_log(self, scope, log):
+        # type: (Scope, Log) -> None
         pass
 
     def capture_session(self, *args, **kwargs):
@@ -856,50 +853,33 @@ def capture_event(
 
         return return_value
 
-    def _capture_experimental_log(
-        self, scope, severity_text, severity_number, body, time_unix_nano=None, **kwargs
-    ):
-        # type: (Scope, str, int, str, Optional[int], **Any) -> None
+    def _capture_experimental_log(self, scope, log):
+        # type: (Scope, Log) -> None
         logs_enabled = self.options["_experiments"].get("enable_sentry_logs", False)
         if not logs_enabled:
             return
 
-        if time_unix_nano is None:
-            time_unix_nano = time.time_ns()
-
         headers = {
             "sent_at": format_timestamp(datetime.now(timezone.utc)),
         }  # type: dict[str, object]
 
-        attrs = {}  # 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
+        if environment is not None and "sentry.environment" not in log["attributes"]:
+            log["attributes"]["sentry.environment"] = environment
 
         release = self.options.get("release")
-        if release is not None:
-            attrs["sentry.release"] = release
+        if release is not None and "sentry.release" not in log["attributes"]:
+            log["attributes"]["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
+        if span is not None and "sentry.trace.parent_span_id" not in log["attributes"]:
+            log["attributes"]["sentry.trace.parent_span_id"] = span.span_id
 
-        log = {
-            "severity_text": severity_text,
-            "severity_number": severity_number,
-            "body": body,
-            "attributes": attrs,
-            "time_unix_nano": time_unix_nano,
-            "trace_id": None,
-        }  # type: Log
+        propagation_context = scope.get_active_propagation_context()
+        if propagation_context is not None:
+            headers["trace_id"] = propagation_context.trace_id
+            if log["trace_id"] is None:
+                log["trace_id"] = propagation_context.trace_id
 
         # If debug is enabled, log the log to the console
         debug = self.options.get("debug", False)
@@ -914,15 +894,10 @@ def _capture_experimental_log(
             }
             # Be careful editing this line, you can add infinite logging loops with the logger integration
             logger.log(
-                severity_text_to_logging_level.get(severity_text, logging.DEBUG),
+                severity_text_to_logging_level.get(log["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")

sentry_sdk/integrations/logging.py

@@ -354,43 +354,45 @@ def _capture_log_from_record(client, record):
         # type: (BaseClient, LogRecord) -> None
         scope = sentry_sdk.get_current_scope()
         otel_severity_number, otel_severity_text = _python_level_to_otel(record.levelno)
-        kwargs = {
+        attrs = {
             "sentry.message.template": (
                 record.msg if isinstance(record.msg, str) else json.dumps(record.msg)
             ),
         }
         if record.args is not None:
             if isinstance(record.args, tuple):
                 for i, arg in enumerate(record.args):
-                    kwargs[f"sentry.message.parameters.{i}"] = (
+                    attrs[f"sentry.message.parameters.{i}"] = (
                         arg if isinstance(arg, str) else json.dumps(arg)
                     )
         if record.lineno:
-            kwargs["code.line.number"] = record.lineno
+            attrs["code.line.number"] = record.lineno
         if record.pathname:
-            kwargs["code.file.path"] = record.pathname
+            attrs["code.file.path"] = record.pathname
         if record.funcName:
-            kwargs["code.function.name"] = record.funcName
+            attrs["code.function.name"] = record.funcName
 
         if record.thread:
-            kwargs["thread.id"] = record.thread
+            attrs["thread.id"] = record.thread
         if record.threadName:
-            kwargs["thread.name"] = record.threadName
+            attrs["thread.name"] = record.threadName
 
         if record.process:
-            kwargs["process.pid"] = record.process
+            attrs["process.pid"] = record.process
         if record.processName:
-            kwargs["process.executable.name"] = record.processName
+            attrs["process.executable.name"] = record.processName
         if record.name:
-            kwargs["logger.name"] = record.name
-        if record.created:
-            kwargs["time_unix_nano"] = int(record.created * 1e9)
+            attrs["logger.name"] = record.name
 
         # noinspection PyProtectedMember
         client._capture_experimental_log(
             scope,
-            otel_severity_text,
-            otel_severity_number,
-            record.getMessage(),
-            **kwargs,
+            {
+                "severity_text": otel_severity_text,
+                "severity_number": otel_severity_number,
+                "body": record.message,
+                "attributes": attrs,
+                "time_unix_nano": int(record.created * 1e9),
+                "trace_id": None,
+            },
         )

tests/test_logs.py

@@ -1,3 +1,4 @@
+import logging
 import sys
 from unittest import mock
 import pytest
@@ -240,3 +241,37 @@ def test_logs_tied_to_spans(sentry_init, capture_envelopes):
         "key": "sentry.trace.parent_span_id",
         "value": {"stringValue": span.span_id},
     }
+
+
+@minimum_python_37
+def test_logger_integration_warning(sentry_init, capture_envelopes):
+    """
+    The python logger module should create 'warn' sentry logs if the flag is on.
+    """
+    sentry_init(_experiments={"enable_sentry_logs": True})
+    envelopes = capture_envelopes()
+
+    python_logger = logging.Logger("test-logger")
+    python_logger.warning("this is %s a template %s", "1", "2")
+
+    log_entry = envelopes[0].items[0].payload.json
+    assert log_entry["attributes"][0] == {
+        "key": "sentry.message.template",
+        "value": {"stringValue": "this is %s a template %s"},
+    }
+    assert log_entry["severityNumber"] == 13
+    assert log_entry["severityText"] == "warn"
+
+
+@minimum_python_37
+def test_logger_integration_debug(sentry_init, capture_envelopes):
+    """
+    The python logger module should not create 'debug' sentry logs if the flag is on by default
+    """
+    sentry_init(_experiments={"enable_sentry_logs": True})
+    envelopes = capture_envelopes()
+
+    python_logger = logging.Logger("test-logger")
+    python_logger.debug("this is %s a template %s", "1", "2")
+
+    assert len(envelopes) == 0