diff --git a/sentry_sdk/integrations/wsgi.py b/sentry_sdk/integrations/wsgi.py index 50deae10c5..751735f462 100644 --- a/sentry_sdk/integrations/wsgi.py +++ b/sentry_sdk/integrations/wsgi.py @@ -1,19 +1,19 @@ import sys from functools import partial +from threading import Timer import sentry_sdk from sentry_sdk._werkzeug import get_host, _get_headers from sentry_sdk.api import continue_trace from sentry_sdk.consts import OP -from sentry_sdk.scope import should_send_default_pii +from sentry_sdk.scope import should_send_default_pii, use_isolation_scope, use_scope from sentry_sdk.integrations._wsgi_common import ( DEFAULT_HTTP_METHODS_TO_CAPTURE, _filter_headers, - nullcontext, ) from sentry_sdk.sessions import track_session -from sentry_sdk.scope import use_isolation_scope from sentry_sdk.tracing import Transaction, TRANSACTION_SOURCE_ROUTE +from sentry_sdk.tracing_utils import finish_running_transaction from sentry_sdk.utils import ( ContextVar, capture_internal_exceptions, @@ -46,6 +46,9 @@ 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") @@ -98,6 +101,7 @@ def __call__(self, environ, start_response): _wsgi_middleware_applied.set(True) try: with sentry_sdk.isolation_scope() as scope: + current_scope = sentry_sdk.get_current_scope() with track_session(scope, session_mode="request"): with capture_internal_exceptions(): scope.clear_breadcrumbs() @@ -109,6 +113,7 @@ def __call__(self, environ, start_response): ) method = environ.get("REQUEST_METHOD", "").upper() + transaction = None if method in self.http_methods_to_capture: transaction = continue_trace( @@ -119,27 +124,43 @@ def __call__(self, environ, start_response): origin=self.span_origin, ) - with ( + 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), ) - if transaction is not None - else nullcontext() - ): - try: - response = self.app( - environ, - partial( - _sentry_start_response, start_response, transaction - ), - ) - except BaseException: - reraise(*_capture_exception()) + timer.start() + + try: + response = self.app( + environ, + partial( + _sentry_start_response, + start_response, + transaction, + ), + ) + except BaseException: + exc_info = sys.exc_info() + _capture_exception(exc_info) + finish_running_transaction(current_scope, exc_info, timer) + reraise(*exc_info) + finally: _wsgi_middleware_applied.set(False) - return _ScopedResponse(scope, response) + return _ScopedResponse( + response=response, + current_scope=current_scope, + isolation_scope=scope, + timer=timer, + ) def _sentry_start_response( # type: ignore @@ -201,13 +222,13 @@ def get_client_ip(environ): return environ.get("REMOTE_ADDR") -def _capture_exception(): - # type: () -> ExcInfo +def _capture_exception(exc_info=None): + # type: (Optional[ExcInfo]) -> ExcInfo """ Captures the current exception and sends it to Sentry. Returns the ExcInfo tuple to it can be reraised afterwards. """ - exc_info = sys.exc_info() + exc_info = exc_info or sys.exc_info() e = exc_info[1] # SystemExit(0) is the only uncaught exception that is expected behavior @@ -225,7 +246,7 @@ def _capture_exception(): class _ScopedResponse: """ - Users a separate scope for each response chunk. + Use separate scopes for each response chunk. This will make WSGI apps more tolerant against: - WSGI servers streaming responses from a different thread/from @@ -234,37 +255,54 @@ class _ScopedResponse: - WSGI servers streaming responses interleaved from the same thread """ - __slots__ = ("_response", "_scope") + __slots__ = ("_response", "_current_scope", "_isolation_scope", "_timer") - def __init__(self, scope, response): - # type: (sentry_sdk.scope.Scope, Iterator[bytes]) -> None - self._scope = 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] iterator = iter(self._response) - while True: - with use_isolation_scope(self._scope): - try: - chunk = next(iterator) - except StopIteration: - break - except BaseException: - reraise(*_capture_exception()) + try: + while True: + with use_isolation_scope(self._isolation_scope): + with use_scope(self._current_scope): + try: + chunk = next(iterator) + except StopIteration: + break + except BaseException: + reraise(*_capture_exception()) + + yield chunk - yield chunk + finally: + with use_isolation_scope(self._isolation_scope): + with use_scope(self._current_scope): + finish_running_transaction(timer=self._timer) def close(self): # type: () -> None - with use_isolation_scope(self._scope): - try: - self._response.close() # type: ignore - except AttributeError: - pass - except BaseException: - reraise(*_capture_exception()) + with use_isolation_scope(self._isolation_scope): + with use_scope(self._current_scope): + try: + finish_running_transaction(timer=self._timer) + self._response.close() # type: ignore + except AttributeError: + pass + except BaseException: + reraise(*_capture_exception()) def _make_wsgi_event_processor(environ, use_x_forwarded_for): @@ -308,3 +346,18 @@ 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_utils.py b/sentry_sdk/tracing_utils.py index 0459563776..969e0812e4 100644 --- a/sentry_sdk/tracing_utils.py +++ b/sentry_sdk/tracing_utils.py @@ -36,6 +36,9 @@ from types import FrameType + from sentry_sdk._types import ExcInfo + from threading import Timer + SENTRY_TRACE_REGEX = re.compile( "^[ \t]*" # whitespace @@ -739,3 +742,18 @@ def get_current_span(scope=None): if TYPE_CHECKING: 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() + + current_scope = scope or sentry_sdk.get_current_scope() + if current_scope.transaction is not None and hasattr( + current_scope.transaction, "_context_manager_state" + ): + if exc_info is not None: + current_scope.transaction.__exit__(*exc_info) + else: + current_scope.transaction.__exit__(None, None, None) diff --git a/tests/integrations/django/test_basic.py b/tests/integrations/django/test_basic.py index 0e3f700105..243431fdf5 100644 --- a/tests/integrations/django/test_basic.py +++ b/tests/integrations/django/test_basic.py @@ -51,7 +51,7 @@ def test_view_exceptions(sentry_init, client, capture_exceptions, capture_events sentry_init(integrations=[DjangoIntegration()], send_default_pii=True) exceptions = capture_exceptions() events = capture_events() - client.get(reverse("view_exc")) + unpack_werkzeug_response(client.get(reverse("view_exc"))) (error,) = exceptions assert isinstance(error, ZeroDivisionError) @@ -72,7 +72,9 @@ def test_ensures_x_forwarded_header_is_honored_in_sdk_when_enabled_in_django( sentry_init(integrations=[DjangoIntegration()], send_default_pii=True) exceptions = capture_exceptions() events = capture_events() - client.get(reverse("view_exc"), headers={"X_FORWARDED_HOST": "example.com"}) + unpack_werkzeug_response( + client.get(reverse("view_exc"), headers={"X_FORWARDED_HOST": "example.com"}) + ) (error,) = exceptions assert isinstance(error, ZeroDivisionError) @@ -91,7 +93,9 @@ def test_ensures_x_forwarded_header_is_not_honored_when_unenabled_in_django( sentry_init(integrations=[DjangoIntegration()], send_default_pii=True) exceptions = capture_exceptions() events = capture_events() - client.get(reverse("view_exc"), headers={"X_FORWARDED_HOST": "example.com"}) + unpack_werkzeug_response( + client.get(reverse("view_exc"), headers={"X_FORWARDED_HOST": "example.com"}) + ) (error,) = exceptions assert isinstance(error, ZeroDivisionError) @@ -103,7 +107,7 @@ def test_ensures_x_forwarded_header_is_not_honored_when_unenabled_in_django( def test_middleware_exceptions(sentry_init, client, capture_exceptions): sentry_init(integrations=[DjangoIntegration()], send_default_pii=True) exceptions = capture_exceptions() - client.get(reverse("middleware_exc")) + unpack_werkzeug_response(client.get(reverse("middleware_exc"))) (error,) = exceptions assert isinstance(error, ZeroDivisionError) @@ -157,7 +161,7 @@ def test_has_trace_if_performance_enabled(sentry_init, client, capture_events): traces_sample_rate=1.0, ) events = capture_events() - client.head(reverse("view_exc_with_msg")) + unpack_werkzeug_response(client.head(reverse("view_exc_with_msg"))) (msg_event, error_event, transaction_event) = events @@ -213,8 +217,10 @@ def test_trace_from_headers_if_performance_enabled(sentry_init, client, capture_ trace_id = "582b43a4192642f0b136d5159a501701" sentry_trace_header = "{}-{}-{}".format(trace_id, "6e8f22c393e68f19", 1) - client.head( - reverse("view_exc_with_msg"), headers={"sentry-trace": sentry_trace_header} + unpack_werkzeug_response( + client.head( + reverse("view_exc_with_msg"), headers={"sentry-trace": sentry_trace_header} + ) ) (msg_event, error_event, transaction_event) = events @@ -928,7 +934,7 @@ def test_render_spans(sentry_init, client, capture_events, render_span_tree): for url, expected_line in views_tests: events = capture_events() - client.get(url) + unpack_werkzeug_response(client.get(url)) transaction = events[0] assert expected_line in render_span_tree(transaction) @@ -967,7 +973,7 @@ def test_middleware_spans(sentry_init, client, capture_events, render_span_tree) ) events = capture_events() - client.get(reverse("message")) + unpack_werkzeug_response(client.get(reverse("message"))) message, transaction = events @@ -984,7 +990,7 @@ def test_middleware_spans_disabled(sentry_init, client, capture_events): ) events = capture_events() - client.get(reverse("message")) + unpack_werkzeug_response(client.get(reverse("message"))) message, transaction = events @@ -1008,7 +1014,7 @@ def test_signals_spans(sentry_init, client, capture_events, render_span_tree): ) events = capture_events() - client.get(reverse("message")) + unpack_werkzeug_response(client.get(reverse("message"))) message, transaction = events @@ -1031,7 +1037,7 @@ def test_signals_spans_disabled(sentry_init, client, capture_events): ) events = capture_events() - client.get(reverse("message")) + unpack_werkzeug_response(client.get(reverse("message"))) message, transaction = events @@ -1061,7 +1067,7 @@ def test_signals_spans_filtering(sentry_init, client, capture_events, render_spa ) events = capture_events() - client.get(reverse("send_myapp_custom_signal")) + unpack_werkzeug_response(client.get(reverse("send_myapp_custom_signal"))) (transaction,) = events @@ -1186,7 +1192,7 @@ def test_span_origin(sentry_init, client, capture_events): ) events = capture_events() - client.get(reverse("view_with_signal")) + unpack_werkzeug_response(client.get(reverse("view_with_signal"))) (transaction,) = events @@ -1211,9 +1217,9 @@ def test_transaction_http_method_default(sentry_init, client, capture_events): ) events = capture_events() - client.get("/nomessage") - client.options("/nomessage") - client.head("/nomessage") + unpack_werkzeug_response(client.get("/nomessage")) + unpack_werkzeug_response(client.options("/nomessage")) + unpack_werkzeug_response(client.head("/nomessage")) (event,) = events @@ -1235,9 +1241,9 @@ def test_transaction_http_method_custom(sentry_init, client, capture_events): ) events = capture_events() - client.get("/nomessage") - client.options("/nomessage") - client.head("/nomessage") + unpack_werkzeug_response(client.get("/nomessage")) + unpack_werkzeug_response(client.options("/nomessage")) + unpack_werkzeug_response(client.head("/nomessage")) assert len(events) == 2 diff --git a/tests/integrations/flask/test_flask.py b/tests/integrations/flask/test_flask.py index 6febb12b8b..e2c37aa5f7 100644 --- a/tests/integrations/flask/test_flask.py +++ b/tests/integrations/flask/test_flask.py @@ -394,6 +394,8 @@ def index(): client = app.test_client() response = client.post("/", data=data) assert response.status_code == 200 + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() event, transaction_event = events @@ -746,6 +748,8 @@ def hi_tx(): with app.test_client() as client: response = client.get("/message_tx") assert response.status_code == 200 + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() message_event, transaction_event = events @@ -938,7 +942,9 @@ def test_response_status_code_not_found_in_transaction_context( envelopes = capture_envelopes() client = app.test_client() - client.get("/not-existing-route") + response = client.get("/not-existing-route") + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() sentry_sdk.get_client().flush() @@ -983,14 +989,21 @@ def test_transaction_http_method_default( events = capture_events() client = app.test_client() + response = client.get("/nomessage") assert response.status_code == 200 + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() response = client.options("/nomessage") assert response.status_code == 200 + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() response = client.head("/nomessage") assert response.status_code == 200 + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() (event,) = events @@ -1020,14 +1033,21 @@ def test_transaction_http_method_custom( events = capture_events() client = app.test_client() + response = client.get("/nomessage") assert response.status_code == 200 + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() response = client.options("/nomessage") assert response.status_code == 200 + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() response = client.head("/nomessage") assert response.status_code == 200 + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + response.close() assert len(events) == 2 diff --git a/tests/integrations/strawberry/test_strawberry.py b/tests/integrations/strawberry/test_strawberry.py index 7b40b238d2..0aab78f443 100644 --- a/tests/integrations/strawberry/test_strawberry.py +++ b/tests/integrations/strawberry/test_strawberry.py @@ -198,7 +198,10 @@ def test_capture_request_if_available_and_send_pii_is_on( client = client_factory(schema) query = "query ErrorQuery { error }" - client.post("/graphql", json={"query": query, "operationName": "ErrorQuery"}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post( + "/graphql", json={"query": query, "operationName": "ErrorQuery"} + ).close() assert len(events) == 1 @@ -253,7 +256,10 @@ def test_do_not_capture_request_if_send_pii_is_off( client = client_factory(schema) query = "query ErrorQuery { error }" - client.post("/graphql", json={"query": query, "operationName": "ErrorQuery"}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post( + "/graphql", json={"query": query, "operationName": "ErrorQuery"} + ).close() assert len(events) == 1 @@ -293,7 +299,8 @@ def test_breadcrumb_no_operation_name( client = client_factory(schema) query = "{ error }" - client.post("/graphql", json={"query": query}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post("/graphql", json={"query": query}).close() assert len(events) == 1 @@ -332,7 +339,10 @@ def test_capture_transaction_on_error( client = client_factory(schema) query = "query ErrorQuery { error }" - client.post("/graphql", json={"query": query, "operationName": "ErrorQuery"}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post( + "/graphql", json={"query": query, "operationName": "ErrorQuery"} + ).close() assert len(events) == 2 (_, transaction_event) = events @@ -409,7 +419,10 @@ def test_capture_transaction_on_success( client = client_factory(schema) query = "query GreetingQuery { hello }" - client.post("/graphql", json={"query": query, "operationName": "GreetingQuery"}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post( + "/graphql", json={"query": query, "operationName": "GreetingQuery"} + ).close() assert len(events) == 1 (transaction_event,) = events @@ -486,7 +499,8 @@ def test_transaction_no_operation_name( client = client_factory(schema) query = "{ hello }" - client.post("/graphql", json={"query": query}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post("/graphql", json={"query": query}).close() assert len(events) == 1 (transaction_event,) = events @@ -566,7 +580,8 @@ def test_transaction_mutation( client = client_factory(schema) query = 'mutation Change { change(attribute: "something") }' - client.post("/graphql", json={"query": query}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post("/graphql", json={"query": query}).close() assert len(events) == 1 (transaction_event,) = events @@ -641,7 +656,8 @@ def test_handle_none_query_gracefully( client_factory = request.getfixturevalue(client_factory) client = client_factory(schema) - client.post("/graphql", json={}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post("/graphql", json={}).close() assert len(events) == 0, "expected no events to be sent to Sentry" @@ -673,7 +689,8 @@ def test_span_origin( client = client_factory(schema) query = 'mutation Change { change(attribute: "something") }' - client.post("/graphql", json={"query": query}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post("/graphql", json={"query": query}).close() (event,) = events @@ -715,7 +732,10 @@ def test_span_origin2( client = client_factory(schema) query = "query GreetingQuery { hello }" - client.post("/graphql", json={"query": query, "operationName": "GreetingQuery"}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post( + "/graphql", json={"query": query, "operationName": "GreetingQuery"} + ).close() (event,) = events @@ -757,7 +777,8 @@ def test_span_origin3( client = client_factory(schema) query = "subscription { messageAdded { content } }" - client.post("/graphql", json={"query": query}) + # Close the response to ensure the WSGI cycle is complete and the transaction is finished + client.post("/graphql", json={"query": query}).close() (event,) = events diff --git a/tests/integrations/wsgi/test_wsgi.py b/tests/integrations/wsgi/test_wsgi.py index 656fc1757f..a4f5ca0623 100644 --- a/tests/integrations/wsgi/test_wsgi.py +++ b/tests/integrations/wsgi/test_wsgi.py @@ -1,7 +1,9 @@ +import time from collections import Counter from unittest import mock import pytest +from sentry_sdk.utils import datetime_from_isoformat from werkzeug.test import Client import sentry_sdk @@ -495,3 +497,80 @@ def dogpark(environ, start_response): (event,) = events assert event["contexts"]["trace"]["origin"] == "auto.dogpark.deluxe" + + +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 + + with mock.patch.object( + sentry_sdk.integrations.wsgi, + "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" + + 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 + + transaction_duration = ( + 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()