From 14246d6d3710da8a43fd389a51a3f85d24de9c57 Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Tue, 1 Apr 2025 13:17:57 -0400 Subject: [PATCH 1/9] Rename import to sentry_sdk.logger, export Log type --- sentry_sdk/__init__.py | 2 +- .../{_experimental_logger.py => logger.py} | 4 +- sentry_sdk/types.py | 5 +- tests/test_logs.py | 51 +++++++++---------- 4 files changed, 31 insertions(+), 31 deletions(-) rename sentry_sdk/{_experimental_logger.py => logger.py} (89%) diff --git a/sentry_sdk/__init__.py b/sentry_sdk/__init__.py index e7e069e377..b4859cc5d2 100644 --- a/sentry_sdk/__init__.py +++ b/sentry_sdk/__init__.py @@ -45,7 +45,7 @@ "start_transaction", "trace", "monitor", - "_experimental_logger", + "logger", ] # Initialize the debug support after everything is loaded diff --git a/sentry_sdk/_experimental_logger.py b/sentry_sdk/logger.py similarity index 89% rename from sentry_sdk/_experimental_logger.py rename to sentry_sdk/logger.py index d28ff69483..83d455ee2f 100644 --- a/sentry_sdk/_experimental_logger.py +++ b/sentry_sdk/logger.py @@ -17,7 +17,7 @@ def _capture_log(severity_text, severity_number, template, **kwargs): if "attributes" in kwargs: attrs.update(kwargs.pop("attributes")) for k, v in kwargs.items(): - attrs[f"sentry.message.parameters.{k}"] = v + attrs[f"sentry.message.parameters.{k}"] = v if isinstance(v, str) else repr(v) # noinspection PyProtectedMember client._capture_experimental_log( @@ -36,6 +36,6 @@ def _capture_log(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) +warning = functools.partial(_capture_log, "warning", 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 a81be8f1c1..2b9f04c097 100644 --- a/sentry_sdk/types.py +++ b/sentry_sdk/types.py @@ -11,7 +11,7 @@ from typing import TYPE_CHECKING if TYPE_CHECKING: - from sentry_sdk._types import Event, EventDataCategory, Hint + from sentry_sdk._types import Event, EventDataCategory, Hint, Log else: from typing import Any @@ -20,5 +20,6 @@ Event = Any EventDataCategory = Any Hint = Any + Log = Any -__all__ = ("Event", "EventDataCategory", "Hint") +__all__ = ("Event", "EventDataCategory", "Hint", "Log") diff --git a/tests/test_logs.py b/tests/test_logs.py index 7ef708ceb1..b73831ccda 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -5,7 +5,6 @@ import pytest import sentry_sdk -from sentry_sdk import _experimental_logger as sentry_logger from sentry_sdk.integrations.logging import LoggingIntegration minimum_python_37 = pytest.mark.skipif( @@ -25,12 +24,12 @@ def test_logs_disabled_by_default(sentry_init, capture_envelopes): 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...") + sentry_sdk.logger.trace("This is a 'trace' log.") + sentry_sdk.logger.debug("This is a 'debug' log...") + sentry_sdk.logger.info("This is a 'info' log...") + sentry_sdk.logger.warning("This is a 'warn' log...") + sentry_sdk.logger.error("This is a 'error' log...") + sentry_sdk.logger.fatal("This is a 'fatal' log...") python_logger.warning("sad") assert len(envelopes) == 0 @@ -41,12 +40,12 @@ 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...") + sentry_sdk.logger.trace("This is a 'trace' log...") + sentry_sdk.logger.debug("This is a 'debug' log...") + sentry_sdk.logger.info("This is a 'info' log...") + sentry_sdk.logger.warning("This is a 'warn' log...") + sentry_sdk.logger.error("This is a 'error' log...") + sentry_sdk.logger.fatal("This is a 'fatal' log...") assert ( len(envelopes) == 6 @@ -96,12 +95,12 @@ def _before_log(record, hint): ) 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...") + sentry_sdk.logger.trace("This is a 'trace' log...") + sentry_sdk.logger.debug("This is a 'debug' log...") + sentry_sdk.logger.info("This is a 'info' log...") + sentry_sdk.logger.warning("This is a 'warn' log...") + sentry_sdk.logger.error("This is a 'error' log...") + sentry_sdk.logger.fatal("This is a 'fatal' log...") assert len(envelopes) == 4 @@ -126,7 +125,7 @@ def test_logs_attributes(sentry_init, capture_envelopes): "attr_string": "string attribute", } - sentry_logger.warn( + sentry_sdk.logger.warning( "The recorded value was '{my_var}'", my_var="some value", attributes=attrs ) @@ -151,10 +150,10 @@ def test_logs_message_params(sentry_init, capture_envelopes): 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( + sentry_sdk.logger.warning("The recorded value was '{int_var}'", int_var=1) + sentry_sdk.logger.warning("The recorded value was '{float_var}'", float_var=2.0) + sentry_sdk.logger.warning("The recorded value was '{bool_var}'", bool_var=False) + sentry_sdk.logger.warning( "The recorded value was '{string_var}'", string_var="some string value" ) @@ -200,7 +199,7 @@ def test_logs_tied_to_transactions(sentry_init, capture_envelopes): envelopes = capture_envelopes() with sentry_sdk.start_transaction(name="test-transaction") as trx: - sentry_logger.warn("This is a log tied to a transaction") + sentry_sdk.logger.warning("This is a log tied to a transaction") log_entry = envelopes[0].items[0].payload.json assert log_entry["attributes"][-1] == { @@ -219,7 +218,7 @@ def test_logs_tied_to_spans(sentry_init, 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") + sentry_sdk.logger.warning("This is a log tied to a span") attrs = otel_attributes_to_dict(envelopes[0].items[0].payload.json["attributes"]) assert attrs["sentry.trace.parent_span_id"] == {"stringValue": span.span_id} From a2eaa8a07adebf9fbf1f6f28b1aa334220064250 Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Tue, 1 Apr 2025 14:00:13 -0400 Subject: [PATCH 2/9] fix test --- tests/test_logs.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/tests/test_logs.py b/tests/test_logs.py index b73831ccda..8fcefdbe0c 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -27,7 +27,7 @@ def test_logs_disabled_by_default(sentry_init, capture_envelopes): sentry_sdk.logger.trace("This is a 'trace' log.") sentry_sdk.logger.debug("This is a 'debug' log...") sentry_sdk.logger.info("This is a 'info' log...") - sentry_sdk.logger.warning("This is a 'warn' log...") + sentry_sdk.logger.warning("This is a 'warning' log...") sentry_sdk.logger.error("This is a 'error' log...") sentry_sdk.logger.fatal("This is a 'fatal' log...") python_logger.warning("sad") @@ -60,7 +60,7 @@ def test_logs_basics(sentry_init, capture_envelopes): 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["severityText"] == "warning" assert envelopes[3].items[0].payload.json["severityNumber"] == 13 assert envelopes[4].items[0].payload.json["severityText"] == "error" @@ -98,7 +98,7 @@ def _before_log(record, hint): sentry_sdk.logger.trace("This is a 'trace' log...") sentry_sdk.logger.debug("This is a 'debug' log...") sentry_sdk.logger.info("This is a 'info' log...") - sentry_sdk.logger.warning("This is a 'warn' log...") + sentry_sdk.logger.warning("This is a 'warning' log...") sentry_sdk.logger.error("This is a 'error' log...") sentry_sdk.logger.fatal("This is a 'fatal' log...") @@ -107,7 +107,7 @@ def _before_log(record, hint): 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" + assert envelopes[3].items[0].payload.json["severityText"] == "warning" @minimum_python_37 @@ -247,7 +247,7 @@ def test_logger_integration_warning(sentry_init, capture_envelopes): assert attrs["sentry.message.parameters.0"] == {"stringValue": "1"} assert attrs["sentry.message.parameters.1"] assert log_entry["severityNumber"] == 13 - assert log_entry["severityText"] == "warn" + assert log_entry["severityText"] == "warning" @minimum_python_37 From db66c5761bd6b51f30061af15fb98996fd7ad9c1 Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Tue, 1 Apr 2025 15:44:00 -0400 Subject: [PATCH 3/9] feat(ourlogs): Batch logs into a single envelope --- sentry_sdk/_log_batcher.py | 141 +++++++++++++++ sentry_sdk/client.py | 55 ++---- sentry_sdk/consts.py | 2 +- sentry_sdk/integrations/logging.py | 2 +- sentry_sdk/logger.py | 6 +- tests/test_logs.py | 276 ++++++++++++++++++----------- 6 files changed, 336 insertions(+), 146 deletions(-) create mode 100644 sentry_sdk/_log_batcher.py diff --git a/sentry_sdk/_log_batcher.py b/sentry_sdk/_log_batcher.py new file mode 100644 index 0000000000..8dca661e2e --- /dev/null +++ b/sentry_sdk/_log_batcher.py @@ -0,0 +1,141 @@ +import json +import os +import random +import threading +from datetime import datetime, timezone +from typing import Optional, List, Callable, TYPE_CHECKING, Any + +from sentry_sdk.utils import format_timestamp +from sentry_sdk.envelope import Envelope + +if TYPE_CHECKING: + from sentry_sdk._types import Log + + +class LogBatcher: + MAX_LOGS_BEFORE_FLUSH = 100 + FLUSH_WAIT_TIME = 5.0 + + def __init__( + self, + capture_func, # type: Callable[[Envelope], None] + ): + # type: (...) -> None + self._log_buffer = [] # type: List[Log] + self._capture_func = capture_func + self._running = True + self._lock = threading.Lock() + + self._flush_event = threading.Event() # type: threading.Event + + self._flusher = None # type: Optional[threading.Thread] + self._flusher_pid = None # type: Optional[int] + + def _ensure_thread(self): + # type: (...) -> bool + """For forking processes we might need to restart this thread. + This ensures that our process actually has that thread running. + """ + if not self._running: + return False + + pid = os.getpid() + if self._flusher_pid == pid: + return True + + with self._lock: + # Double-checked locking + if self._flusher_pid == pid: + return True + + self._flusher_pid = pid + + self._flusher = threading.Thread(target=self._flush_loop) + self._flusher.daemon = True + + try: + self._flusher.start() + except RuntimeError: + # Unfortunately at this point the interpreter is in a state that no + # longer allows us to spawn a thread and we have to bail. + self._running = False + return False + + return True + + def _flush_loop(self): + # type: (...) -> None + while self._running: + self._flush_event.wait(self.FLUSH_WAIT_TIME + random.random()) + self._flush() + + def add( + self, + log, # type: Log + ): + # type: (...) -> None + if not self._ensure_thread() or self._flusher is None: + return None + + with self._lock: + self._log_buffer.append(log) + if len(self._log_buffer) >= self.MAX_LOGS_BEFORE_FLUSH: + self._flush_event.set() + + def kill(self): + # type: (...) -> None + if self._flusher is None: + return + + self._running = False + self._flush_event.set() + self._flusher = None + + def flush(self): + # type: (...) -> None + self._flush() + + @staticmethod + def _log_to_otel(log): + # type: (Log) -> Any + 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"] + + return otel_log + + def _flush(self): + # type: (...) -> Optional[Envelope] + + envelope = Envelope( + headers={"sent_at": format_timestamp(datetime.now(timezone.utc))} + ) + with self._lock: + for log in self._log_buffer: + envelope.add_log(self._log_to_otel(log)) + self._log_buffer.clear() + if envelope.items: + self._capture_func(envelope) + return envelope + return None diff --git a/sentry_sdk/client.py b/sentry_sdk/client.py index 0cdf0f7717..0dc463f9aa 100644 --- a/sentry_sdk/client.py +++ b/sentry_sdk/client.py @@ -1,4 +1,3 @@ -import json import os import uuid import random @@ -65,6 +64,7 @@ from sentry_sdk.session import Session from sentry_sdk.spotlight import SpotlightClient from sentry_sdk.transport import Transport + from sentry_sdk._log_batcher import LogBatcher I = TypeVar("I", bound=Integration) # noqa: E741 @@ -178,6 +178,7 @@ def __init__(self, options=None): self.transport = None # type: Optional[Transport] self.monitor = None # type: Optional[Monitor] self.metrics_aggregator = None # type: Optional[MetricsAggregator] + self.log_batcher = None # type: Optional[LogBatcher] def __getstate__(self, *args, **kwargs): # type: (*Any, **Any) -> Any @@ -375,6 +376,12 @@ def _capture_envelope(envelope): "Metrics not supported on Python 3.6 and lower with gevent." ) + self.log_batcher = None + if experiments.get("enable_logs", False): + from sentry_sdk._log_batcher import LogBatcher + + self.log_batcher = LogBatcher(capture_func=_capture_envelope) + max_request_body_size = ("always", "never", "small", "medium") if self.options["max_request_body_size"] not in max_request_body_size: raise ValueError( @@ -451,6 +458,7 @@ def _capture_envelope(envelope): if ( self.monitor or self.metrics_aggregator + or self.log_batcher or has_profiling_enabled(self.options) or isinstance(self.transport, BaseHttpTransport) ): @@ -868,15 +876,11 @@ def capture_event( def _capture_experimental_log(self, current_scope, log): # type: (Scope, Log) -> None - logs_enabled = self.options["_experiments"].get("enable_sentry_logs", False) + logs_enabled = self.options["_experiments"].get("enable_logs", False) if not logs_enabled: return isolation_scope = current_scope.get_isolation_scope() - headers = { - "sent_at": format_timestamp(datetime.now(timezone.utc)), - } # type: dict[str, object] - environment = self.options.get("environment") if environment is not None and "sentry.environment" not in log["attributes"]: log["attributes"]["sentry.environment"] = environment @@ -913,46 +917,13 @@ def _capture_experimental_log(self, current_scope, log): f'[Sentry Logs] {log["body"]}', ) - 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) + self.log_batcher.add(log) def capture_session( self, session # type: Session @@ -1006,6 +977,8 @@ def close( self.session_flusher.kill() if self.metrics_aggregator is not None: self.metrics_aggregator.kill() + if self.log_batcher is not None: + self.log_batcher.kill() if self.monitor: self.monitor.kill() self.transport.kill() @@ -1030,6 +1003,8 @@ def flush( self.session_flusher.flush() if self.metrics_aggregator is not None: self.metrics_aggregator.flush() + if self.log_batcher is not None: + self.log_batcher.flush() self.transport.flush(timeout=timeout, callback=callback) def __enter__(self): diff --git a/sentry_sdk/consts.py b/sentry_sdk/consts.py index 6c663b6ff2..05942b6071 100644 --- a/sentry_sdk/consts.py +++ b/sentry_sdk/consts.py @@ -78,7 +78,7 @@ class CompressionAlgo(Enum): Callable[[str, MetricValue, MeasurementUnit, MetricTags], bool] ], "metric_code_locations": Optional[bool], - "enable_sentry_logs": Optional[bool], + "enable_logs": Optional[bool], }, total=False, ) diff --git a/sentry_sdk/integrations/logging.py b/sentry_sdk/integrations/logging.py index 7822608de8..0f50a276f4 100644 --- a/sentry_sdk/integrations/logging.py +++ b/sentry_sdk/integrations/logging.py @@ -348,7 +348,7 @@ def emit(self, record): if not client.is_active(): return - if not client.options["_experiments"].get("enable_sentry_logs", False): + if not client.options["_experiments"].get("enable_logs", False): return SentryLogsHandler._capture_log_from_record(client, record) diff --git a/sentry_sdk/logger.py b/sentry_sdk/logger.py index 83d455ee2f..c2d5f37e23 100644 --- a/sentry_sdk/logger.py +++ b/sentry_sdk/logger.py @@ -17,7 +17,11 @@ def _capture_log(severity_text, severity_number, template, **kwargs): if "attributes" in kwargs: attrs.update(kwargs.pop("attributes")) for k, v in kwargs.items(): - attrs[f"sentry.message.parameters.{k}"] = v if isinstance(v, str) else repr(v) + attrs[f"sentry.message.parameters.{k}"] = ( + v + if (isinstance(v, str) or isinstance(v, int) or isinstance(v, bool)) + else repr(v) + ) # noinspection PyProtectedMember client._capture_experimental_log( diff --git a/tests/test_logs.py b/tests/test_logs.py index 8fcefdbe0c..a2affb7d37 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -1,11 +1,16 @@ +import json import logging import sys +import time from typing import List, Any -from unittest import mock import pytest import sentry_sdk +import sentry_sdk.logger +from sentry_sdk import get_client +from sentry_sdk.envelope import Envelope from sentry_sdk.integrations.logging import LoggingIntegration +from sentry_sdk.types import Log minimum_python_37 = pytest.mark.skipif( sys.version_info < (3, 7), reason="Asyncio tests need Python >= 3.7" @@ -13,7 +18,41 @@ def otel_attributes_to_dict(otel_attrs: List[Any]): - return {item["key"]: item["value"] for item in otel_attrs} + def _convert_attr(attr: dict[str, str | int | bool]): + if "boolValue" in attr: + return bool(attr["boolValue"]) + if "doubleValue" in attr: + return float(attr["doubleValue"]) + if "intValue" in attr: + return int(attr["intValue"]) + if attr["stringValue"].startswith("{"): + try: + return json.loads(attr["stringValue"]) + except ValueError: + pass + return str(attr["stringValue"]) + + return {item["key"]: _convert_attr(item["value"]) for item in otel_attrs} + + +def envelopes_to_logs(envelopes: List[Envelope]) -> List[Log]: + res = [] # type: List[Log] + for envelope in envelopes: + for item in envelope.items: + if item.type == "otel_log": + log_json = item.payload.json + log = { + "severity_text": log_json["severityText"], + "severity_number": log_json["severityNumber"], + "body": log_json["body"]["stringValue"], + "attributes": otel_attributes_to_dict(log_json["attributes"]), + "time_unix_nano": int(log_json["timeUnixNano"]), + "trace_id": None, + } # type: Log + if "traceId" in log_json: + log["trace_id"] = log_json["traceId"] + res.append(log) + return res @minimum_python_37 @@ -37,7 +76,7 @@ def test_logs_disabled_by_default(sentry_init, capture_envelopes): @minimum_python_37 def test_logs_basics(sentry_init, capture_envelopes): - sentry_init(_experiments={"enable_sentry_logs": True}) + sentry_init(_experiments={"enable_logs": True}) envelopes = capture_envelopes() sentry_sdk.logger.trace("This is a 'trace' log...") @@ -47,31 +86,31 @@ def test_logs_basics(sentry_init, capture_envelopes): sentry_sdk.logger.error("This is a 'error' log...") sentry_sdk.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 + get_client().flush() + logs = envelopes_to_logs(envelopes) + assert logs[0].get("severity_text") == "trace" + assert logs[0].get("severity_number") == 1 - assert envelopes[1].items[0].payload.json["severityText"] == "debug" - assert envelopes[1].items[0].payload.json["severityNumber"] == 5 + assert logs[1].get("severity_text") == "debug" + assert logs[1].get("severity_number") == 5 - assert envelopes[2].items[0].payload.json["severityText"] == "info" - assert envelopes[2].items[0].payload.json["severityNumber"] == 9 + assert logs[2].get("severity_text") == "info" + assert logs[2].get("severity_number") == 9 - assert envelopes[3].items[0].payload.json["severityText"] == "warning" - assert envelopes[3].items[0].payload.json["severityNumber"] == 13 + assert logs[3].get("severity_text") == "warning" + assert logs[3].get("severity_number") == 13 - assert envelopes[4].items[0].payload.json["severityText"] == "error" - assert envelopes[4].items[0].payload.json["severityNumber"] == 17 + assert logs[4].get("severity_text") == "error" + assert logs[4].get("severity_number") == 17 - assert envelopes[5].items[0].payload.json["severityText"] == "fatal" - assert envelopes[5].items[0].payload.json["severityNumber"] == 21 + assert logs[5].get("severity_text") == "fatal" + assert logs[5].get("severity_number") == 21 @minimum_python_37 def test_logs_before_emit_log(sentry_init, capture_envelopes): + before_log_called = [False] + def _before_log(record, hint): assert set(record.keys()) == { "severity_text", @@ -85,11 +124,13 @@ def _before_log(record, hint): if record["severity_text"] in ["fatal", "error"]: return None + before_log_called[0] = True + return record sentry_init( _experiments={ - "enable_sentry_logs": True, + "enable_logs": True, "before_emit_log": _before_log, } ) @@ -102,12 +143,15 @@ def _before_log(record, hint): sentry_sdk.logger.error("This is a 'error' log...") sentry_sdk.logger.fatal("This is a 'fatal' log...") - assert len(envelopes) == 4 + get_client().flush() + logs = envelopes_to_logs(envelopes) + assert len(logs) == 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"] == "warning" + assert logs[0]["severity_text"] == "trace" + assert logs[1]["severity_text"] == "debug" + assert logs[2]["severity_text"] == "info" + assert logs[3]["severity_text"] == "warning" + assert before_log_called[0] @minimum_python_37 @@ -115,7 +159,7 @@ def test_logs_attributes(sentry_init, capture_envelopes): """ Passing arbitrary attributes to log messages. """ - sentry_init(_experiments={"enable_sentry_logs": True}) + sentry_init(_experiments={"enable_logs": True}) envelopes = capture_envelopes() attrs = { @@ -129,17 +173,15 @@ def test_logs_attributes(sentry_init, capture_envelopes): "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'" + get_client().flush() + logs = envelopes_to_logs(envelopes) + assert logs[0]["body"] == "The recorded value was 'some value'" - attrs = otel_attributes_to_dict(log_item["attributes"]) - assert attrs["attr_int"] == {"intValue": "1"} - assert attrs["attr_float"] == {"doubleValue": 2.0} - assert attrs["attr_bool"] == {"boolValue": True} - assert attrs["attr_string"] == {"stringValue": "string attribute"} - assert attrs["sentry.environment"] == {"stringValue": "production"} - assert attrs["sentry.release"] == {"stringValue": mock.ANY} - assert attrs["sentry.message.parameters.my_var"] == {"stringValue": "some value"} + for k, v in attrs.items(): + assert logs[0]["attributes"][k] == v + assert logs[0]["attributes"]["sentry.environment"] == "production" + assert "sentry.release" in logs[0]["attributes"] + assert logs[0]["attributes"]["sentry.message.parameters.my_var"] == "some value" @minimum_python_37 @@ -147,7 +189,7 @@ 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}) + sentry_init(_experiments={"enable_logs": True}) envelopes = capture_envelopes() sentry_sdk.logger.warning("The recorded value was '{int_var}'", int_var=1) @@ -156,38 +198,33 @@ def test_logs_message_params(sentry_init, capture_envelopes): sentry_sdk.logger.warning( "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'" + sentry_sdk.logger.error( + "The recorded error was '{error}'", error=Exception("some error") ) - assert otel_attributes_to_dict(envelopes[0].items[0].payload.json["attributes"])[ - "sentry.message.parameters.int_var" - ] == {"intValue": "1"} - assert ( - envelopes[1].items[0].payload.json["body"]["stringValue"] - == "The recorded value was '2.0'" - ) - assert otel_attributes_to_dict(envelopes[1].items[0].payload.json["attributes"])[ - "sentry.message.parameters.float_var" - ] == {"doubleValue": 2.0} + get_client().flush() + logs = envelopes_to_logs(envelopes) + + assert logs[0]["body"] == "The recorded value was '1'" + assert logs[0]["attributes"]["sentry.message.parameters.int_var"] == 1 + assert logs[1]["body"] == "The recorded value was '2.0'" + assert logs[1]["attributes"]["sentry.message.parameters.float_var"] == 2.0 + + assert logs[2]["body"] == "The recorded value was 'False'" + assert logs[2]["attributes"]["sentry.message.parameters.bool_var"] is False + + assert logs[3]["body"] == "The recorded value was 'some string value'" assert ( - envelopes[2].items[0].payload.json["body"]["stringValue"] - == "The recorded value was 'False'" + logs[3]["attributes"]["sentry.message.parameters.string_var"] + == "some string value" ) - assert otel_attributes_to_dict(envelopes[2].items[0].payload.json["attributes"])[ - "sentry.message.parameters.bool_var" - ] == {"boolValue": False} + assert logs[4]["body"] == "The recorded error was 'some error'" assert ( - envelopes[3].items[0].payload.json["body"]["stringValue"] - == "The recorded value was 'some string value'" + logs[4]["attributes"]["sentry.message.parameters.error"] + == "Exception('some error')" ) - assert otel_attributes_to_dict(envelopes[3].items[0].payload.json["attributes"])[ - "sentry.message.parameters.string_var" - ] == {"stringValue": "some string value"} @minimum_python_37 @@ -195,17 +232,15 @@ def test_logs_tied_to_transactions(sentry_init, capture_envelopes): """ Log messages are also tied to transactions. """ - sentry_init(_experiments={"enable_sentry_logs": True}) + sentry_init(_experiments={"enable_logs": True}) envelopes = capture_envelopes() with sentry_sdk.start_transaction(name="test-transaction") as trx: sentry_sdk.logger.warning("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}, - } + get_client().flush() + logs = envelopes_to_logs(envelopes) + assert logs[0]["attributes"]["sentry.trace.parent_span_id"] == trx.span_id @minimum_python_37 @@ -213,15 +248,16 @@ def test_logs_tied_to_spans(sentry_init, capture_envelopes): """ Log messages are also tied to spans. """ - sentry_init(_experiments={"enable_sentry_logs": True}) + sentry_init(_experiments={"enable_logs": True}) envelopes = capture_envelopes() with sentry_sdk.start_transaction(name="test-transaction"): with sentry_sdk.start_span(description="test-span") as span: sentry_sdk.logger.warning("This is a log tied to a span") - attrs = otel_attributes_to_dict(envelopes[0].items[0].payload.json["attributes"]) - assert attrs["sentry.trace.parent_span_id"] == {"stringValue": span.span_id} + get_client().flush() + logs = envelopes_to_logs(envelopes) + assert logs[0]["attributes"]["sentry.trace.parent_span_id"] == span.span_id @minimum_python_37 @@ -229,25 +265,24 @@ 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}) + sentry_init(_experiments={"enable_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 - attrs = otel_attributes_to_dict(log_entry["attributes"]) - assert attrs["sentry.message.template"] == { - "stringValue": "this is %s a template %s" - } + get_client().flush() + logs = envelopes_to_logs(envelopes) + attrs = logs[0]["attributes"] + assert attrs["sentry.message.template"] == "this is %s a template %s" assert "code.file.path" in attrs assert "code.line.number" in attrs - assert attrs["logger.name"] == {"stringValue": "test-logger"} - assert attrs["sentry.environment"] == {"stringValue": "production"} - assert attrs["sentry.message.parameters.0"] == {"stringValue": "1"} - assert attrs["sentry.message.parameters.1"] - assert log_entry["severityNumber"] == 13 - assert log_entry["severityText"] == "warning" + assert attrs["logger.name"] == "test-logger" + assert attrs["sentry.environment"] == "production" + assert attrs["sentry.message.parameters.0"] == "1" + assert attrs["sentry.message.parameters.1"] == "2" + assert logs[0]["severity_number"] == 13 + assert logs[0]["severity_text"] == "warn" @minimum_python_37 @@ -255,11 +290,12 @@ 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}) + sentry_init(_experiments={"enable_logs": True}) envelopes = capture_envelopes() python_logger = logging.Logger("test-logger") python_logger.debug("this is %s a template %s", "1", "2") + get_client().flush() assert len(envelopes) == 0 @@ -270,7 +306,7 @@ def test_no_log_infinite_loop(sentry_init, capture_envelopes): If 'debug' mode is true, and you set a low log level in the logging integration, there should be no infinite loops. """ sentry_init( - _experiments={"enable_sentry_logs": True}, + _experiments={"enable_logs": True}, integrations=[LoggingIntegration(sentry_logs_level=logging.DEBUG)], debug=True, ) @@ -278,6 +314,7 @@ def test_no_log_infinite_loop(sentry_init, capture_envelopes): python_logger = logging.Logger("test-logger") python_logger.debug("this is %s a template %s", "1", "2") + get_client().flush() assert len(envelopes) == 1 @@ -287,34 +324,67 @@ def test_logging_errors(sentry_init, capture_envelopes): """ The python logger module should be able to log errors without erroring """ - sentry_init(_experiments={"enable_sentry_logs": True}) + sentry_init(_experiments={"enable_logs": True}) envelopes = capture_envelopes() python_logger = logging.Logger("test-logger") python_logger.error(Exception("test exc 1")) python_logger.error("error is %s", Exception("test exc 2")) + get_client().flush() error_event_1 = envelopes[0].items[0].payload.json assert error_event_1["level"] == "error" + error_event_2 = envelopes[1].items[0].payload.json + assert error_event_2["level"] == "error" - log_event_1 = envelopes[1].items[0].payload.json - assert log_event_1["severityText"] == "error" - # When only logging an exception, there is no "sentry.message.template" or "sentry.message.parameters.0" - assert len(log_event_1["attributes"]) == 10 - assert log_event_1["attributes"][0]["key"] == "code.line.number" + print(envelopes) + logs = envelopes_to_logs(envelopes) + assert logs[0]["severity_text"] == "error" + assert "sentry.message.template" not in logs[0]["attributes"] + assert "sentry.message.parameters.0" not in logs[0]["attributes"] + assert "code.line.number" in logs[0]["attributes"] - error_event_2 = envelopes[2].items[0].payload.json - assert error_event_2["level"] == "error" + assert logs[1]["severity_text"] == "error" + assert logs[1]["attributes"]["sentry.message.template"] == "error is %s" + assert logs[1]["attributes"]["sentry.message.parameters.0"] == "Exception('test exc 2')" + assert "code.line.number" in logs[1]["attributes"] - log_event_2 = envelopes[3].items[0].payload.json - assert log_event_2["severityText"] == "error" - assert len(log_event_2["attributes"]) == 12 - assert log_event_2["attributes"][0]["key"] == "sentry.message.template" - assert log_event_2["attributes"][0]["value"] == {"stringValue": "error is %s"} - assert log_event_2["attributes"][1]["key"] == "sentry.message.parameters.0" - assert log_event_2["attributes"][1]["value"] == { - "stringValue": "Exception('test exc 2')" - } - assert log_event_2["attributes"][2]["key"] == "code.line.number" + assert len(logs) == 2 + + +def test_auto_flush_logs_after_100(sentry_init, capture_envelopes): + """ + If you log >100 logs, it should automatically trigger a flush. + """ + sentry_init(_experiments={"enable_logs": True}) + envelopes = capture_envelopes() + + python_logger = logging.Logger("test-logger") + for i in range(200): + python_logger.warning("log #%d", i) + + for _ in range(500): + time.sleep(1.0 / 100.0) + if len(envelopes) > 0: + return + + raise AssertionError("200 logs were never flushed after five seconds") + + +@minimum_python_37 +def test_auto_flush_logs_after_5s(sentry_init, capture_envelopes): + """ + If you log a single log, it should automatically flush after 5 seconds, at most 10 seconds. + """ + sentry_init(_experiments={"enable_logs": True}) + envelopes = capture_envelopes() + + python_logger = logging.Logger("test-logger") + python_logger.warning("log #%d", 1) + + for _ in range(100): + time.sleep(1.0 / 10.0) + if len(envelopes) > 0: + return - assert len(envelopes) == 4 + raise AssertionError("1 logs was never flushed after 10 seconds") From 1e9b6175da9c72783f9b8a023c7a93b54edfa86a Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Tue, 1 Apr 2025 15:52:41 -0400 Subject: [PATCH 4/9] null gate --- sentry_sdk/client.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/sentry_sdk/client.py b/sentry_sdk/client.py index 0dc463f9aa..801aa936d2 100644 --- a/sentry_sdk/client.py +++ b/sentry_sdk/client.py @@ -923,7 +923,8 @@ def _capture_experimental_log(self, current_scope, log): if log is None: return - self.log_batcher.add(log) + if self.log_batcher: + self.log_batcher.add(log) def capture_session( self, session # type: Session From 1d2253b9bb945646d22cce79a108655585c1a9d4 Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Tue, 1 Apr 2025 16:28:23 -0400 Subject: [PATCH 5/9] improve typing in test --- tests/test_logs.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/tests/test_logs.py b/tests/test_logs.py index a2affb7d37..68bacd187c 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -2,7 +2,7 @@ import logging import sys import time -from typing import List, Any +from typing import List, Any, Mapping, Union import pytest import sentry_sdk @@ -17,8 +17,10 @@ ) -def otel_attributes_to_dict(otel_attrs: List[Any]): - def _convert_attr(attr: dict[str, str | int | bool]): +def otel_attributes_to_dict(otel_attrs): + # type: (List[Mapping[str, Any]]) -> Mapping[str, Any] + def _convert_attr(attr): + # type: (Mapping[str, Union[str, float, bool]]) -> Any if "boolValue" in attr: return bool(attr["boolValue"]) if "doubleValue" in attr: From cd5ddd5c337ac8514361c7e0ce4a149077333b6c Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Tue, 1 Apr 2025 17:07:30 -0400 Subject: [PATCH 6/9] fix more tests --- sentry_sdk/logger.py | 7 ++++++- tests/test_logs.py | 2 +- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/sentry_sdk/logger.py b/sentry_sdk/logger.py index c2d5f37e23..6983635edd 100644 --- a/sentry_sdk/logger.py +++ b/sentry_sdk/logger.py @@ -19,7 +19,12 @@ def _capture_log(severity_text, severity_number, template, **kwargs): for k, v in kwargs.items(): attrs[f"sentry.message.parameters.{k}"] = ( v - if (isinstance(v, str) or isinstance(v, int) or isinstance(v, bool)) + if ( + isinstance(v, str) + or isinstance(v, int) + or isinstance(v, bool) + or isinstance(v, float) + ) else repr(v) ) diff --git a/tests/test_logs.py b/tests/test_logs.py index 68bacd187c..3f32c7efea 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -254,7 +254,7 @@ def test_logs_tied_to_spans(sentry_init, capture_envelopes): envelopes = capture_envelopes() with sentry_sdk.start_transaction(name="test-transaction"): - with sentry_sdk.start_span(description="test-span") as span: + with sentry_sdk.start_span(name="test-span") as span: sentry_sdk.logger.warning("This is a log tied to a span") get_client().flush() From 7564711442a25f3097e789a6a45b3101692b95df Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Wed, 2 Apr 2025 00:16:40 -0400 Subject: [PATCH 7/9] ci From edde92ab07ca31ab3036de0b36eba7cfe2934bc7 Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Wed, 2 Apr 2025 08:48:19 -0400 Subject: [PATCH 8/9] rename before_emit_log to before_send_log --- sentry_sdk/client.py | 6 +++--- tests/test_logs.py | 9 ++++++--- 2 files changed, 9 insertions(+), 6 deletions(-) diff --git a/sentry_sdk/client.py b/sentry_sdk/client.py index 801aa936d2..f29c1171a3 100644 --- a/sentry_sdk/client.py +++ b/sentry_sdk/client.py @@ -917,9 +917,9 @@ def _capture_experimental_log(self, current_scope, log): f'[Sentry Logs] {log["body"]}', ) - before_emit_log = self.options["_experiments"].get("before_emit_log") - if before_emit_log is not None: - log = before_emit_log(log, {}) + before_send_log = self.options["_experiments"].get("before_send_log") + if before_send_log is not None: + log = before_send_log(log, {}) if log is None: return diff --git a/tests/test_logs.py b/tests/test_logs.py index 3f32c7efea..1305f243de 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -110,7 +110,7 @@ def test_logs_basics(sentry_init, capture_envelopes): @minimum_python_37 -def test_logs_before_emit_log(sentry_init, capture_envelopes): +def test_logs_before_send_log(sentry_init, capture_envelopes): before_log_called = [False] def _before_log(record, hint): @@ -133,7 +133,7 @@ def _before_log(record, hint): sentry_init( _experiments={ "enable_logs": True, - "before_emit_log": _before_log, + "before_send_log": _before_log, } ) envelopes = capture_envelopes() @@ -348,7 +348,10 @@ def test_logging_errors(sentry_init, capture_envelopes): assert logs[1]["severity_text"] == "error" assert logs[1]["attributes"]["sentry.message.template"] == "error is %s" - assert logs[1]["attributes"]["sentry.message.parameters.0"] == "Exception('test exc 2')" + assert ( + logs[1]["attributes"]["sentry.message.parameters.0"] + == "Exception('test exc 2')" + ) assert "code.line.number" in logs[1]["attributes"] assert len(logs) == 2 From 5d417657b258dd19563e5065b867209833d1244b Mon Sep 17 00:00:00 2001 From: Colin Chartier Date: Wed, 2 Apr 2025 09:18:34 -0400 Subject: [PATCH 9/9] more usages of safe_repr --- sentry_sdk/_log_batcher.py | 5 ++--- sentry_sdk/integrations/logging.py | 7 ++++++- sentry_sdk/logger.py | 10 ++++++++-- 3 files changed, 16 insertions(+), 6 deletions(-) diff --git a/sentry_sdk/_log_batcher.py b/sentry_sdk/_log_batcher.py index 8dca661e2e..9c70f78b36 100644 --- a/sentry_sdk/_log_batcher.py +++ b/sentry_sdk/_log_batcher.py @@ -1,11 +1,10 @@ -import json import os import random import threading from datetime import datetime, timezone from typing import Optional, List, Callable, TYPE_CHECKING, Any -from sentry_sdk.utils import format_timestamp +from sentry_sdk.utils import format_timestamp, safe_repr from sentry_sdk.envelope import Envelope if TYPE_CHECKING: @@ -108,7 +107,7 @@ def format_attribute(key, val): return {"key": key, "value": {"doubleValue": val}} if isinstance(val, str): return {"key": key, "value": {"stringValue": val}} - return {"key": key, "value": {"stringValue": json.dumps(val)}} + return {"key": key, "value": {"stringValue": safe_repr(val)}} otel_log = { "severityText": log["severity_text"], diff --git a/sentry_sdk/integrations/logging.py b/sentry_sdk/integrations/logging.py index 0f50a276f4..ba6e6581b7 100644 --- a/sentry_sdk/integrations/logging.py +++ b/sentry_sdk/integrations/logging.py @@ -365,7 +365,12 @@ def _capture_log_from_record(client, record): if isinstance(record.args, tuple): for i, arg in enumerate(record.args): attrs[f"sentry.message.parameters.{i}"] = ( - arg if isinstance(arg, str) else safe_repr(arg) + arg + if isinstance(arg, str) + or isinstance(arg, float) + or isinstance(arg, int) + or isinstance(arg, bool) + else safe_repr(arg) ) if record.lineno: attrs["code.line.number"] = record.lineno diff --git a/sentry_sdk/logger.py b/sentry_sdk/logger.py index 6983635edd..3449fd1433 100644 --- a/sentry_sdk/logger.py +++ b/sentry_sdk/logger.py @@ -4,6 +4,7 @@ from typing import Any from sentry_sdk import get_client, get_current_scope +from sentry_sdk.utils import safe_repr def _capture_log(severity_text, severity_number, template, **kwargs): @@ -17,7 +18,10 @@ def _capture_log(severity_text, severity_number, template, **kwargs): if "attributes" in kwargs: attrs.update(kwargs.pop("attributes")) for k, v in kwargs.items(): - attrs[f"sentry.message.parameters.{k}"] = ( + attrs[f"sentry.message.parameters.{k}"] = v + + attrs = { + k: ( v if ( isinstance(v, str) @@ -25,8 +29,10 @@ def _capture_log(severity_text, severity_number, template, **kwargs): or isinstance(v, bool) or isinstance(v, float) ) - else repr(v) + else safe_repr(v) ) + for k, v in attrs.items() + } # noinspection PyProtectedMember client._capture_experimental_log(