diff --git a/sentry_sdk/tracing.py b/sentry_sdk/tracing.py index 105be67e02..9e1ed1d55a 100644 --- a/sentry_sdk/tracing.py +++ b/sentry_sdk/tracing.py @@ -133,11 +133,12 @@ def __init__( self._span_recorder = None # type: Optional[_SpanRecorder] + # TODO this should really live on the Transaction class rather than the Span + # class def init_span_recorder(self, maxlen): # type: (int) -> None if self._span_recorder is None: self._span_recorder = _SpanRecorder(maxlen) - self._span_recorder.add(self) def __repr__(self): # type: () -> str @@ -199,9 +200,11 @@ def start_child(self, **kwargs): **kwargs ) - child._span_recorder = recorder = self._span_recorder - if recorder: - recorder.add(child) + span_recorder = ( + self.containing_transaction and self.containing_transaction._span_recorder + ) + if span_recorder: + span_recorder.add(child) return child def new_span(self, **kwargs): @@ -577,9 +580,15 @@ def finish(self, hub=None): finished_spans = [ span.to_json() for span in self._span_recorder.spans - if span is not self and span.timestamp is not None + if span.timestamp is not None ] + # we do this to break the circular reference of transaction -> span + # recorder -> span -> containing transaction (which is where we started) + # before either the spans or the transaction goes out of scope and has + # to be garbage collected + del self._span_recorder + return hub.capture_event( { "type": "transaction", diff --git a/tests/integrations/sqlalchemy/test_sqlalchemy.py b/tests/integrations/sqlalchemy/test_sqlalchemy.py index 2821126387..421a72ebae 100644 --- a/tests/integrations/sqlalchemy/test_sqlalchemy.py +++ b/tests/integrations/sqlalchemy/test_sqlalchemy.py @@ -189,7 +189,7 @@ def processor(event, hint): assert len(json_dumps(event)) < max_bytes # Some spans are discarded. - assert len(event["spans"]) == 999 + assert len(event["spans"]) == 1000 # Some spans have their descriptions truncated. Because the test always # generates the same amount of descriptions and truncation is deterministic, @@ -197,7 +197,7 @@ def processor(event, hint): # # 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 + assert len(event["_meta"]["spans"]) == 537 for i, span in enumerate(event["spans"]): description = span["description"] diff --git a/tests/tracing/test_misc.py b/tests/tracing/test_misc.py index bd0ddaf10d..5d6613cd28 100644 --- a/tests/tracing/test_misc.py +++ b/tests/tracing/test_misc.py @@ -1,9 +1,18 @@ import pytest +import gc +import uuid +import os +import sentry_sdk from sentry_sdk import Hub, start_span, start_transaction from sentry_sdk.tracing import Span, Transaction from sentry_sdk.tracing_utils import has_tracestate_enabled +try: + from unittest import mock # python 3.3 and above +except ImportError: + import mock # python < 3.3 + def test_span_trimming(sentry_init, capture_events): sentry_init(traces_sample_rate=1.0, _experiments={"max_spans": 3}) @@ -16,14 +25,12 @@ def test_span_trimming(sentry_init, capture_events): (event,) = events - # the transaction is its own first span (which counts for max_spans) but it - # doesn't show up in the span list in the event, so this is 1 less than our - # max_spans value - assert len(event["spans"]) == 2 + assert len(event["spans"]) == 3 - span1, span2 = event["spans"] + span1, span2, span3 = event["spans"] assert span1["op"] == "foo0" assert span2["op"] == "foo1" + assert span3["op"] == "foo2" def test_transaction_naming(sentry_init, capture_events): @@ -152,6 +159,79 @@ def test_finds_non_orphan_span_on_scope(sentry_init): assert scope._span.op == "sniffing" +def test_circular_references(monkeypatch, sentry_init, request): + # TODO: We discovered while writing this test about transaction/span + # reference cycles that there's actually also a circular reference in + # `serializer.py`, between the functions `_serialize_node` and + # `_serialize_node_impl`, both of which are defined inside of the main + # `serialize` function, and each of which calls the other one. For now, in + # order to avoid having those ref cycles give us a false positive here, we + # can mock out `serialize`. In the long run, though, we should probably fix + # that. (Whenever we do work on fixing it, it may be useful to add + # + # gc.set_debug(gc.DEBUG_LEAK) + # request.addfinalizer(lambda: gc.set_debug(~gc.DEBUG_LEAK)) + # + # immediately after the initial collection below, so we can see what new + # objects the garbage collecter has to clean up once `transaction.finish` is + # called and the serializer runs.) + monkeypatch.setattr( + sentry_sdk.client, + "serialize", + mock.Mock( + return_value=None, + ), + ) + + # In certain versions of python, in some environments (specifically, python + # 3.4 when run in GH Actions), we run into a `ctypes` bug which creates + # circular references when `uuid4()` is called, as happens when we're + # generating event ids. Mocking it with an implementation which doesn't use + # the `ctypes` function lets us avoid having false positives when garbage + # collecting. See https://bugs.python.org/issue20519. + monkeypatch.setattr( + uuid, + "uuid4", + mock.Mock( + return_value=uuid.UUID(bytes=os.urandom(16)), + ), + ) + + gc.disable() + request.addfinalizer(gc.enable) + + sentry_init(traces_sample_rate=1.0) + + # Make sure that we're starting with a clean slate before we start creating + # transaction/span reference cycles + gc.collect() + + dogpark_transaction = start_transaction(name="dogpark") + sniffing_span = dogpark_transaction.start_child(op="sniffing") + wagging_span = dogpark_transaction.start_child(op="wagging") + + # At some point, you have to stop sniffing - there are balls to chase! - so finish + # this span while the dogpark transaction is still open + sniffing_span.finish() + + # The wagging, however, continues long past the dogpark, so that span will + # NOT finish before the transaction ends. (Doing it in this order proves + # that both finished and unfinished spans get their cycles broken.) + dogpark_transaction.finish() + + # Eventually you gotta sleep... + wagging_span.finish() + + # assuming there are no cycles by this point, these should all be able to go + # out of scope and get their memory deallocated without the garbage + # collector having anything to do + del sniffing_span + del wagging_span + del dogpark_transaction + + assert gc.collect() == 0 + + # TODO (kmclb) remove this test once tracestate is a real feature @pytest.mark.parametrize("tracestate_enabled", [True, False, None]) def test_has_tracestate_enabled(sentry_init, tracestate_enabled):