Skip to content

feat(tracing): Record lost spans in client reports #3244

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Jul 9, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions sentry_sdk/_types.py
Original file line number Diff line number Diff line change
Expand Up @@ -155,6 +155,7 @@
"profile_chunk",
"metric_bucket",
"monitor",
"span",
]
SessionStatus = Literal["ok", "exited", "crashed", "abnormal"]

Expand Down
28 changes: 27 additions & 1 deletion sentry_sdk/client.py
Original file line number Diff line number Diff line change
Expand Up @@ -448,6 +448,7 @@ def _prepare_event(

if scope is not None:
is_transaction = event.get("type") == "transaction"
spans_before = len(event.get("spans", []))
event_ = scope.apply_to_event(event, hint, self.options)

# one of the event/error processors returned None
Expand All @@ -457,10 +458,22 @@ def _prepare_event(
"event_processor",
data_category=("transaction" if is_transaction else "error"),
)
if is_transaction:
self.transport.record_lost_event(
"event_processor",
data_category="span",
quantity=spans_before + 1, # +1 for the transaction itself
)
return None

event = event_

spans_delta = spans_before - len(event.get("spans", []))
if is_transaction and spans_delta > 0 and self.transport is not None:
self.transport.record_lost_event(
"event_processor", data_category="span", quantity=spans_delta
)

if (
self.options["attach_stacktrace"]
and "exception" not in event
Expand Down Expand Up @@ -541,14 +554,27 @@ def _prepare_event(
and event.get("type") == "transaction"
):
new_event = None
spans_before = len(event.get("spans", []))
with capture_internal_exceptions():
new_event = before_send_transaction(event, hint or {})
if new_event is None:
logger.info("before send transaction dropped event")
if self.transport:
self.transport.record_lost_event(
"before_send", data_category="transaction"
reason="before_send", data_category="transaction"
)
self.transport.record_lost_event(
reason="before_send",
data_category="span",
quantity=spans_before + 1, # +1 for the transaction itself
)
else:
spans_delta = spans_before - len(new_event.get("spans", []))
if spans_delta > 0 and self.transport is not None:
self.transport.record_lost_event(
reason="before_send", data_category="span", quantity=spans_delta
)

event = new_event # type: ignore

return event
Expand Down
4 changes: 2 additions & 2 deletions sentry_sdk/tracing.py
Original file line number Diff line number Diff line change
Expand Up @@ -119,11 +119,9 @@ class TransactionKwargs(SpanKwargs, total=False):
},
)


BAGGAGE_HEADER_NAME = "baggage"
SENTRY_TRACE_HEADER_NAME = "sentry-trace"


# Transaction source
# see https://develop.sentry.dev/sdk/event-payloads/transaction/#transaction-annotations
TRANSACTION_SOURCE_CUSTOM = "custom"
Expand Down Expand Up @@ -858,6 +856,8 @@ def finish(self, hub=None, end_timestamp=None):

client.transport.record_lost_event(reason, data_category="transaction")

# Only one span (the transaction itself) is discarded, since we did not record any spans here.
client.transport.record_lost_event(reason, data_category="span")
return None

if not self.name:
Expand Down
30 changes: 27 additions & 3 deletions sentry_sdk/transport.py
Original file line number Diff line number Diff line change
Expand Up @@ -133,10 +133,23 @@ def record_lost_event(
reason, # type: str
data_category=None, # type: Optional[EventDataCategory]
item=None, # type: Optional[Item]
*,
quantity=1, # type: int
):
# type: (...) -> None
"""This increments a counter for event loss by reason and
data category.
data category by the given positive-int quantity (default 1).

If an item is provided, the data category and quantity are
extracted from the item, and the values passed for
data_category and quantity are ignored.

When recording a lost transaction via data_category="transaction",
the calling code should also record the lost spans via this method.
When recording lost spans, `quantity` should be set to the number
of contained spans, plus one for the transaction itself. When
passing an Item containing a transaction via the `item` parameter,
this method automatically records the lost spans.
"""
return None

Expand Down Expand Up @@ -224,15 +237,26 @@ def record_lost_event(
reason, # type: str
data_category=None, # type: Optional[EventDataCategory]
item=None, # type: Optional[Item]
*,
quantity=1, # type: int
):
# type: (...) -> None
if not self.options["send_client_reports"]:
return

quantity = 1
if item is not None:
data_category = item.data_category
if data_category == "attachment":
quantity = 1 # If an item is provided, we always count it as 1 (except for attachments, handled below).

if data_category == "transaction":
# Also record the lost spans
event = item.get_transaction_event() or {}

# +1 for the transaction itself
span_count = len(event.get("spans") or []) + 1
self.record_lost_event(reason, "span", quantity=span_count)

elif data_category == "attachment":
# quantity of 0 is actually 1 as we do not want to count
# empty attachments as actually empty.
quantity = len(item.get_bytes()) or 1
Expand Down
4 changes: 2 additions & 2 deletions tests/conftest.py
Original file line number Diff line number Diff line change
Expand Up @@ -253,8 +253,8 @@ def inner():
calls = []
test_client = sentry_sdk.get_client()

def record_lost_event(reason, data_category=None, item=None):
calls.append((reason, data_category, item))
def record_lost_event(reason, data_category=None, item=None, *, quantity=1):
calls.append((reason, data_category, item, quantity))

monkeypatch.setattr(
test_client.transport, "record_lost_event", record_lost_event
Expand Down
6 changes: 3 additions & 3 deletions tests/profiler/test_transaction_profiler.py
Original file line number Diff line number Diff line change
Expand Up @@ -162,7 +162,7 @@ def test_profiles_sample_rate(
elif profile_count:
assert record_lost_event_calls == []
else:
assert record_lost_event_calls == [("sample_rate", "profile", None)]
assert record_lost_event_calls == [("sample_rate", "profile", None, 1)]


@pytest.mark.parametrize(
Expand Down Expand Up @@ -231,7 +231,7 @@ def test_profiles_sampler(
if profile_count:
assert record_lost_event_calls == []
else:
assert record_lost_event_calls == [("sample_rate", "profile", None)]
assert record_lost_event_calls == [("sample_rate", "profile", None, 1)]


def test_minimum_unique_samples_required(
Expand Down Expand Up @@ -260,7 +260,7 @@ def test_minimum_unique_samples_required(
# because we dont leave any time for the profiler to
# take any samples, it should be not be sent
assert len(items["profile"]) == 0
assert record_lost_event_calls == [("insufficient_data", "profile", None)]
assert record_lost_event_calls == [("insufficient_data", "profile", None, 1)]


@pytest.mark.forked
Expand Down
7 changes: 4 additions & 3 deletions tests/test_basics.py
Original file line number Diff line number Diff line change
Expand Up @@ -570,7 +570,7 @@ def test_dedupe_event_processor_drop_records_client_report(

assert event["level"] == "error"
assert "exception" in event
assert lost_event_call == ("event_processor", "error", None)
assert lost_event_call == ("event_processor", "error", None, 1)


def test_event_processor_drop_records_client_report(
Expand Down Expand Up @@ -602,8 +602,9 @@ def foo(event, hint):
# Using Counter because order of record_lost_event calls does not matter
assert Counter(record_lost_event_calls) == Counter(
[
("event_processor", "error", None),
("event_processor", "transaction", None),
("event_processor", "error", None, 1),
("event_processor", "transaction", None, 1),
("event_processor", "span", None, 1),
]
)

Expand Down
157 changes: 157 additions & 0 deletions tests/test_client.py
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
import subprocess
import sys
import time
from collections import Counter, defaultdict
from collections.abc import Mapping
from textwrap import dedent
from unittest import mock
Expand Down Expand Up @@ -1214,3 +1215,159 @@ def test_uwsgi_warnings(sentry_init, recwarn, opt, missing_flags):
assert flag in str(record.message)
else:
assert not recwarn


class TestSpanClientReports:
"""
Tests for client reports related to spans.
"""

@staticmethod
def span_dropper(spans_to_drop):
"""
Returns a function that can be used to drop spans from an event.
"""

def drop_spans(event, _):
event["spans"] = event["spans"][spans_to_drop:]
return event

return drop_spans

@staticmethod
def mock_transaction_event(span_count):
"""
Returns a mock transaction event with the given number of spans.
"""

return defaultdict(
mock.MagicMock,
type="transaction",
spans=[mock.MagicMock() for _ in range(span_count)],
)

def __init__(self, span_count):
"""Configures a test case with the number of spans dropped and whether the transaction was dropped."""
self.span_count = span_count
self.expected_record_lost_event_calls = Counter()
self.before_send = lambda event, _: event
self.event_processor = lambda event, _: event

def _update_resulting_calls(self, reason, drops_transactions=0, drops_spans=0):
"""
Updates the expected calls with the given resulting calls.
"""
if drops_transactions > 0:
self.expected_record_lost_event_calls[
(reason, "transaction", None, drops_transactions)
] += 1

if drops_spans > 0:
self.expected_record_lost_event_calls[
(reason, "span", None, drops_spans)
] += 1

def with_before_send(
self,
before_send,
*,
drops_transactions=0,
drops_spans=0,
):
self.before_send = before_send
self._update_resulting_calls(
"before_send",
drops_transactions,
drops_spans,
)

return self

def with_event_processor(
self,
event_processor,
*,
drops_transactions=0,
drops_spans=0,
):
self.event_processor = event_processor
self._update_resulting_calls(
"event_processor",
drops_transactions,
drops_spans,
)

return self

def run(self, sentry_init, capture_record_lost_event_calls):
"""Runs the test case with the configured parameters."""
sentry_init(before_send_transaction=self.before_send)
record_lost_event_calls = capture_record_lost_event_calls()

with sentry_sdk.isolation_scope() as scope:
scope.add_event_processor(self.event_processor)
event = self.mock_transaction_event(self.span_count)
sentry_sdk.get_client().capture_event(event, scope=scope)

# We use counters to ensure that the calls are made the expected number of times, disregarding order.
assert Counter(record_lost_event_calls) == self.expected_record_lost_event_calls


@pytest.mark.parametrize(
"test_config",
(
TestSpanClientReports(span_count=10), # No spans dropped
TestSpanClientReports(span_count=0).with_before_send(
lambda e, _: None,
drops_transactions=1,
drops_spans=1,
),
TestSpanClientReports(span_count=10).with_before_send(
lambda e, _: None,
drops_transactions=1,
drops_spans=11,
),
TestSpanClientReports(span_count=10).with_before_send(
TestSpanClientReports.span_dropper(3),
drops_spans=3,
),
TestSpanClientReports(span_count=10).with_before_send(
TestSpanClientReports.span_dropper(10),
drops_spans=10,
),
TestSpanClientReports(span_count=10).with_event_processor(
lambda e, _: None,
drops_transactions=1,
drops_spans=11,
),
TestSpanClientReports(span_count=10).with_event_processor(
TestSpanClientReports.span_dropper(3),
drops_spans=3,
),
TestSpanClientReports(span_count=10).with_event_processor(
TestSpanClientReports.span_dropper(10),
drops_spans=10,
),
TestSpanClientReports(span_count=10)
.with_event_processor(
TestSpanClientReports.span_dropper(3),
drops_spans=3,
)
.with_before_send(
TestSpanClientReports.span_dropper(5),
drops_spans=5,
),
TestSpanClientReports(10)
.with_event_processor(
TestSpanClientReports.span_dropper(3),
drops_spans=3,
)
.with_before_send(
lambda e, _: None,
drops_transactions=1,
drops_spans=8, # 3 of the 11 (incl. transaction) spans already dropped
),
),
)
def test_dropped_transaction(sentry_init, capture_record_lost_event_calls, test_config):
test_config.run(sentry_init, capture_record_lost_event_calls)
8 changes: 7 additions & 1 deletion tests/test_monitor.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import random
from collections import Counter
from unittest import mock

import sentry_sdk
Expand Down Expand Up @@ -79,7 +80,12 @@ def test_transaction_uses_downsampled_rate(
assert transaction.sampled is False
assert transaction.sample_rate == 0.5

assert record_lost_event_calls == [("backpressure", "transaction", None)]
assert Counter(record_lost_event_calls) == Counter(
[
("backpressure", "transaction", None, 1),
("backpressure", "span", None, 1),
]
)


def test_monitor_no_thread_on_shutdown_no_errors(sentry_init):
Expand Down
Loading
Loading