diff --git a/sentry_sdk/integrations/wsgi.py b/sentry_sdk/integrations/wsgi.py index 751735f462..29dd6d6f6d 100644 --- a/sentry_sdk/integrations/wsgi.py +++ b/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 diff --git a/sentry_sdk/tracing.py b/sentry_sdk/tracing.py index 3868b2e6c8..a0949fa9c2 100644 --- a/sentry_sdk/tracing.py +++ b/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.""" diff --git a/sentry_sdk/tracing_utils.py b/sentry_sdk/tracing_utils.py index 969e0812e4..71ef710259 100644 --- a/sentry_sdk/tracing_utils.py +++ b/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" diff --git a/tests/integrations/wsgi/test_wsgi.py b/tests/integrations/wsgi/test_wsgi.py index a4f5ca0623..5c88bad653 100644 --- a/tests/integrations/wsgi/test_wsgi.py +++ b/tests/integrations/wsgi/test_wsgi.py @@ -500,11 +500,11 @@ 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, ): @@ -512,8 +512,11 @@ def test_long_running_transaction_finished(sentry_init, capture_events): 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"