search

pytest-dev / pytest

The pytest framework makes it easy to write small tests, yet scales to support complex functional testing
https://pytest.org
MIT License
11.88k stars 2.65k forks source link

Test suite crashes with core dump at 99% with pytest 5.3.3 #6495

Closed agateblue closed 4 years ago

agateblue commented 4 years ago

My test suite fails consistently at 99% (e.g https://dev.funkwhale.audio/funkwhale/funkwhale/-/jobs/40524) when using Pytest 5.3.3. The issue doesn't seem to occur when using Pytest 5.3.2, so I suspect it is a regression.

Fortunately, I seem to reproduce the issue when running only a fraction of my test suite, e.g:

bash-4.4# pytest --reuse-db tests/music/test_views.py
Test session starts (platform: linux, Python 3.6.8, pytest 5.3.3, pytest-sugar 0.9.2)
Using --randomly-seed=1579272238
Django settings: config.settings.local (from environment variable)
rootdir: /app, inifile: setup.cfg
plugins: sugar-0.9.2, cov-2.8.1, xdist-1.31.0, env-0.6.2, profiling-1.3.0, randomly-3.2.1, requests-mock-1.7.0, forked-1.1.3, mock-2.0.0, django-3.7.0, celery-4.3.0
collecting ... 
 tests/music/test_views.py ✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓ 33% ███▍      
                           ✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓ 65% ██████▋   
                           ✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓✓ 98% █████████▊
                           ✓                                    99% █████████▉
Aborted (core dumped)

At first, since the error seemingly occured at the very end of the test suite, I suspected a broken interaction with a plugin, so I uninstalled a few of them (xdist, forked, profiling, cov, sugar), but it's still failing:

bash-4.4# pytest --reuse-db tests/music/test_views.py
============================ test session starts =============================
platform linux -- Python 3.6.8, pytest-5.3.3, py-1.8.1, pluggy-0.13.1
Using --randomly-seed=1579272680
Django settings: config.settings.local (from environment variable)
rootdir: /app, inifile: setup.cfg
plugins: env-0.6.2, randomly-3.2.1, requests-mock-1.7.0, mock-2.0.0, django-3.7.0, celery-4.3.0
collected 110 items                                                          

tests/music/test_views.py ............................................ [ 40%]
..................................................................Aborted (core dumped)

I've also tried to isolate a specific test that could cause this issue, by runnining only a subset of the tests, but I couldn't isolate one this way. However, I did find an interesting outcome! With the 110 tests uncommented, I get the core dumped issues. But when I commented tests one by one, at one point, I got a recursion error:

bash-4.4# pytest --reuse-db -p no:randomly tests/music/test_views.py
=========================================== test session starts ===========================================
platform linux -- Python 3.6.8, pytest-5.3.3, py-1.8.1, pluggy-0.13.1
Django settings: config.settings.local (from environment variable)
rootdir: /app, inifile: setup.cfg
plugins: env-0.6.2, requests-mock-1.7.0, mock-2.0.0, django-3.7.0, celery-4.3.0
collected 93 items                                                                                        

tests/music/test_views.py ......................................................................... [ 78%]
....................E                                                                               [100%]

================================================= ERRORS ==================================================
_______ ERROR at teardown of test_detail_includes_description_key[api:v1:tracks-detail-music.Track] _______

cls = <class '_pytest.runner.CallInfo'>
func = <function call_runtest_hook.<locals>.<lambda> at 0x7ff6edcd9e18>, when = 'teardown'
reraise = (<class '_pytest.outcomes.Exit'>, <class 'KeyboardInterrupt'>)

    @classmethod
    def from_call(cls, func, when, reraise=None) -> "CallInfo":
        #: context of invocation: one of "setup", "call",
        #: "teardown", "memocollect"
        start = time()
        excinfo = None
        try:
>           result = func()

/usr/lib/python3.6/site-packages/_pytest/runner.py:235: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
/usr/lib/python3.6/site-packages/_pytest/runner.py:208: in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
/usr/lib/python3.6/site-packages/pluggy/hooks.py:286: in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
/usr/lib/python3.6/site-packages/pluggy/manager.py:93: in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
/usr/lib/python3.6/site-packages/pluggy/manager.py:87: in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
/usr/lib/python3.6/site-packages/_pytest/runner.py:147: in pytest_runtest_teardown
    item.session._setupstate.teardown_exact(item, nextitem)
/usr/lib/python3.6/site-packages/_pytest/runner.py:332: in teardown_exact
    self._teardown_towards(needed_collectors)
/usr/lib/python3.6/site-packages/_pytest/runner.py:349: in _teardown_towards
    raise val.with_traceback(tb)
/usr/lib/python3.6/site-packages/_pytest/runner.py:340: in _teardown_towards
    self._pop_and_teardown()
/usr/lib/python3.6/site-packages/_pytest/runner.py:298: in _pop_and_teardown
    self._teardown_with_finalization(colitem)
/usr/lib/python3.6/site-packages/_pytest/runner.py:318: in _teardown_with_finalization
    self._callfinalizers(colitem)
/usr/lib/python3.6/site-packages/_pytest/runner.py:315: in _callfinalizers
    raise val.with_traceback(tb)
/usr/lib/python3.6/site-packages/_pytest/runner.py:306: in _callfinalizers
    fin()
/usr/lib/python3.6/site-packages/_pytest/fixtures.py:873: in finish
    raise val.with_traceback(tb)
/usr/lib/python3.6/site-packages/_pytest/fixtures.py:866: in finish
    func
###
# I TRUNCATED THE LOG, BUT THIS WAS REPEATED 100s OF TIMES
###
/usr/lib/python3.6/site-packages/_pytest/fixtures.py:873: in finish
    raise val.with_traceback(tb)
/usr/lib/python3.6/site-packages/_pytest/fixtures.py:866: in finish
    func()
/usr/lib/python3.6/site-packages/_pytest/fixtures.py:873: in finish
    raise val.with_traceback(tb)
/usr/lib/python3.6/site-packages/_pytest/fixtures.py:866: in finish
    func()
/usr/lib/python3.6/site-packages/_pytest/fixtures.py:876: in finish
    hook.pytest_fixture_post_finalizer(fixturedef=self, request=request)
/usr/lib/python3.6/site-packages/pluggy/hooks.py:286: in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
/usr/lib/python3.6/site-packages/pluggy/manager.py:93: in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

hook = <_HookCaller 'pytest_fixture_post_finalizer'>
methods = [<HookImpl plugin_name='setuponly', plugin=<module '_pytest.setuponly' from '/usr/lib/python3.6/site-packages/_pytest/setuponly.py'>>]
kwargs = {'fixturedef': <FixtureDef argname='django_db_setup' scope='session' baseid=''>, 'request': <SubRequest 'django_db_setup' for <Function test_refresh_remote_entity_when_param_is_true[music.Artist-api:v1:artists-detail]>>}

    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
        methods,
        kwargs,
>       firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
    )
E   RecursionError: maximum recursion depth exceeded while calling a Python object

/usr/lib/python3.6/site-packages/pluggy/manager.py:87: RecursionError
============================================ warnings summary =============================================
tests/music/test_views.py::test_can_get_libraries_for_music_entities[artist]
tests/music/test_views.py::test_refresh_remote_entity_when_param_is_true[music.Artist-api:v1:artists-detail]
tests/music/test_views.py::test_refresh_remote_entity_no_param[false]
tests/music/test_views.py::test_refresh_remote_entity_no_param[0]
tests/music/test_views.py::test_refresh_remote_entity_no_param[]
tests/music/test_views.py::test_artist_list_exclude_channels[params2-1]
tests/music/test_views.py::test_search_get[True]
tests/music/test_views.py::test_search_get[False]
tests/music/test_views.py::test_detail_includes_description_key[api:v1:artists-detail-music.Artist]
  /usr/lib/python3.6/site-packages/django/db/models/query.py:1242: RemovedInDjango31Warning: Album QuerySet won't use Meta.ordering in Django 3.1. Add .order_by('-creation_date') to retain the current query.
    self._result_cache = list(self._iterable_class(self))

tests/music/test_views.py::test_can_get_libraries_for_music_entities[artist]
tests/music/test_views.py::test_can_get_libraries_for_music_entities[album]
tests/music/test_views.py::test_can_get_libraries_for_music_entities[track]
  /usr/lib/python3.6/site-packages/rest_framework/pagination.py:200: UnorderedObjectListWarning: Pagination may yield inconsistent results with an unordered object_list: <class 'funkwhale_api.music.models.Library'> LibraryQuerySet.
    paginator = self.django_paginator_class(queryset, page_size)

-- Docs: https://docs.pytest.org/en/latest/warnings.html
================================ 93 passed, 12 warnings, 1 error in 31.26s ================================

I don't have the time to provide a minimal example right now, but I can definitely give more information or try some commands, since I reliably reproduce this in my dev environment, inside a Docker container running Linux Alpine and Python 3.6.8.

pip freeze output:

bash-4.4# pip freeze
aiohttp==3.5.4
aioredis==1.3.1
aioresponses==0.6.0
amqp==2.5.2
apipkg==1.5
appdirs==1.4.3
asgiref==2.3.2
async-timeout==3.0.1
asynctest==0.12.2
attrs==19.3.0
autobahn==19.11.2
Automat==0.8.0
autopep8==1.4.4
backcall==0.1.0
billiard==3.6.1.0
black==19.10b0
bleach==3.1.0
boto3==1.11.0
botocore==1.14.0
celery==4.3.0
certifi==2019.11.28
cffi==1.13.2
channels==2.1.6
channels-redis==2.3.3
chardet==3.0.4
Click==7.0
click-default-group==1.2.2
constantly==15.1.0
coverage==4.5.4
cryptography==2.8
daphne==2.2.5
decorator==4.4.1
defusedxml==0.6.0
Django==2.2.9
django-allauth==0.39.1
django-auth-ldap==1.7.0
django-cacheops==4.2
django-cleanup==3.2.0
django-cors-headers==2.5.3
django-coverage-plugin==1.6.0
django-debug-toolbar==1.11
django-debug-toolbar-line-profiler==0.6.1
django-dynamic-preferences==1.7.1
django-environ==0.4.5
django-filter==2.1.0
django-oauth-toolkit==1.2.0
django-redis==4.10.0
django-rest-auth==0.9.5
django-silk==3.0.4
django-storages==1.7.1
django-versatileimagefield==1.10
djangorestframework==3.10.3
djangorestframework-jwt==1.11.0
docutils==0.15.2
entrypoints==0.3
execnet==1.7.1
factory-boy==2.12.0
Faker==3.0.0
flake8==3.7.9
funcy==1.14
gprof2dot==2019.11.30
gunicorn==20.0.4
h11==0.9.0
hiredis==1.0.1
httptools==0.0.13
hyperlink==19.0.0
idna==2.8
idna-ssl==1.1.0
importlib-metadata==1.4.0
incremental==17.5.0
ipdb==0.11
ipython==7.11.1
ipython-genutils==0.2.0
jedi==0.15.2
Jinja2==2.10.3
jmespath==0.9.4
kombu==4.5.0
line-profiler==2.1.2
Markdown==3.1.1
MarkupSafe==1.1.1
mccabe==0.6.1
more-itertools==8.1.0
msgpack==0.6.2
multidict==4.7.4
musicbrainzngs==0.6
mutagen==1.42.0
oauthlib==3.1.0
olefile==0.43
packaging==20.0
parso==0.5.2
pathspec==0.7.0
pendulum==2.0.5
persisting-theory==0.2.1
pexpect==4.7.0
pickleshare==0.7.5
Pillow==4.3.0
pluggy==0.13.1
profiling==0.1.3
prompt-toolkit==2.0.10
psycopg2==2.7.5
psycopg2-binary==2.8.4
ptyprocess==0.6.0
py==1.8.1
pyasn1==0.4.8
pyasn1-modules==0.2.8
pycodestyle==2.5.0
pycparser==2.19
pydub==0.23.1
pyflakes==2.1.1
Pygments==2.5.2
PyHamcrest==1.9.0
PyJWT==1.7.1
PyLD==1.0.4
PyMemoize==1.0.3
pyOpenSSL==19.1.0
pyparsing==2.4.6
pytest==5.3.3
pytest-django==3.7.0
pytest-env==0.6.2
pytest-mock==2.0.0
pytest-randomly==3.2.1
python-dateutil==2.8.1
python-ldap==3.2.0
python-magic==0.4.15
python3-openid==3.1.0
pytz==2019.1
pytzdata==2019.3
raven==6.10.0
redis==3.2.1
regex==2020.1.8
requests==2.22.0
requests-http-signature==0.0.3
requests-mock==1.7.0
requests-oauthlib==1.3.0
s3transfer==0.3.0
service-identity==18.1.0
six==1.13.0
sqlparse==0.3.0
termcolor==1.1.0
text-unidecode==1.3
toml==0.10.0
traitlets==4.3.3
Twisted==19.10.0
txaio==18.8.1
typed-ast==1.4.0
typing-extensions==3.7.4.1
unicode-slugify==0.1.3
Unidecode==1.1.1
urllib3==1.25.7
urwid==2.1.0
uvicorn==0.11.1
uvloop==0.14.0
valuedispatch==0.0.1
vine==1.3.0
wcwidth==0.1.8
webencodings==0.5.1
websockets==8.1
yarl==1.4.2
zipp==0.6.0
zope.interface==4.7.1

By the way, many thanks to the Pytest community for the amazing piece of software :heart: Let me know if I can provide anything else to troubleshoot this.

nicoddemus commented 4 years ago

Hi @EliotBerriot,

Thanks for the report! Seems to be the same issue as in #6492. The workaround for now is to pin pytest to 5.3.2 until we figure out if the problem is in pytest or pytest-django. 👍

Closing this one in favor of #6492, please subscribe to it to get notifications on the progress of this problem. 👍

blueyed commented 4 years ago

@EliotBerriot It might be useful to run it with -l to show locals in the traceback (to see what those finish calls are about), and/or put a pdb.set_trace()/print there to see if it is the same fixture all the time. /cc @SalmonMode I think this might be interesting for debugging.