pytest 5.3.3: slow or crashing tests

[rixx]

tl;dr: If your tests are slow or break on pytest 5.3.3, please pin pytest==5.3.2 until this is resolved. A change to fixture handling seems incompatible with at least pytest-django, but also some non-Django projects.

A change in 9918093 (part of the 5.3.3 release) led to an incompatibility regarding fixture handling/cleanup. It seems fixtures are not correctly recycled/collected, so they persist in unintended ways.

Original report with plenty of unimportant details inside:

I'm testing a Django project with pytest, pytest-xdist, pytest-django, and tox as runner. As of the latest pytest release ~2 hours ago, 5.3.3, I'm seeing the weirdest test failures.

The errors can be seen here:

django.core.exceptions.ImproperlyConfigured: The database name 'test_travis_ci_test_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0' (71 characters) is longer than PostgreSQL's limit of 63 characters. Supply a shorter NAME in settings.DATABASES.
---------------------------- Captured stderr setup -----------------------------
Got an error creating the test database: database "test_travis_ci_test_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0_gw0" already exists

or using MySQL:

---------------------------------------------------------------------------------------------- Captured stderr setup ----------------------------------------------------------------------------------------------
Got an error creating the test database: (1102, "Incorrect database name 'test_pretalx_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7_gw7'")

The database name is supposedly generated by pytest-xdist, which is running on gw0 and gw1 in this Travis runner.

From my local debugging: It appears that initally, pytest-xdist will create databases called "test_pretalx_gw0" and so on, but then I see those disappear and be replaced by "test_pretalx_gw0_gw0", then "test_pretalx_gw0_gw0_gw0", and so on, while the tests are running. They aren't all replaced at the same time, and not for each test, but (I think) each time each thread opens a new module/test file.

I'm not sure if the fault rests with pytest, or pytest-xdist, or pytest-django, but it's only present as of the 5.3.3. bugfix release, with 5.3.2 running as intended (and significantly faster, at that). I'm reporting this here in hopes of help, and because while the error implies that the problem lies with either pytest-xdist or pytest-django, the change was definitely introduced on the side of pytest itself.

I'm happy to provide more details or debugging.

[blueyed]

As of the latest pytest release ~2 hours ago, 5.3.3, I'm seeing the weirdest test failures.

Can you git-bisect it then between 5.3.2 and 5.3.3, please?
And make sure that it does not fail with 5.3.2 already, of course.

[nicoddemus]

If the problem is between 5.3.2 and 5.3.3, one of those two fixes might be the culprit:

• Test involving multiprocessing crashes when pytest 5.1.2 and xdist are used #5971: Fix a pytest-xdist crash when dealing with exceptions raised in subprocesses created by the multiprocessing module.
• Autouse and parameterization results in fixtures not being torn down, or even being torn down out of order  #6436: :class:FixtureDef <_pytest.fixtures.FixtureDef> objects now properly register their finalizers with autouse and parameterized fixtures that execute before them in the fixture stack so they are torn down at the right times, and in the right order.

🤔

[nicoddemus]

#6436 seems more likely, but perhaps in the sense that the fix broke some expectation on pytest-django

[rixx]

Running the two versions side by side, the performance hit is very noticeable, too.

Result of git bisect 5.3.3 5.3.2:

commit 99180939febb6ca4b3ff788cf336b065046653f2
Author: Chris NeJame <[email protected]>
Date:   Wed Jan 15 11:00:42 2020 -0500

    fixtures register finalizers with all fixtures before them in the stack

 AUTHORS                    |   1 +
 changelog/6436.bugfix.rst  |   3 ++
 src/_pytest/fixtures.py    |  59 ++++++++++++++++++--
 testing/python/fixtures.py | 132 +++++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 192 insertions(+), 3 deletions(-)
 create mode 100644 changelog/6436.bugfix.rst

Full bisect:

$ git bisect start 5.3.3 5.3.2
Bisecting: 41 revisions left to test after this (roughly 5 steps)
[23475b6ab95a40ad35b676637aea885fa777a3fd] Fix wrong 'changelog' and 'reference' links in docs

$ git bisect good
Bisecting: 20 revisions left to test after this (roughly 4 steps)
[f5844449a86b5f45ceeecd9389c4aa03374517e8] Merge pull request #6442 from blueyed/rP

$ git bisect good
Bisecting: 10 revisions left to test after this (roughly 3 steps)
[749752d440c3e72f5e2824b9bc344b35ed562dc8] Merge pull request #6435 from blueyed/type_checking

$ git bisect bad
Bisecting: 4 revisions left to test after this (roughly 2 steps)
[99180939febb6ca4b3ff788cf336b065046653f2] fixtures register finalizers with all fixtures before them in the stack

$ git bisect bad
Bisecting: 2 revisions left to test after this (roughly 1 step)
[29703a5f51d07534103c405c81b2166e766400c1] Merge pull request #6466 from blueyed/cover-safe_getattr

$ git bisect good
Bisecting: 0 revisions left to test after this (roughly 1 step)
[1ec5befdb7301107121cc448236793a52ee86f6a] Merge pull request #6468 from nicoddemus/deploy-release-notes-6369

$ git bisect good
99180939febb6ca4b3ff788cf336b065046653f2 is the first bad commit
commit 99180939febb6ca4b3ff788cf336b065046653f2
Author: Chris NeJame <[email protected]>
Date:   Wed Jan 15 11:00:42 2020 -0500

    fixtures register finalizers with all fixtures before them in the stack

 AUTHORS                    |   1 +
 changelog/6436.bugfix.rst  |   3 ++
 src/_pytest/fixtures.py    |  59 ++++++++++++++++++--
 testing/python/fixtures.py | 132 +++++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 192 insertions(+), 3 deletions(-)
 create mode 100644 changelog/6436.bugfix.rst

[nicoddemus]

Thanks @rixx.

That confirms my suspicion that it is related to #6438.

The fix might have caused a regression in pytest-django though, so I suggest to cross-post this in https://github.com/pytest-dev/pytest-django/issues. 👍

[mvbrn]

I have the same issue without pytest-xdist installed.

[blueyed]

FWIW, pytest-django has a failing test (pytest-dev/pytest-django#801 (comment)): https://github.com/pytest-dev/pytest-django/blob/6528bc976dfd907fc5c63c659947371dbccb1f17/tests/test_db_setup.py#L310-L332

/cc @SalmonMode

[blueyed]

@mvbrn without pytest-django?
@nicoddemus I'm off for now, FYI.

[mvbrn]

@blueyed pytest-django is present :)

upd: downgrade to pytest==5.3.2 helped me

[blueyed]

#6494 has more info, in particular that tests are using more fixtures all the time.

[nicoddemus]

From #6494 so the context is included here:

Looking at the change, code was previously running with self.argnames == ['request'], after the change it is now computing its list of fixtures as {'_django_clear_site_cache', 'django_db_blocker', 'django_test_environment', '_fail_for_invalid_template_variable', '_dj_autoclear_mailbox', 'request', '_django_setup_unittest'} and this obviously make the tests slower.

plugins: django-3.8.0, localserver-0.5.0, freezegun-0.3.0.post1, django-webtest-1.9.7

[nicoddemus]

Pinned this issue as I suspect more people will hit this problem.

[rsebille]

Hi 👋,

Coming here from #6495, we have the same issue with a non-django project, so the problem is more likely coming from pytest than pytest-django :).
bisecting also give me 9918093 as first bad commit.

[nicoddemus]

Coming here from #6495, we have the same issue with a non-django project, so the problem is more likely coming from pytest than pytest-django :).

That's very important information, thanks! Also can you please confirm that pytest-django is not installed at all there?

I'm thinking we should make a new hotfix release reverting #6403.

Meanwhile, if someone can provide a MWE for us to study, it would be great, thanks!

[SalmonMode]

@nicoddemus I took a look at #6494 and it provided me with a clue. I'm not sure if this is the actual core of the issue, and I'm not even sure how this could have an impact, but it could be that function scope-level fixtures are registering their finalizers with autouse class scope-level fixtures when the test requesting the function scope-level fixture is not contained within a test class.

I know how to prevent this from happening and can have a PR ready in a few minutes, but I have no idea how to recreate an issue caused by this, as the function scope-level fixtures should already have been torn down before the next test has a chance to run the autouse class scope-level fixture that would otherwise teardown the function scope-level fixture.

[rsebille]

@nicoddemus Yeah I can confirm that pytest-django is not installed inside the virtualenv.
pytest-related packages installed:

pip list | grep pytest
pytest                        5.3.3.dev42+g23475b6ab            /home/romain/Projects/pytest/src
pytest-asyncio                0.10.0                            
pytest-cov                    2.8.1                             
pytest-html                   2.0.1                             
pytest-metadata               1.8.0                             
pytest-mock                   2.0.0                             
pytest-randomly               3.2.0                             
pytest-timeout                1.3.4   

I am going to test without any plugins installed at all, just to be sure it not one of them neither :).

One last piece of information is the problem appears only with python 3.6, 3.7 is OK, didn't check other versions.

Edit: Same issue with only pytest-asyncio and pytest-mock installed (need them for the current subset of tests to reproduce the issue).

[rixx]

@SalmonMode I don't have the time to create a MWE, but if you have a patch ready, I can test it directly, if that helps.

Re Python versions, I'm running Python 3.7 in that virtualenv, so it's not 3.6 specific.

[SalmonMode]

@rixx that would be much appreciated! I'll have a branch ready in just a sec

[SalmonMode]

@rixx here's the branch https://github.com/SalmonMode/pytest/tree/fix-6492

[SalmonMode]

@rixx would you mind trying the patch from #6504 with pytest, and pytest-dev/pytest-django#807 with pytest-django?

[rixx]

That combination still shows the broken behaviour for me, as far as I can tell: Slow tests, and duplicate databases.

[SalmonMode]

@rixx this is a tough one. I really appreciate you taking the time to help with it!

Are you by any chance using request.addfinalizer and/or request.getfixturevalue anywhere?

[rixx]

I'm not (or at least not to my knowledge). I'm running the pretalx test suite, you can run it yourself for testing purposes.

[SalmonMode]

@rixx I'm not able to get the same results as you. I'm running tox -e tox -e tests-sqlite per the documents instructions, but I only get 1 failed test, and the rest are fine. Here's the bottom of my report:

==============================================================================
FAIL: tests/agenda/test_agenda_schedule_export.py::test_schedule_frab_json_export
------------------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/nejame/dev/SalmonMode/pretalx/src/tests/agenda/test_agenda_schedule_export.py", line 117, in test_schedule_frab_json_export
    follow=True,
  File "/usr/lib/python3.6/contextlib.py", line 88, in __exit__
    next(self.gen)
  File "/home/nejame/dev/SalmonMode/pretalx/.env/lib/python3.6/site-packages/pytest_django/fixtures.py", line 471, in _assert_num_queries
    pytest.fail(msg)
  File "/home/nejame/dev/SalmonMode/pytest/src/_pytest/outcomes.py", line 130, in fail
    raise Failed(msg=msg, pytrace=pytrace)
Failed: Expected to perform 25 queries or less but 26 were done (add -v option to show queries)

------------------------------------------------------------------------------
Ran 979 tests in 88.37s

FAILED (failures=1, skipped=1)

Pytest also shows up in the pip list at the start of that command as this for me:

-e git+https://github.com/SalmonMode/pytest.git@9e013400c3dd3d9f2bd3fdeb3d0227de1f9fbd8c#egg=pytest

Here's the complete list it spat out:

amqp==2.5.2
apipkg==1.5
appdirs==1.4.3
attrs==19.3.0
beautifulsoup4==4.8.2
billiard==3.6.1.0
black==19.10b0
bleach==3.1.0
celery==4.4.0
certifi==2019.11.28
chardet==3.0.4
Click==7.0
coverage==5.0.3
csscompressor==0.9.5
cssutils==1.0.2
defusedcsv==1.1.0
Django==2.2.9
django-appconf==1.0.3
django-bootstrap4==1.1.1
django-compressor==2.4
django-context-decorator==1.6.0
django-csp==3.6
django-filter==2.2.0
django-formset-js-improved==0.5.0.2
django-formtools==2.2
django-hierarkey==1.0.3
django-i18nfield==1.6.1
django-jquery-js==3.1.1
django-libsass==0.8
django-scopes==1.2.0
djangorestframework==3.11.0
docformatter==1.3.1
entrypoints==0.3
execnet==1.7.1
Faker==4.0.0
flake8==3.7.9
freezegun==0.3.13
idna==2.8
importlib-metadata==1.4.0
inlinestyler==0.2.5
isort==4.3.21
kombu==4.6.7
libsass==0.19.4
lxml==4.4.2
Markdown==3.1.1
mccabe==0.6.1
more-itertools==8.1.0
packaging==20.0
pathspec==0.7.0
Pillow==7.0.0
pluggy==0.13.1
-e git+https://github.com/pretalx/pretalx.git@af33578f2ffb28846b3e444df51695568fb50ba4#egg=pretalx&subdirectory=src
publicsuffixlist==0.6.11
py==1.8.1
pycodestyle==2.5.0
pyflakes==2.1.1
pyparsing==2.4.6
-e git+https://github.com/SalmonMode/pytest.git@9e013400c3dd3d9f2bd3fdeb3d0227de1f9fbd8c#egg=pytest
pytest-cov==2.8.1
-e git+https://github.com/SalmonMode/pytest-django.git@0d1f4befb5be33ecb0f3f1ad4b7314d30d6f0f07#egg=pytest_django
pytest-forked==1.1.3
pytest-mock==2.0.0
pytest-rerunfailures==8.0
pytest-sugar==0.9.2
pytest-tldr==0.2.1
pytest-xdist==1.31.0
python-dateutil==2.8.1
pytz==2019.3
qrcode==6.1
rcssmin==1.0.6
regex==2020.1.8
reportlab==3.5.34
requests==2.22.0
responses==0.10.9
rjsmin==1.1.0
rules==2.2
semantic-version==2.6.0
six==1.14.0
soupsieve==1.9.5
sqlparse==0.3.0
termcolor==1.1.0
text-unidecode==1.3
toml==0.10.0
typed-ast==1.4.1
untokenize==0.1.1
urllib3==1.25.7
urlman==1.3.0
vine==1.3.0
vobject==0.9.6.1
wcwidth==0.1.8
webencodings==0.5.1
whitenoise==5.0.1
zipp==1.0.0
zxcvbn==4.4.28

[rixx]

This conversation has gotten somewhat spammy and uninformative for everybody else – I think further discussion would probably work better in private, if necessary – you can find my contact details here. I pushed a branch pinning the pytest and pytest-django versions here for reference..

[SalmonMode]

@rixx @nicoddemus @blueyed @RonnyPfannschmidt I have a confirmed fix. The problem was with pytest-django in how it determined what database name to use for a test. It kept adding on the worker ID to the end of what was already there. The error here was caused by it trying to create a mysql database with too long of a name. The PR for it is here pytest-dev/pytest-django#807

I'm currently looking into why the build for it fails.

[nicoddemus]

Closing as per: #6496

There's a new attempt at tackling the original problem again at #7511 in case anybody is interested.

Thanks for everyone who participated in this thread.