Dont use threading.Timer when finishing long running Transactions

sentry_sdk/integrations/wsgi.py

@@ -1,6 +1,5 @@
 import sys
 from functools import partial
-from threading import Timer
 
 import sentry_sdk
 from sentry_sdk._werkzeug import get_host, _get_headers
@@ -46,9 +45,6 @@ def __call__(self, status, response_headers, exc_info=None):  # type: ignore
             pass
 
 
-MAX_TRANSACTION_DURATION_SECONDS = 5 * 60
-
-
 _wsgi_middleware_applied = ContextVar("sentry_wsgi_middleware_applied")
 
 
@@ -124,18 +120,11 @@ def __call__(self, environ, start_response):
                             origin=self.span_origin,
                         )
 
-                    timer = None
                     if transaction is not None:
                         sentry_sdk.start_transaction(
                             transaction,
                             custom_sampling_context={"wsgi_environ": environ},
                         ).__enter__()
-                        timer = Timer(
-                            MAX_TRANSACTION_DURATION_SECONDS,
-                            _finish_long_running_transaction,
-                            args=(current_scope, scope),
-                        )
-                        timer.start()
 
                     try:
                         response = self.app(
@@ -149,7 +138,7 @@ def __call__(self, environ, start_response):
                     except BaseException:
                         exc_info = sys.exc_info()
                         _capture_exception(exc_info)
-                        finish_running_transaction(current_scope, exc_info, timer)
+                        finish_running_transaction(current_scope, exc_info)
                         reraise(*exc_info)
 
         finally:
@@ -159,7 +148,6 @@ def __call__(self, environ, start_response):
             response=response,
             current_scope=current_scope,
             isolation_scope=scope,
-            timer=timer,
         )
 
 
@@ -255,20 +243,18 @@ class _ScopedResponse:
     - WSGI servers streaming responses interleaved from the same thread
     """
 
-    __slots__ = ("_response", "_current_scope", "_isolation_scope", "_timer")
+    __slots__ = ("_response", "_current_scope", "_isolation_scope")
 
     def __init__(
         self,
         response,  # type: Iterator[bytes]
         current_scope,  # type: sentry_sdk.scope.Scope
         isolation_scope,  # type: sentry_sdk.scope.Scope
-        timer=None,  # type: Optional[Timer]
     ):
         # type: (...) -> None
         self._response = response
         self._current_scope = current_scope
         self._isolation_scope = isolation_scope
-        self._timer = timer
 
     def __iter__(self):
         # type: () -> Iterator[bytes]
@@ -290,14 +276,14 @@ def __iter__(self):
         finally:
             with use_isolation_scope(self._isolation_scope):
                 with use_scope(self._current_scope):
-                    finish_running_transaction(timer=self._timer)
+                    finish_running_transaction()
 
     def close(self):
         # type: () -> None
         with use_isolation_scope(self._isolation_scope):
             with use_scope(self._current_scope):
                 try:
-                    finish_running_transaction(timer=self._timer)
+                    finish_running_transaction()
                     self._response.close()  # type: ignore
                 except AttributeError:
                     pass
@@ -346,18 +332,3 @@ def event_processor(event, hint):
         return event
 
     return event_processor
-
-
-def _finish_long_running_transaction(current_scope, isolation_scope):
-    # type: (sentry_sdk.scope.Scope, sentry_sdk.scope.Scope) -> None
-    """
-    Make sure we don't keep transactions open for too long.
-    Triggered after MAX_TRANSACTION_DURATION_SECONDS have passed.
-    """
-    try:
-        with use_isolation_scope(isolation_scope):
-            with use_scope(current_scope):
-                finish_running_transaction()
-    except AttributeError:
-        # transaction is not there anymore
-        pass

sentry_sdk/tracing.py

@@ -13,6 +13,8 @@
     nanosecond_time,
 )
 
+MAX_TRANSACTION_DURATION_SECONDS = 5 * 60
+
 from typing import TYPE_CHECKING
 
 if TYPE_CHECKING:
@@ -377,7 +379,10 @@ def __exit__(self, ty, value, tb):
 
         scope, old_span = self._context_manager_state
         del self._context_manager_state
+
         self.finish(scope)
+        self.prune_transaction()
+
         scope.span = old_span
 
     @property
@@ -651,6 +656,30 @@ def finish(self, scope=None, end_timestamp=None):
 
         return None
 
+    def prune_transaction(self, scope=None):
+        # type: (Optional[sentry_sdk.Scope]) -> None
+        if (
+            self.containing_transaction
+            and self.containing_transaction.timestamp is not None
+        ):
+            # transaction already finished, nothing to do
+            return
+
+        trx = self.containing_transaction
+        if trx is None or self is trx:
+            return
+
+        transaction_duration = (
+            datetime.now(timezone.utc) - trx.start_timestamp
+        ).total_seconds()
+
+        if transaction_duration > MAX_TRANSACTION_DURATION_SECONDS:
+            logger.debug(
+                "Finishing Transaction because it is running longer the maximum allowed duration (%ss)",
+                MAX_TRANSACTION_DURATION_SECONDS,
+            )
+            trx.__exit__(None, None, None)
+
     def to_json(self):
         # type: () -> Dict[str, Any]
         """Returns a JSON-compatible representation of the span."""

sentry_sdk/tracing_utils.py

@@ -37,7 +37,6 @@
     from types import FrameType
 
     from sentry_sdk._types import ExcInfo
-    from threading import Timer
 
 
 SENTRY_TRACE_REGEX = re.compile(
@@ -744,11 +743,8 @@ def get_current_span(scope=None):
     from sentry_sdk.tracing import Span
 
 
-def finish_running_transaction(scope=None, exc_info=None, timer=None):
-    # type: (Optional[sentry_sdk.Scope], Optional[ExcInfo], Optional[Timer]) -> None
-    if timer is not None:
-        timer.cancel()
-
+def finish_running_transaction(scope=None, exc_info=None):
+    # type: (Optional[sentry_sdk.Scope], Optional[ExcInfo]) -> None
     current_scope = scope or sentry_sdk.get_current_scope()
     if current_scope.transaction is not None and hasattr(
         current_scope.transaction, "_context_manager_state"

tests/integrations/wsgi/test_wsgi.py

@@ -500,20 +500,23 @@ def dogpark(environ, start_response):
 
 
 def test_long_running_transaction_finished(sentry_init, capture_events):
-    # we allow transactions to be 0.5 seconds as a maximum
-    new_max_duration = 0.5
+    # we allow transactions to be 1 seconds as a maximum
+    new_max_duration = 1
 
     with mock.patch.object(
-        sentry_sdk.integrations.wsgi,
+        sentry_sdk.tracing,
         "MAX_TRANSACTION_DURATION_SECONDS",
         new_max_duration,
     ):
 
         def generate_content():
             # This response will take 1.5 seconds to generate
             for _ in range(15):
-                time.sleep(0.1)
-                yield "ok"
+                with sentry_sdk.start_span(
+                    op="generate_content", name="generate_content {_}"
+                ):
+                    time.sleep(0.1)
+                    yield "ok"
 
         def long_running_app(environ, start_response):
             start_response("200 OK", [])
@@ -534,43 +537,8 @@ def long_running_app(environ, start_response):
             datetime_from_isoformat(transaction["timestamp"])
             - datetime_from_isoformat(transaction["start_timestamp"])
         ).total_seconds()
-        assert (
-            transaction_duration <= new_max_duration * 1.02
-        )  # we allow 2% margin for processing the request
-
-
-def test_long_running_transaction_timer_canceled(sentry_init, capture_events):
-    # we allow transactions to be 0.5 seconds as a maximum
-    new_max_duration = 0.5
-
-    with mock.patch.object(
-        sentry_sdk.integrations.wsgi,
-        "MAX_TRANSACTION_DURATION_SECONDS",
-        new_max_duration,
-    ):
-        with mock.patch(
-            "sentry_sdk.integrations.wsgi._finish_long_running_transaction"
-        ) as mock_finish:
 
-            def generate_content():
-                # This response will take 0.3 seconds to generate
-                for _ in range(3):
-                    time.sleep(0.1)
-                    yield "ok"
-
-            def long_running_app(environ, start_response):
-                start_response("200 OK", [])
-                return generate_content()
-
-            sentry_init(send_default_pii=True, traces_sample_rate=1.0)
-            app = SentryWsgiMiddleware(long_running_app)
-
-            events = capture_events()
-
-            client = Client(app)
-            response = client.get("/")
-            _ = response.get_data()
-
-            (transaction,) = events
-
-            mock_finish.assert_not_called()
+        assert (
+            transaction_duration
+            <= new_max_duration * 1.05  # we allow 5% margin for processing the request
+        ), "Long running transaction has not been finished after a set maximum duration"