Parallel testing fails reporting unit test combining subTest and assertNumQueries

[Jean Bvt]

Updating from django 5.1.8 to 5.2.0, our test suit fails to correctly reports failed test.

python manage.py test app.module.tests --parallel 8
Found 9 test(s).
[...]




Destroying test database for alias 'default'...
Destroying test database for alias 'default'...
Destroying test database for alias 'default'...
Traceback (most recent call last):
  File "/app/manage.py", line 23, in <module>
    main()
  File "/app/manage.py", line 19, in main
    execute_from_command_line(sys.argv)
  File "/app/.venv/lib/python3.12/site-packages/django/core/management/__init__.py", line 442, in execute_from_command_line
    utility.execute()
  File "/app/.venv/lib/python3.12/site-packages/django/core/management/__init__.py", line 436, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/app/.venv/lib/python3.12/site-packages/django/core/management/commands/test.py", line 24, in run_from_argv
    super().run_from_argv(argv)
  File "/app/.venv/lib/python3.12/site-packages/django/core/management/base.py", line 416, in run_from_argv
    self.execute(*args, **cmd_options)
  File "/app/.venv/lib/python3.12/site-packages/django/core/management/base.py", line 460, in execute
    output = self.handle(*args, **options)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.12/site-packages/django/core/management/commands/test.py", line 63, in handle
    failures = test_runner.run_tests(test_labels)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.12/site-packages/django/test/runner.py", line 1099, in run_tests
    result = self.run_suite(suite)
             ^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.12/site-packages/django/test/runner.py", line 1026, in run_suite
    return runner.run(suite)
           ^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/unittest/runner.py", line 240, in run
    test(result)
  File "/usr/local/lib/python3.12/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.12/site-packages/django/test/runner.py", line 553, in run
    subsuite_index, events = test_results.next(timeout=0.1)
                             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/multiprocessing/pool.py", line 873, in next
    raise value
multiprocessing.pool.MaybeEncodingError: Error sending result: '(17, [('startTest', 0), ('addDuration', 0, 0.02817973299897858), ('addSuccess', 0), ('stopTest', 0), ('startTest', 1), ('addDuration', 1, 0.02015996399859432), ('addSuccess', 1), ('stopTest', 1), ('startTest', 2), ('addDuration', 2, 0.024580582001362927), ('addSuccess', 2), ('stopTest', 2), ('startTest', 3), ('addSubTest', 3, <unittest.case._SubTest testMethod=runTest>, (<class 'AssertionError'>, AssertionError('3 != 2 : 3 queries executed, 2 expected\nCaptured queries were:\n1. SELECT "app_tokenapi"."id", "app_tokenapi"."user_id", "app_tokenapi"."key", "app_tokenapi"."name", "app_tokenapi"."scope_level", "app_tokenapi"."created_at", "app_tokenapi"."expired_at", "app_tokenapi"."expire_reason", "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" FROM "app_tokenapi" INNER JOIN "auth_user" ON ("app_tokenapi"."user_id" = "auth_user"."id") WHERE "app_tokenapi"."key" = \'abcdabcd-abcd-abcd-abcd-abcdabcd\' ORDER BY "app_tokenapi"."id" ASC LIMIT 1\n2. SELECT "my_models_entite"."id", "my_models_entite"."deleted", "my_models_entite"."deleted_by_cascade", "my_models_entite"."some_id", "my_models_entite"."parent_id", "my_models_entite"."type_id", "my_models_entite"."code", "my_models_entite"."libelle", "my_models_entite"."libelle_court", "my_models_entite"."url_logo", "my_models_entite"."begin_date", "my_models_entite"."end_date", "my_models_entite"."created_at", "my_models_entite"."modified_at", "my_models_entite"."json", "my_models_entite"."allow_externe_id", "my_models_entitetype"."id", "my_models_entitetype"."name", "my_models_entitetype"."id_rfu_link", "my_models_entitetype"."id_imotep_link", "my_models_entitetype"."created_at", "my_models_entitetype"."modified_at" FROM "my_models_entite" INNER JOIN "my_models_entitetype" ON ("my_models_entite"."type_id" = "my_models_entitetype"."id") WHERE "my_models_entite"."deleted" IS NULL ORDER BY "my_models_entite"."libelle" ASC\n3. SELECT "my_models_entite"."id", "my_models_entite"."deleted", "my_models_entite"."deleted_by_cascade", "my_models_entite"."some_id", "my_models_entite"."parent_id", "my_models_entite"."type_id", "my_models_entite"."code", "my_models_entite"."libelle", "my_models_entite"."libelle_court", "my_models_entite"."url_logo", "my_models_entite"."begin_date", "my_models_entite"."end_date", "my_models_entite"."created_at", "my_models_entite"."modified_at", "my_models_entite"."json", "my_models_entite"."allow_externe_id" FROM "my_models_entite" WHERE ("my_models_entite"."id") IN ((54), (NULL), (59), (62), (56), (55), (58), (57))'), <traceback object at 0x744f93f72e80>)), ('addDuration', 3, 0.032738704001531005), ('stopTest', 3), ('startTest', 4), ('addDuration', 4, 0.01990954599750694), ('addSuccess', 4), ('stopTest', 4), ('startTest', 5), ('addDuration', 5, 0.10901878799995757), ('addSuccess', 5), ('stopTest', 5), ('startTest', 6), ('addDuration', 6, 0.01989884100112249), ('addSuccess', 6), ('stopTest', 6)])'. Reason: 'AttributeError("Can't get local object 'convert_exception_to_response.<locals>.inner'")'
6998993075), ('addSuccess', 6), ('stopTest', 6)])'. Reason: 'AttributeError("Can't get local object 'convert_exception_to_response.<locals>.inner'")'

(I've renamed some name in this SQL queries for privacy reason)
# the culprit test

    def test_queryset_performances(self):
        EntiteFactory.create()
        with self.subTest("sub test"):
            with self.assertNumQueries(2):
                response = self.client.get(self.url)

# Reproductibility
This errors does not happen if

• We call only this test or only its TestCase (9 tests)
• self.client.get(self.url) is not called, assertNumQueries still raise AssertionError but reporting works fine.
• replacing self.client.get(...) with a simpler QuerySet call still raise AssertionError but reporting works fine.
• we remove self.subTest(...)

The problem does not appear in django 5.1.8 because the test succeeded in 5.1.8, it seems that 5.2 unexpectedly raised the number of query from 2 to 3 (notice the third query look redundant with the second query) so the core issue with reporting may be older than 5.2.

[Sarah Boyce]

I cannot reproduce, but I think you would need to share your view here.
Does the view raise an error on it's own?

I tried:

tests/test_utils/tests.py

@@ -237 +237 @@
 
         self.assertNumQueries(2, test_func)
 
+    def test_assert_num_queries_with_client_and_subtest(self):
+        person = Person.objects.create(name="test")
+        with self.subTest("sub test"):
+            with self.assertNumQueries(2):
+                self.client.get("/test_utils/get_person/%s/" % person.pk)
+
 
 class AssertNumQueriesUponConnectionTests(TransactionTestCase):

And running ./runtests.py test_utils --parallel 2 but this failed in an expected manner.

[Jean Bvt]

Replying to Sarah Boyce:

I cannot reproduce, but I think you would need to share your view here.
Does the view raise an error on it's own?

I tried:

tests/test_utils/tests.py

@@ -237 +237 @@
 
         self.assertNumQueries(2, test_func)
 
+    def test_assert_num_queries_with_client_and_subtest(self):
+        person = Person.objects.create(name="test")
+        with self.subTest("sub test"):
+            with self.assertNumQueries(2):
+                self.client.get("/test_utils/get_person/%s/" % person.pk)
+
 
 class AssertNumQueriesUponConnectionTests(TransactionTestCase):

And running ./runtests.py test_utils --parallel 2 but this failed in an expected manner.

The view does not raise an exception, the raised exception contains a message related to AssertNumQueries:

(<class 'AssertionError'>, AssertionError('3 != 2 : 3 queries executed, 2 expected\nCaptured queries were:\n1. SELECT "app_tokenapi"."id", "app_tokenapi"."user_id", "app_tokenapi"."key", "app_tokenapi"."name", "app_tokenapi"."scope_level", "app_tokenapi"."created_at", "app_tokenapi"."expired_at", "app_tokenapi"."expire [...]

making me believe its the reporting that failed.

Anyway, here is my view (and my serializer since I am using DRF)

@extend_schema(tags=["entite", "v2"])
class EntitesView(ListAPIView):
    permission_classes = [AllowAny]
    queryset = Entite.objects.prefetch_related("parent").select_related("type")
    serializer_class = EntiteSerializer
    logger_instance = logging.getLogger("entites.entites")
    filter_backends = (DjangoFilterBackend,)
    filterset_class = EntitesFilter

from rest_framework.serializers import ModelSerializer
from rest_framework.relations import SlugRelatedField

from my_models.models.entite import Entite, EntiteType
from rest_framework import serializers


class EntiteSerializer(ModelSerializer):
    parent = SlugRelatedField(
        slug_field="uness_id",
        queryset=Entite.objects.all(),
        error_messages={
            "does_not_exist": "L'identifiant {value} ne correspond à aucune entité."
        },
        required=False,
    )

    type = SlugRelatedField(
        slug_field="name",
        queryset=EntiteType.objects.all(),
        error_messages={
            "does_not_exist": "Le type {value} ne correspond à aucun type d'entité."
        },
    )
    allow_externe_id = serializers.SerializerMethodField()

    def get_allow_externe_id(self, obj):
        return obj.allow_externe_id

    class Meta:
        model = Entite
        fields = (
            "allow_externe_id",
            "code",
            "json",
            "libelle_court",
            "libelle",
            "parent",
            "type",
            "uness_id",
            "id",
        )
        read_only_fields = [
            "code",
            "libelle_court",
            "libelle",
            "parent",
            "type",
            "uness_id",
            "id",
        ]

[Sarah Boyce]

This needs quite a bit of debugging to simplify and reduce dependencies
There's a chance this is related to the changes in #35849 (as you say this was introduced in Django 5.2), cc-ing some people
#26942 may also be semi-related

[Jacob Walls]

The problem does not appear in django 5.1.8 because the test succeeded in 5.1.8, it seems that 5.2 unexpectedly raised the number of query from 2 to 3 (notice the third query look redundant with the second query) so the core issue with reporting may be older than 5.2.

The first query looks related to auth, and queries 2 and 3 are as I would expect when using .prefetch_related(). If you didn't see that third query before, it seems your test data may have changed. Django will not execute the .prefetch_related("parent") if the queryset it is chained to returned no results. You could verify this quickly by counting Entite.objects.all() at the top of your test and let us know if that varies between 5.1.8 and 5.2.

Seeing your TestCase would be helpful. For instance, does it subclass TestCase or TransactionTestCase? Do you have a setUpClass() method?

Finally, a git bisect would be very helpful here. You can clone the django repo, pip install -e path-to-local-copy-of-django, run your test case, and in a matter of minutes report the commit that caused the symptom of the problem to appear.

[Jean Bvt]

Replying to Jacob Walls:

The problem does not appear in django 5.1.8 because the test succeeded in 5.1.8, it seems that 5.2 unexpectedly raised the number of query from 2 to 3 (notice the third query look redundant with the second query) so the core issue with reporting may be older than 5.2.

The first query looks related to auth, and queries 2 and 3 are as I would expect when using .prefetch_related(). If you didn't see that third query before, it seems your test data may have changed. Django will not execute the .prefetch_related("parent") if the queryset it is chained to returned no results. You could verify this quickly by counting Entite.objects.all() at the top of your test and let us know if that varies between 5.1.8 and 5.2.

Seeing your TestCase would be helpful. For instance, does it subclass TestCase or TransactionTestCase? Do you have a setUpClass() method?

Finally, a git bisect would be very helpful here. You can clone the django repo, pip install -e path-to-local-copy-of-django, run your test case, and in a matter of minutes report the commit that caused the symptom of the problem to appear.

Thank you for your reply, I'll try to do all that once I've some time