`startTest` result hook not called until after tests already started when `--parallel` used

[Bob Whitelock]

Given a custom Django test runner that uses a custom result class, like this:

from unittest.runner import TextTestRunner, TextTestResult

from django.test.runner import DiscoverRunner


class CustomResult(TextTestResult):

    def startTest(self, test):
        print(f"startTest called for {test}")
        super().startTest(test)


class CustomRunner(TextTestRunner):
    resultclass = CustomResult


class CustomDjangoRunner(DiscoverRunner):
    test_runner = CustomRunner

And some tests, like this:

from django.test import TestCase


class FirstTest(TestCase):
    def test_first(self):
        print("Running test_first")


class SecondTest(TestCase):
    def test_second(self):
        print("Running test_second")

When the tests are run without --parallel, the expected behaviour occurs, and the startTest hook is called just before starting the test:

$ ./manage.py test
Creating test database for alias 'default'...
System check identified no issues (0 silenced).
startTest called for test_first (parallel_test.tests.FirstTest)
Running test_first
.startTest called for test_second (parallel_test.tests.SecondTest)
Running test_second
.
----------------------------------------------------------------------
Ran 2 tests in 0.001s

OK
Destroying test database for alias 'default'...

When the tests are run with --parallel, the startTest hook appears to be called after the test has already been run:

$ ./manage.py test --parallel
Creating test database for alias 'default'...
Cloning test database for alias 'default'...
Cloning test database for alias 'default'...
System check identified no issues (0 silenced).
Running test_first
Running test_second
startTest called for test_second (parallel_test.tests.SecondTest)
.startTest called for test_first (parallel_test.tests.FirstTest)
.
----------------------------------------------------------------------
Ran 2 tests in 0.017s

OK
Destroying test database for alias 'default'...
Destroying test database for alias 'default'...
Destroying test database for alias 'default'...

This is surprising, as I would expect the hook to a. be called in a consistent place when running a test, whether this is in parallel or serial, and b. be called before/as the test is started. This inconsistent behaviour can lead to issues when writing custom Django test runners, as people use this hook to run some code just as each test is started - for example see ​https://github.com/xmlrunner/unittest-xml-reporting/issues/229 and ​https://stackoverflow.com/a/39758653/2620402.

See ​https://github.com/bobwhitelock/django_parallel_test_issue_repro for a minimal repro of the issue including the code samples above.

I've confirmed this issue is present in both Django 3.1 and 2.2.

Happy to help with fixing this, but I'd need some pointers as to where to start. Thanks!

[Adam Johnson]

The reason this happens is that custom result classes aren't used in the parallel processes, but instead RemoteTestResult, which mostly holds onto the result to send it back to the main process for display. In theory it's possible to change how that works, and might even allow the --debug-sql and --pdb options work with --parallel, but it might require a little thought.

If you're trying to do something before a test begins, you can also override TestCase._callTestMethod, for example to capture output:

class ExampleTestMixin:
    def _callTestMethod(self, method):
        try:
            out = StringIO()
            err = StringIO()
            with mock.patch.object(sys, "stdout", new=out), mock.patch.object(
                sys, "stderr", new=err
            ):
                super()._callTestMethod(method)
        except Exception:
            print(out.getvalue(), end="")
            print(err.getvalue(), end="", file=sys.stderr)
            raise


class SimpleTestCase(ExampleTestMixin, test.SimpleTestCase):
    pass

[Carlton Gibson]

Given Adam's comment, I'm going to mark this as needsinfo — that info being a Proof of concept for what a patch might look like here.

[Bob Whitelock]

The reason this happens is that custom result classes aren't used in the parallel processes, but instead RemoteTestResult, which mostly holds onto the result to send it back to the main process for display. In theory it's possible to change how that works, and might even allow the --debug-sql and --pdb options work with --parallel, but it might require a little thought.

Thanks for the explanation, and that's interesting - the custom startTest method does appear to be called however, just after the test has actually started, so it does look like the custom result class is being used. Unless I'm misunderstanding what you mean?

[Adam Johnson]

the custom startTest method does appear to be called however, just after the test has actually started, so it does look like the custom result class is being used.

Yes - I think it's being called back in the main process when reporting the results, though I haven't confirmed this.