Skip Queryset serialization for any querysets embedded in the stack frame f_locals.

[jvineet]

Problem Statement

Sentry tried to serialize a queryset (as part of stack frame locals) which resulted in multiple expensive queries to the db over and over while serializing stack frames that almost knocked over one of our production databases. Here is what happened:

Django ModelAdmin adds a QuerySet to the django log table as part of the request context (or template context, definitely one of the two) in the _changeform_view method

https://github.com/django/django/blob/5.1.6/django/contrib/admin/options.py#L1928
https://github.com/django/django/blob/5.1.6/django/contrib/admin/sites.py#L341

This context then ends up in sentry as part of the frame locals for each frame that captured this context. Sentry then ends up calling this queryset for every frame serialization step, which makes a new call to the admin log table with multiple joins (one inner and one outer).

SELECT django_admin_log.id, django_admin_log.action_time, django_admin_log.user_id,
  django_admin_log.content_type_id, django_admin_log.object_id, django_admin_log.object_repr,
  django_admin_log.action_flag, django_admin_log.change_message, auth_user.id, auth_user.password,
  auth_user.last_login, auth_user.is_superuser, auth_user.username, auth_user.first_name,
  auth_user.last_name, auth_user.email, auth_user.is_staff, auth_user.is_active, auth_user.date_joined,
   django_content_type.id, django_content_type.app_label, django_content_type.model
FROM django_admin_log
INNER JOIN auth_user ON (django_admin_log.user_id = auth_user.id)
LEFT OUTER JOIN django_content_type ON (django_admin_log.content_type_id = django_content_type.id)
ORDER BY django_admin_log.action_time DESC
LIMIT 21

The stack traces are ginormous, over 70 frames deep, so it ends up making ~70+ of these expensive queries to the db, adding a lot of load to it. And then 2x this value, since we had reported recently to the sentry team that sentry logging.exception serialization often happens twice, so we were probably making ~140 expensive db calls!! This is what almost knocked over our database.

https://github.com/getsentry/sentry-python/blob/2.33.1/sentry_sdk/utils.py#L615-L617

I should mention that this queryset is not at the top level in the context dict, but buried at least 3 levels down (frame.f_locals["context"].dicts[3]["log_entries"]). These db calls happen because QuerySets get evaluated whenever repr(some_queryset) is called on them as part of stack frame serialization. We also couldn't patch safe_repr in sentry as that calls repr() and then all dict objects are recursively called with repr() and I could not think of a way to have safe_repr be called recursively on all dict elements, without something invasive like patching builtin.repr() or QuerySet.__repr__.

https://docs.djangoproject.com/en/5.2/ref/models/querysets/#when-querysets-are-evaluated

For reference here is sentry trace when this happened. Notice how it took us over 6 mins, just to serialization all of the stack frames (twice) because of all of the expensive db calls.

here are some of the db spans from this trace for the 140+ db calls where each one took ~2.5s.

Solution Brainstorm

For the time being, to get around this particular issue, we ended up creating a simple sentry integration, which patches the sentry serializer.serializefunction and adds a wrapper that strips out the the location which holds this particularQuerySetthat DjangoModelAdmin` had added to the context.

class SafeQuerySetIntegration(integrations.Integration):
    identifier = "safe_queryset_integration"

    @staticmethod
    def setup_once() -> None:
        """
        This method is called once by Sentry when the integration is initialized.
        """
        original_serialize = serializer.serialize

        def patched_serialize(event: dict[str, Any], **kwargs: Any) -> dict[str, Any]:
            # strip context dicts, if they are present, since that's where admin adds the
            # django_admin_log table QuerySets.
            if "context" in event and hasattr(event["context"], "dicts"):
                event["context"].dicts = ["<stripped>"]
            return original_serialize(event, **kwargs)

        serializer.serialize = patched_serialize
        logging.info("Sentry Integration: serialize has been patched via SafeQuerySetIntegration.")

While this works for now, what we are hoping for is a global way to tell sentry to skip any QuerySet serializations that it encounters while serializing the stack frames. I understand if there isn't any way to do this since django evaluating QuerySets as part of repr() definitely came as a surprise to us, and wasn't something we were expecting. I'd also be happy to find out if there is already a way to do this that I just couldn't quite figure out.

At one point I had thought about patching safe_repr with a wrapper and traverse through the entire data structure of the value passed over and replace and QuerySet instance with <QuerySet> str before passing the value over to the wrapped safe_repr function. But I am not sure if that is a good idea, because traversing the whole value data requires additional complexity and the data in theory could be deeply nested (maybe not an issue if sentry only serializes 3 or 4 levels of depth).

[linear]

PY-1783 Skip Queryset serialization for any querysets embedded in the stack frame f_locals.

[sentrivana]

Hey @jvineet, thanks for the detailed issue!

I don't know if it's better than your workaround, but __sentry_repr__ is also an option, even though it's not something we necessarily advertize. If you're able to define a __sentry_repr__ function on the QuerySet that returns something static (as opposed to actually evaluating the QuerySet), like for instance here, the serializer should pick that up instead of trying to repr() the QuerySet. Would something like this work for you?

[sentrivana]

Also, unrelated, but would you be able to share how you found out what's actually happening/keeping the DB busy? It might help us in debugging another similar issue.

[sl0thentr0py]

@sentrivana we already have a global repr for QuerySet

sentry-python/sentry_sdk/integrations/django/__init__.py

Lines 244 to 265 in 1b4f8d3

	@add_global_repr_processor
	def _django_queryset_repr(value, hint):
	# type: (Any, Dict[str, Any]) -> Union[NotImplementedType, str]
	try:
	# Django 1.6 can fail to import `QuerySet` when Django settings
	# have not yet been initialized.
	#
	# If we fail to import, return `NotImplemented`. It's at least
	# unlikely that we have a query set in `value` when importing
	# `QuerySet` fails.
	from django.db.models.query import QuerySet
	except Exception:
	return NotImplemented
	if not isinstance(value, QuerySet) or value._result_cache:
	return NotImplemented
	return "<%s from %s at 0x%x>" % (
	value.__class__.__name__,
	value.__module__,
	id(value),
	)

maybe it's not working properly since the variables serialization change?

[sl0thentr0py]

hmm no we even have a test that covers that case

sentry-python/tests/integrations/django/test_basic.py

Lines 290 to 310 in 1b4f8d3

	@pytest.mark.forked
	@pytest_mark_django_db_decorator()
	def test_queryset_repr(sentry_init, capture_events):
	sentry_init(integrations=[DjangoIntegration()])
	events = capture_events()
	User.objects.create_user("john", "lennon@thebeatles.com", "johnpassword")
	try:
	my_queryset = User.objects.all() # noqa
	1 / 0
	except Exception:
	capture_exception()
	(event,) = events
	(exception,) = event["exception"]["values"]
	assert exception["type"] == "ZeroDivisionError"
	(frame,) = exception["stacktrace"]["frames"]
	assert frame["vars"]["my_queryset"].startswith(
	"<QuerySet from django.db.models.query at"
	)