feat: Avoid truncating span descriptions (#782)

* feat: Avoid truncating span descriptions

For database auto-instrumented spans, the description contains
potentially long SQL queries that are most useful when not truncated.

Because arbitrarily large events may be discarded by the server as a
protection mechanism, we dynamically limit the description length,
preserving the most important descriptions/queries.

Performance impact

Preliminary CPU profiling using [1] suggests that uuid4() dominates the
execution time for code sending many transactions sequentially.

Preliminary memory profiling using [2] and looking at the max RSS of a
benchmark script suggests that the max RSS has no significant change
(JSON encoding in CPython is implemented in C).

In any case, we mitigate any increase in memory usage and run time for
the majority of cases by avoiding any extra work when the total number
of bytes consumed by descriptions do not exceed ~512 KB, which is
equivalent to having the standard string truncation applied.

Integrating profiling to the SDK is left for a future PR.

[1]: https://pypi.org/project/zprofile/
[2]: /usr/bin/time -l (macOS)

Co-authored-by: Markus Unterwaditzer <[email protected]>

Author: rhcarvalho

sentry_sdk/client.py

@@ -197,7 +197,12 @@ def _prepare_event(
         # Postprocess the event here so that annotated types do
         # generally not surface in before_send
         if event is not None:
-            event = serialize(event)
+            event = serialize(
+                event,
+                smart_transaction_trimming=self.options["_experiments"].get(
+                    "smart_transaction_trimming"
+                ),
+            )
 
         before_send = self.options["before_send"]
         if before_send is not None and event.get("type") != "transaction":

sentry_sdk/serializer.py

@@ -6,29 +6,37 @@
     AnnotatedValue,
     capture_internal_exception,
     disable_capture_event,
+    format_timestamp,
+    json_dumps,
     safe_repr,
     strip_string,
-    format_timestamp,
 )
 
+import sentry_sdk.utils
+
 from sentry_sdk._compat import text_type, PY2, string_types, number_types, iteritems
 
 from sentry_sdk._types import MYPY
 
 if MYPY:
+    from datetime import timedelta
+
     from types import TracebackType
 
     from typing import Any
+    from typing import Callable
+    from typing import ContextManager
     from typing import Dict
     from typing import List
     from typing import Optional
-    from typing import Callable
-    from typing import Union
-    from typing import ContextManager
+    from typing import Tuple
     from typing import Type
+    from typing import Union
 
     from sentry_sdk._types import NotImplementedType, Event
 
+    Span = Dict[str, Any]
+
     ReprProcessor = Callable[[Any, Dict[str, Any]], Union[NotImplementedType, str]]
     Segment = Union[str, int]
 
@@ -48,6 +56,17 @@
     # Bytes are technically not strings in Python 3, but we can serialize them
     serializable_str_types = (str, bytes)
 
+
+# Maximum length of JSON-serialized event payloads that can be safely sent
+# before the server may reject the event due to its size. This is not intended
+# to reflect actual values defined server-side, but rather only be an upper
+# bound for events sent by the SDK.
+#
+# Can be overwritten if wanting to send more bytes, e.g. with a custom server.
+# When changing this, keep in mind that events may be a little bit larger than
+# this value due to attached metadata, so keep the number conservative.
+MAX_EVENT_BYTES = 10 ** 6
+
 MAX_DATABAG_DEPTH = 5
 MAX_DATABAG_BREADTH = 10
 CYCLE_MARKER = u"<cyclic>"
@@ -93,11 +112,12 @@ def __exit__(
         self._ids.pop(id(self._objs.pop()), None)
 
 
-def serialize(event, **kwargs):
-    # type: (Event, **Any) -> Event
+def serialize(event, smart_transaction_trimming=False, **kwargs):
+    # type: (Event, bool, **Any) -> Event
     memo = Memo()
     path = []  # type: List[Segment]
     meta_stack = []  # type: List[Dict[str, Any]]
+    span_description_bytes = []  # type: List[int]
 
     def _annotate(**meta):
         # type: (**Any) -> None
@@ -325,14 +345,113 @@ def _serialize_node_impl(
             if not isinstance(obj, string_types):
                 obj = safe_repr(obj)
 
+        # Allow span descriptions to be longer than other strings.
+        #
+        # For database auto-instrumented spans, the description contains
+        # potentially long SQL queries that are most useful when not truncated.
+        # Because arbitrarily large events may be discarded by the server as a
+        # protection mechanism, we dynamically limit the description length
+        # later in _truncate_span_descriptions.
+        if (
+            smart_transaction_trimming
+            and len(path) == 3
+            and path[0] == "spans"
+            and path[-1] == "description"
+        ):
+            span_description_bytes.append(len(obj))
+            return obj
         return _flatten_annotated(strip_string(obj))
 
+    def _truncate_span_descriptions(serialized_event, event, excess_bytes):
+        # type: (Event, Event, int) -> None
+        """
+        Modifies serialized_event in-place trying to remove excess_bytes from
+        span descriptions. The original event is used read-only to access the
+        span timestamps (represented as RFC3399-formatted strings in
+        serialized_event).
+
+        It uses heuristics to prioritize preserving the description of spans
+        that might be the most interesting ones in terms of understanding and
+        optimizing performance.
+        """
+        # When truncating a description, preserve a small prefix.
+        min_length = 10
+
+        def shortest_duration_longest_description_first(args):
+            # type: (Tuple[int, Span]) -> Tuple[timedelta, int]
+            i, serialized_span = args
+            span = event["spans"][i]
+            now = datetime.utcnow()
+            start = span.get("start_timestamp") or now
+            end = span.get("timestamp") or now
+            duration = end - start
+            description = serialized_span.get("description") or ""
+            return (duration, -len(description))
+
+        # Note: for simplicity we sort spans by exact duration and description
+        # length. If ever needed, we could have a more involved heuristic, e.g.
+        # replacing exact durations with "buckets" and/or looking at other span
+        # properties.
+        path.append("spans")
+        for i, span in sorted(
+            enumerate(serialized_event.get("spans") or []),
+            key=shortest_duration_longest_description_first,
+        ):
+            description = span.get("description") or ""
+            if len(description) <= min_length:
+                continue
+            excess_bytes -= len(description) - min_length
+            path.extend([i, "description"])
+            # Note: the last time we call strip_string we could preserve a few
+            # more bytes up to a total length of MAX_EVENT_BYTES. Since that's
+            # not strictly required, we leave it out for now for simplicity.
+            span["description"] = _flatten_annotated(
+                strip_string(description, max_length=min_length)
+            )
+            del path[-2:]
+            del meta_stack[len(path) + 1 :]
+
+            if excess_bytes <= 0:
+                break
+        path.pop()
+        del meta_stack[len(path) + 1 :]
+
     disable_capture_event.set(True)
     try:
         rv = _serialize_node(event, **kwargs)
         if meta_stack and isinstance(rv, dict):
             rv["_meta"] = meta_stack[0]
 
+        sum_span_description_bytes = sum(span_description_bytes)
+        if smart_transaction_trimming and sum_span_description_bytes > 0:
+            span_count = len(event.get("spans") or [])
+            # This is an upper bound of how many bytes all descriptions would
+            # consume if the usual string truncation in _serialize_node_impl
+            # would have taken place, not accounting for the metadata attached
+            # as event["_meta"].
+            descriptions_budget_bytes = span_count * sentry_sdk.utils.MAX_STRING_LENGTH
+
+            # If by not truncating descriptions we ended up with more bytes than
+            # per the usual string truncation, check if the event is too large
+            # and we need to truncate some descriptions.
+            #
+            # This is guarded with an if statement to avoid JSON-encoding the
+            # event unnecessarily.
+            if sum_span_description_bytes > descriptions_budget_bytes:
+                original_bytes = len(json_dumps(rv))
+                excess_bytes = original_bytes - MAX_EVENT_BYTES
+                if excess_bytes > 0:
+                    # Event is too large, will likely be discarded by the
+                    # server. Trim it down before sending.
+                    _truncate_span_descriptions(rv, event, excess_bytes)
+
+                    # Span descriptions truncated, set or reset _meta.
+                    #
+                    # We run the same code earlier because we want to account
+                    # for _meta when calculating original_bytes, the number of
+                    # bytes in the JSON-encoded event.
+                    if meta_stack and isinstance(rv, dict):
+                        rv["_meta"] = meta_stack[0]
         return rv
     finally:
         disable_capture_event.set(False)

tests/integrations/sqlalchemy/test_sqlalchemy.py

@@ -6,8 +6,10 @@
 from sqlalchemy.ext.declarative import declarative_base
 from sqlalchemy.orm import relationship, sessionmaker
 
-from sentry_sdk import capture_message, start_transaction
+from sentry_sdk import capture_message, start_transaction, configure_scope
 from sentry_sdk.integrations.sqlalchemy import SqlalchemyIntegration
+from sentry_sdk.utils import json_dumps, MAX_STRING_LENGTH
+from sentry_sdk.serializer import MAX_EVENT_BYTES
 
 
 def test_orm_queries(sentry_init, capture_events):
@@ -133,3 +135,90 @@ class Address(Base):
   - op='db': description='RELEASE SAVEPOINT sa_savepoint_4'\
 """
     )
+
+
+def test_long_sql_query_preserved(sentry_init, capture_events):
+    sentry_init(
+        traces_sample_rate=1,
+        integrations=[SqlalchemyIntegration()],
+        _experiments={"smart_transaction_trimming": True},
+    )
+    events = capture_events()
+
+    engine = create_engine("sqlite:///:memory:")
+    with start_transaction(name="test"):
+        with engine.connect() as con:
+            con.execute(" UNION ".join("SELECT {}".format(i) for i in range(100)))
+
+    (event,) = events
+    description = event["spans"][0]["description"]
+    assert description.startswith("SELECT 0 UNION SELECT 1")
+    assert description.endswith("SELECT 98 UNION SELECT 99")
+
+
+def test_too_large_event_truncated(sentry_init, capture_events):
+    sentry_init(
+        traces_sample_rate=1,
+        integrations=[SqlalchemyIntegration()],
+        _experiments={"smart_transaction_trimming": True},
+    )
+    events = capture_events()
+
+    long_str = "x" * (MAX_STRING_LENGTH + 10)
+
+    with configure_scope() as scope:
+
+        @scope.add_event_processor
+        def processor(event, hint):
+            event["message"] = long_str
+            return event
+
+    engine = create_engine("sqlite:///:memory:")
+    with start_transaction(name="test"):
+        with engine.connect() as con:
+            for _ in range(2000):
+                con.execute(" UNION ".join("SELECT {}".format(i) for i in range(100)))
+
+    (event,) = events
+
+    # Because of attached metadata in the "_meta" key, we may send out a little
+    # bit more than MAX_EVENT_BYTES.
+    max_bytes = 1.2 * MAX_EVENT_BYTES
+    assert len(json_dumps(event)) < max_bytes
+
+    # Some spans are discarded.
+    assert len(event["spans"]) == 999
+
+    # Some spans have their descriptions truncated. Because the test always
+    # generates the same amount of descriptions and truncation is deterministic,
+    # the number here should never change across test runs.
+    #
+    # Which exact span descriptions are truncated depends on the span durations
+    # of each SQL query and is non-deterministic.
+    assert len(event["_meta"]["spans"]) == 536
+
+    for i, span in enumerate(event["spans"]):
+        description = span["description"]
+
+        assert description.startswith("SELECT ")
+        if str(i) in event["_meta"]["spans"]:
+            # Description must have been truncated
+            assert len(description) == 10
+            assert description.endswith("...")
+        else:
+            # Description was not truncated, check for original length
+            assert len(description) == 1583
+            assert description.endswith("SELECT 98 UNION SELECT 99")
+
+    # Smoke check the meta info for one of the spans.
+    assert next(iter(event["_meta"]["spans"].values())) == {
+        "description": {"": {"len": 1583, "rem": [["!limit", "x", 7, 10]]}}
+    }
+
+    # Smoke check that truncation of other fields has not changed.
+    assert len(event["message"]) == MAX_STRING_LENGTH
+
+    # The _meta for other truncated fields should be there as well.
+    assert event["_meta"]["message"] == {
+        "": {"len": 522, "rem": [["!limit", "x", 509, 512]]}
+    }