ref: Store tracked spans on start not finish (#738)

This matches the JS implementation. Without it, we cannot use the span
recorder of a span to find its parent transaction.

Note about test changes

Instrumented subprocess methods are called in this order: __init__,
communicate, wait. Because we now store the spans on start, that's the
order we expect the spans to be in. The previous order was based on
finish time.

Grouping the assertion of "op" values together produces better output on
failure, because one can easily detect what all the "op" values are,
instead of being left with only the first one that is different.

Similar to subprocess changes, the order of expected middleware spans in
Django is now sorted by start time.

Author: rhcarvalho

sentry_sdk/tracing.py

@@ -67,28 +67,26 @@ def __iter__(self):
 
 
 class _SpanRecorder(object):
-    __slots__ = ("maxlen", "finished_spans", "open_span_count")
+    """Limits the number of spans recorded in a transaction."""
+
+    __slots__ = ("maxlen", "spans")
 
     def __init__(self, maxlen):
         # type: (int) -> None
-        self.maxlen = maxlen
-        self.open_span_count = 0  # type: int
-        self.finished_spans = []  # type: List[Span]
-
-    def start_span(self, span):
+        # FIXME: this is `maxlen - 1` only to preserve historical behavior
+        # enforced by tests.
+        # Either this should be changed to `maxlen` or the JS SDK implementation
+        # should be changed to match a consistent interpretation of what maxlen
+        # limits: either transaction+spans or only child spans.
+        self.maxlen = maxlen - 1
+        self.spans = []  # type: List[Span]
+
+    def add(self, span):
         # type: (Span) -> None
-
-        # This is just so that we don't run out of memory while recording a lot
-        # of spans. At some point we just stop and flush out the start of the
-        # trace tree (i.e. the first n spans with the smallest
-        # start_timestamp).
-        self.open_span_count += 1
-        if self.open_span_count > self.maxlen:
+        if len(self.spans) > self.maxlen:
             span._span_recorder = None
-
-    def finish_span(self, span):
-        # type: (Span) -> None
-        self.finished_spans.append(span)
+        else:
+            self.spans.append(span)
 
 
 class Span(object):
@@ -157,7 +155,7 @@ def init_finished_spans(self, maxlen):
         # type: (int) -> None
         if self._span_recorder is None:
             self._span_recorder = _SpanRecorder(maxlen)
-        self._span_recorder.start_span(self)
+        self._span_recorder.add(self)
 
     def __repr__(self):
         # type: () -> str
@@ -330,8 +328,6 @@ def finish(self, hub=None):
         if self._span_recorder is None:
             return None
 
-        self._span_recorder.finish_span(self)
-
         if self.transaction is None:
             # If this has no transaction set we assume there's a parent
             # transaction for this span that would be flushed out eventually.
@@ -354,6 +350,12 @@ def finish(self, hub=None):
 
             return None
 
+        finished_spans = [
+            span.to_json(client)
+            for span in self._span_recorder.spans
+            if span is not self and span.timestamp is not None
+        ]
+
         return hub.capture_event(
             {
                 "type": "transaction",
@@ -362,11 +364,7 @@ def finish(self, hub=None):
                 "tags": self._tags,
                 "timestamp": self.timestamp,
                 "start_timestamp": self.start_timestamp,
-                "spans": [
-                    s.to_json(client)
-                    for s in self._span_recorder.finished_spans
-                    if s is not self
-                ],
+                "spans": finished_spans,
             }
         )
 

tests/integrations/django/test_basic.py

@@ -518,10 +518,10 @@ def test_middleware_spans(sentry_init, client, capture_events):
 
     if DJANGO_VERSION >= (1, 10):
         reference_value = [
-            "tests.integrations.django.myapp.settings.TestFunctionMiddleware.__call__",
-            "tests.integrations.django.myapp.settings.TestMiddleware.__call__",
-            "django.contrib.auth.middleware.AuthenticationMiddleware.__call__",
             "django.contrib.sessions.middleware.SessionMiddleware.__call__",
+            "django.contrib.auth.middleware.AuthenticationMiddleware.__call__",
+            "tests.integrations.django.myapp.settings.TestMiddleware.__call__",
+            "tests.integrations.django.myapp.settings.TestFunctionMiddleware.__call__",
         ]
     else:
         reference_value = [

tests/integrations/stdlib/test_subprocess.py

@@ -140,13 +140,15 @@ def test_subprocess_basic(
 
     (
         subprocess_init_span,
-        subprocess_wait_span,
         subprocess_communicate_span,
+        subprocess_wait_span,
     ) = transaction_event["spans"]
 
-    assert subprocess_init_span["op"] == "subprocess"
-    assert subprocess_communicate_span["op"] == "subprocess.communicate"
-    assert subprocess_wait_span["op"] == "subprocess.wait"
+    assert (
+        subprocess_init_span["op"],
+        subprocess_communicate_span["op"],
+        subprocess_wait_span["op"],
+    ) == ("subprocess", "subprocess.communicate", "subprocess.wait")
 
     # span hierarchy
     assert (