diff --git a/sentry_sdk/_compat.py b/sentry_sdk/_compat.py index b88c648b01..8c1bf9711f 100644 --- a/sentry_sdk/_compat.py +++ b/sentry_sdk/_compat.py @@ -1,6 +1,6 @@ import sys import contextlib -from datetime import datetime +from datetime import datetime, timedelta from functools import wraps from sentry_sdk._types import TYPE_CHECKING @@ -34,11 +34,19 @@ binary_sequence_types = (bytearray, memoryview) def datetime_utcnow(): + # type: () -> datetime return datetime.utcnow() def utc_from_timestamp(timestamp): + # type: (float) -> datetime return datetime.utcfromtimestamp(timestamp) + def duration_in_milliseconds(delta): + # type: (timedelta) -> float + seconds = delta.days * 24 * 60 * 60 + delta.seconds + milliseconds = seconds * 1000 + float(delta.microseconds) / 1000 + return milliseconds + def implements_str(cls): # type: (T) -> T cls.__unicode__ = cls.__str__ @@ -103,6 +111,10 @@ def utc_from_timestamp(timestamp): # type: (float) -> datetime return datetime.fromtimestamp(timestamp, timezone.utc) + def duration_in_milliseconds(delta): + # type: (timedelta) -> float + return delta / timedelta(milliseconds=1) + def implements_str(x): # type: (T) -> T return x diff --git a/sentry_sdk/integrations/gcp.py b/sentry_sdk/integrations/gcp.py index 5f771c95c6..819c7ac93d 100644 --- a/sentry_sdk/integrations/gcp.py +++ b/sentry_sdk/integrations/gcp.py @@ -7,7 +7,7 @@ from sentry_sdk.consts import OP from sentry_sdk.hub import Hub, _should_send_default_pii from sentry_sdk.tracing import TRANSACTION_SOURCE_COMPONENT -from sentry_sdk._compat import datetime_utcnow, reraise +from sentry_sdk._compat import datetime_utcnow, duration_in_milliseconds, reraise from sentry_sdk.utils import ( AnnotatedValue, capture_internal_exceptions, @@ -158,7 +158,7 @@ def event_processor(event, hint): final_time = datetime_utcnow() time_diff = final_time - initial_time - execution_duration_in_millis = time_diff.microseconds / MILLIS_TO_SECONDS + execution_duration_in_millis = duration_in_milliseconds(time_diff) extra = event.setdefault("extra", {}) extra["google cloud functions"] = { diff --git a/sentry_sdk/tracing_utils.py b/sentry_sdk/tracing_utils.py index 037f3c4133..f6d8acabb2 100644 --- a/sentry_sdk/tracing_utils.py +++ b/sentry_sdk/tracing_utils.py @@ -14,7 +14,7 @@ _is_external_source, _module_in_list, ) -from sentry_sdk._compat import PY2, iteritems +from sentry_sdk._compat import PY2, duration_in_milliseconds, iteritems from sentry_sdk._types import TYPE_CHECKING if PY2: @@ -186,7 +186,7 @@ def add_query_source(hub, span): duration = span.timestamp - span.start_timestamp threshold = client.options.get("db_query_source_threshold_ms", 0) - slow_query = duration.microseconds > threshold * 1000 + slow_query = duration_in_milliseconds(duration) > threshold if not slow_query: return diff --git a/tests/integrations/asyncpg/test_asyncpg.py b/tests/integrations/asyncpg/test_asyncpg.py index 2a31c59dee..b9d96e1718 100644 --- a/tests/integrations/asyncpg/test_asyncpg.py +++ b/tests/integrations/asyncpg/test_asyncpg.py @@ -31,6 +31,13 @@ from sentry_sdk import capture_message, start_transaction from sentry_sdk.integrations.asyncpg import AsyncPGIntegration from sentry_sdk.consts import SPANDATA +from sentry_sdk.tracing_utils import record_sql_queries +from sentry_sdk._compat import contextmanager + +try: + from unittest import mock +except ImportError: + import mock PG_CONNECTION_URI = "postgresql://{}:{}@{}/{}".format( @@ -548,3 +555,110 @@ async def test_query_source(sentry_init, capture_events): assert is_relative_path assert data.get(SPANDATA.CODE_FUNCTION) == "test_query_source" + + +@pytest.mark.asyncio +async def test_no_query_source_if_duration_too_short(sentry_init, capture_events): + sentry_init( + integrations=[AsyncPGIntegration()], + enable_tracing=True, + enable_db_query_source=True, + db_query_source_threshold_ms=100, + ) + + events = capture_events() + + with start_transaction(name="test_transaction", sampled=True): + conn: Connection = await connect(PG_CONNECTION_URI) + + @contextmanager + def fake_record_sql_queries(*args, **kwargs): + with record_sql_queries(*args, **kwargs) as span: + pass + span.start_timestamp = datetime.datetime(2024, 1, 1, microsecond=0) + span.timestamp = datetime.datetime(2024, 1, 1, microsecond=99999) + yield span + + with mock.patch( + "sentry_sdk.integrations.asyncpg.record_sql_queries", + fake_record_sql_queries, + ): + await conn.execute( + "INSERT INTO users(name, password, dob) VALUES ('Alice', 'secret', '1990-12-25')", + ) + + await conn.close() + + (event,) = events + + span = event["spans"][-1] + assert span["description"].startswith("INSERT INTO") + + data = span.get("data", {}) + + assert SPANDATA.CODE_LINENO not in data + assert SPANDATA.CODE_NAMESPACE not in data + assert SPANDATA.CODE_FILEPATH not in data + assert SPANDATA.CODE_FUNCTION not in data + + +@pytest.mark.asyncio +async def test_query_source_if_duration_over_threshold(sentry_init, capture_events): + sentry_init( + integrations=[AsyncPGIntegration()], + enable_tracing=True, + enable_db_query_source=True, + db_query_source_threshold_ms=100, + ) + + events = capture_events() + + with start_transaction(name="test_transaction", sampled=True): + conn: Connection = await connect(PG_CONNECTION_URI) + + @contextmanager + def fake_record_sql_queries(*args, **kwargs): + with record_sql_queries(*args, **kwargs) as span: + pass + span.start_timestamp = datetime.datetime(2024, 1, 1, microsecond=0) + span.timestamp = datetime.datetime(2024, 1, 1, microsecond=100001) + yield span + + with mock.patch( + "sentry_sdk.integrations.asyncpg.record_sql_queries", + fake_record_sql_queries, + ): + await conn.execute( + "INSERT INTO users(name, password, dob) VALUES ('Alice', 'secret', '1990-12-25')", + ) + + await conn.close() + + (event,) = events + + span = event["spans"][-1] + assert span["description"].startswith("INSERT INTO") + + data = span.get("data", {}) + + assert SPANDATA.CODE_LINENO in data + assert SPANDATA.CODE_NAMESPACE in data + assert SPANDATA.CODE_FILEPATH in data + assert SPANDATA.CODE_FUNCTION in data + + assert type(data.get(SPANDATA.CODE_LINENO)) == int + assert data.get(SPANDATA.CODE_LINENO) > 0 + assert ( + data.get(SPANDATA.CODE_NAMESPACE) == "tests.integrations.asyncpg.test_asyncpg" + ) + assert data.get(SPANDATA.CODE_FILEPATH).endswith( + "tests/integrations/asyncpg/test_asyncpg.py" + ) + + is_relative_path = data.get(SPANDATA.CODE_FILEPATH)[0] != os.sep + assert is_relative_path + + assert ( + data.get(SPANDATA.CODE_FUNCTION) + == "test_query_source_if_duration_over_threshold" + ) diff --git a/tests/integrations/django/test_db_query_data.py b/tests/integrations/django/test_db_query_data.py index f1a82a6996..d773a3486a 100644 --- a/tests/integrations/django/test_db_query_data.py +++ b/tests/integrations/django/test_db_query_data.py @@ -2,6 +2,7 @@ import os import pytest +from datetime import datetime from django import VERSION as DJANGO_VERSION from django.db import connections @@ -15,11 +16,17 @@ from sentry_sdk.consts import SPANDATA from sentry_sdk.integrations.django import DjangoIntegration +from sentry_sdk.tracing_utils import record_sql_queries from tests.conftest import unpack_werkzeug_response from tests.integrations.django.utils import pytest_mark_django_db_decorator from tests.integrations.django.myapp.wsgi import application +try: + from unittest import mock +except ImportError: + import mock + @pytest.fixture def client(): @@ -228,3 +235,134 @@ def test_query_source_with_in_app_include(sentry_init, client, capture_events): break else: raise AssertionError("No db span found") + + +@pytest.mark.forked +@pytest_mark_django_db_decorator(transaction=True) +def test_no_query_source_if_duration_too_short(sentry_init, client, capture_events): + sentry_init( + integrations=[DjangoIntegration()], + send_default_pii=True, + traces_sample_rate=1.0, + enable_db_query_source=True, + db_query_source_threshold_ms=100, + ) + + if "postgres" not in connections: + pytest.skip("postgres tests disabled") + + # trigger Django to open a new connection by marking the existing one as None. + connections["postgres"].connection = None + + events = capture_events() + + class fake_record_sql_queries: # noqa: N801 + def __init__(self, *args, **kwargs): + with record_sql_queries(*args, **kwargs) as span: + self.span = span + + self.span.start_timestamp = datetime(2024, 1, 1, microsecond=0) + self.span.timestamp = datetime(2024, 1, 1, microsecond=99999) + + def __enter__(self): + return self.span + + def __exit__(self, type, value, traceback): + pass + + with mock.patch( + "sentry_sdk.integrations.django.record_sql_queries", + fake_record_sql_queries, + ): + _, status, _ = unpack_werkzeug_response( + client.get(reverse("postgres_select_orm")) + ) + + assert status == "200 OK" + + (event,) = events + for span in event["spans"]: + if span.get("op") == "db" and "auth_user" in span.get("description"): + data = span.get("data", {}) + + assert SPANDATA.CODE_LINENO not in data + assert SPANDATA.CODE_NAMESPACE not in data + assert SPANDATA.CODE_FILEPATH not in data + assert SPANDATA.CODE_FUNCTION not in data + + break + else: + raise AssertionError("No db span found") + + +@pytest.mark.forked +@pytest_mark_django_db_decorator(transaction=True) +def test_query_source_if_duration_over_threshold(sentry_init, client, capture_events): + sentry_init( + integrations=[DjangoIntegration()], + send_default_pii=True, + traces_sample_rate=1.0, + enable_db_query_source=True, + db_query_source_threshold_ms=100, + ) + + if "postgres" not in connections: + pytest.skip("postgres tests disabled") + + # trigger Django to open a new connection by marking the existing one as None. + connections["postgres"].connection = None + + events = capture_events() + + class fake_record_sql_queries: # noqa: N801 + def __init__(self, *args, **kwargs): + with record_sql_queries(*args, **kwargs) as span: + self.span = span + + self.span.start_timestamp = datetime(2024, 1, 1, microsecond=0) + self.span.timestamp = datetime(2024, 1, 1, microsecond=101000) + + def __enter__(self): + return self.span + + def __exit__(self, type, value, traceback): + pass + + with mock.patch( + "sentry_sdk.integrations.django.record_sql_queries", + fake_record_sql_queries, + ): + _, status, _ = unpack_werkzeug_response( + client.get(reverse("postgres_select_orm")) + ) + + assert status == "200 OK" + + (event,) = events + for span in event["spans"]: + if span.get("op") == "db" and "auth_user" in span.get("description"): + data = span.get("data", {}) + + assert SPANDATA.CODE_LINENO in data + assert SPANDATA.CODE_NAMESPACE in data + assert SPANDATA.CODE_FILEPATH in data + assert SPANDATA.CODE_FUNCTION in data + + assert type(data.get(SPANDATA.CODE_LINENO)) == int + assert data.get(SPANDATA.CODE_LINENO) > 0 + + assert ( + data.get(SPANDATA.CODE_NAMESPACE) + == "tests.integrations.django.myapp.views" + ) + assert data.get(SPANDATA.CODE_FILEPATH).endswith( + "tests/integrations/django/myapp/views.py" + ) + + is_relative_path = data.get(SPANDATA.CODE_FILEPATH)[0] != os.sep + assert is_relative_path + + assert data.get(SPANDATA.CODE_FUNCTION) == "postgres_select_orm" + break + else: + raise AssertionError("No db span found") diff --git a/tests/integrations/sqlalchemy/test_sqlalchemy.py b/tests/integrations/sqlalchemy/test_sqlalchemy.py index c0dd279c15..292e4026b7 100644 --- a/tests/integrations/sqlalchemy/test_sqlalchemy.py +++ b/tests/integrations/sqlalchemy/test_sqlalchemy.py @@ -1,6 +1,7 @@ import os import pytest import sys +from datetime import datetime from sqlalchemy import Column, ForeignKey, Integer, String, create_engine from sqlalchemy.exc import IntegrityError @@ -12,8 +13,14 @@ from sentry_sdk.consts import DEFAULT_MAX_VALUE_LENGTH, SPANDATA from sentry_sdk.integrations.sqlalchemy import SqlalchemyIntegration from sentry_sdk.serializer import MAX_EVENT_BYTES +from sentry_sdk.tracing_utils import record_sql_queries from sentry_sdk.utils import json_dumps +try: + from unittest import mock +except ImportError: + import mock + def test_orm_queries(sentry_init, capture_events): sentry_init( @@ -336,3 +343,148 @@ class Person(Base): break else: raise AssertionError("No db span found") + + +def test_no_query_source_if_duration_too_short(sentry_init, capture_events): + sentry_init( + integrations=[SqlalchemyIntegration()], + enable_tracing=True, + enable_db_query_source=True, + db_query_source_threshold_ms=100, + ) + events = capture_events() + + with start_transaction(name="test_transaction", sampled=True): + Base = declarative_base() # noqa: N806 + + class Person(Base): + __tablename__ = "person" + id = Column(Integer, primary_key=True) + name = Column(String(250), nullable=False) + + engine = create_engine("sqlite:///:memory:") + Base.metadata.create_all(engine) + + Session = sessionmaker(bind=engine) # noqa: N806 + session = Session() + + bob = Person(name="Bob") + session.add(bob) + + class fake_record_sql_queries: # noqa: N801 + def __init__(self, *args, **kwargs): + with record_sql_queries(*args, **kwargs) as span: + self.span = span + + self.span.start_timestamp = datetime(2024, 1, 1, microsecond=0) + self.span.timestamp = datetime(2024, 1, 1, microsecond=99999) + + def __enter__(self): + return self.span + + def __exit__(self, type, value, traceback): + pass + + with mock.patch( + "sentry_sdk.integrations.sqlalchemy.record_sql_queries", + fake_record_sql_queries, + ): + assert session.query(Person).first() == bob + + (event,) = events + + for span in event["spans"]: + if span.get("op") == "db" and span.get("description").startswith( + "SELECT person" + ): + data = span.get("data", {}) + + assert SPANDATA.CODE_LINENO not in data + assert SPANDATA.CODE_NAMESPACE not in data + assert SPANDATA.CODE_FILEPATH not in data + assert SPANDATA.CODE_FUNCTION not in data + + break + else: + raise AssertionError("No db span found") + + +def test_query_source_if_duration_over_threshold(sentry_init, capture_events): + sentry_init( + integrations=[SqlalchemyIntegration()], + enable_tracing=True, + enable_db_query_source=True, + db_query_source_threshold_ms=100, + ) + events = capture_events() + + with start_transaction(name="test_transaction", sampled=True): + Base = declarative_base() # noqa: N806 + + class Person(Base): + __tablename__ = "person" + id = Column(Integer, primary_key=True) + name = Column(String(250), nullable=False) + + engine = create_engine("sqlite:///:memory:") + Base.metadata.create_all(engine) + + Session = sessionmaker(bind=engine) # noqa: N806 + session = Session() + + bob = Person(name="Bob") + session.add(bob) + + class fake_record_sql_queries: # noqa: N801 + def __init__(self, *args, **kwargs): + with record_sql_queries(*args, **kwargs) as span: + self.span = span + + self.span.start_timestamp = datetime(2024, 1, 1, microsecond=0) + self.span.timestamp = datetime(2024, 1, 1, microsecond=101000) + + def __enter__(self): + return self.span + + def __exit__(self, type, value, traceback): + pass + + with mock.patch( + "sentry_sdk.integrations.sqlalchemy.record_sql_queries", + fake_record_sql_queries, + ): + assert session.query(Person).first() == bob + + (event,) = events + + for span in event["spans"]: + if span.get("op") == "db" and span.get("description").startswith( + "SELECT person" + ): + data = span.get("data", {}) + + assert SPANDATA.CODE_LINENO in data + assert SPANDATA.CODE_NAMESPACE in data + assert SPANDATA.CODE_FILEPATH in data + assert SPANDATA.CODE_FUNCTION in data + + assert type(data.get(SPANDATA.CODE_LINENO)) == int + assert data.get(SPANDATA.CODE_LINENO) > 0 + assert ( + data.get(SPANDATA.CODE_NAMESPACE) + == "tests.integrations.sqlalchemy.test_sqlalchemy" + ) + assert data.get(SPANDATA.CODE_FILEPATH).endswith( + "tests/integrations/sqlalchemy/test_sqlalchemy.py" + ) + + is_relative_path = data.get(SPANDATA.CODE_FILEPATH)[0] != os.sep + assert is_relative_path + + assert ( + data.get(SPANDATA.CODE_FUNCTION) + == "test_query_source_if_duration_over_threshold" + ) + break + else: + raise AssertionError("No db span found") diff --git a/tests/test_utils.py b/tests/test_utils.py index 71657f75c7..147064b541 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -1,7 +1,9 @@ import pytest import re import sys +from datetime import timedelta +from sentry_sdk._compat import duration_in_milliseconds from sentry_sdk.utils import ( Components, Dsn, @@ -592,3 +594,16 @@ def test_default_release_empty_string(): release = get_default_release() assert release is None + + +@pytest.mark.parametrize( + "timedelta,expected_milliseconds", + [ + [timedelta(milliseconds=132), 132.0], + [timedelta(hours=1, milliseconds=132), float(60 * 60 * 1000 + 132)], + [timedelta(days=10), float(10 * 24 * 60 * 60 * 1000)], + [timedelta(microseconds=100), 0.1], + ], +) +def test_duration_in_milliseconds(timedelta, expected_milliseconds): + assert duration_in_milliseconds(timedelta) == expected_milliseconds