diff --git a/sentry_sdk/__init__.py b/sentry_sdk/__init__.py index 1c9cedec5f..4a0d551e5a 100644 --- a/sentry_sdk/__init__.py +++ b/sentry_sdk/__init__.py @@ -45,6 +45,7 @@ "start_transaction", "trace", "monitor", + "_experimental_logger.py", ] # Initialize the debug support after everything is loaded diff --git a/sentry_sdk/_experimental_logger.py b/sentry_sdk/_experimental_logger.py new file mode 100644 index 0000000000..1f3cd5e443 --- /dev/null +++ b/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) diff --git a/sentry_sdk/_types.py b/sentry_sdk/_types.py index 883b4cbc81..bc730719d2 100644 --- a/sentry_sdk/_types.py +++ b/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"] diff --git a/sentry_sdk/client.py b/sentry_sdk/client.py index 4f5c1566b3..5bbf919c02 100644 --- a/sentry_sdk/client.py +++ b/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 ): diff --git a/sentry_sdk/envelope.py b/sentry_sdk/envelope.py index 760116daa1..5f61e689c5 100644 --- a/sentry_sdk/envelope.py +++ b/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": diff --git a/tests/test_logs.py b/tests/test_logs.py new file mode 100644 index 0000000000..173a4028d6 --- /dev/null +++ b/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}, + }