getsentry · untitaker · Aug 13, 2020 · Jul 30, 2020 · Aug 12, 2020 · Aug 12, 2020
@@ -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":

@@ -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
@@ -323,14 +343,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)
@@ -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]]}
+    }