Apparent issue with pytest 3.4.0

[jakewan]

Pytest 3.4.0 was just released today and immediately I started seeing failing tests and lots of unfamiliar output. I wasn't sure what it was, so I started removing bits one by one, and the problem seems to go away when I disable the pytest-sugar plugin. I'm not sure whether to report this to the pytest project or the pytest-sugar project, but thought I'd start here.

Pytest-sugar is the only plugin I'm using, so perhaps it's a general problem related to all pytest plugins.

I made a project that I believe isolates the issue: https://github.com/jakewan/pytestdemo

From the README:

Create a virtual environment

From project root directory:

$ make create-virtual-env
if [ -d ".pytestdemo/env" ]; then rm -rf .pytestdemo/env; fi
python3 -m venv .pytestdemo/env
.pytestdemo/env/bin/pip install -e .
Obtaining file:///Users/jacob/Documents/repos/pytestdemo
Collecting pytest (from pytestdemo==0.1a1)
  Using cached pytest-3.4.0-py2.py3-none-any.whl
Collecting pytest-sugar (from pytestdemo==0.1a1)
  Using cached pytest-sugar-0.9.0.tar.gz
Collecting pluggy<0.7,>=0.5 (from pytest->pytestdemo==0.1a1)
Collecting attrs>=17.2.0 (from pytest->pytestdemo==0.1a1)
  Using cached attrs-17.4.0-py2.py3-none-any.whl
Collecting py>=1.5.0 (from pytest->pytestdemo==0.1a1)
  Using cached py-1.5.2-py2.py3-none-any.whl
Collecting six>=1.10.0 (from pytest->pytestdemo==0.1a1)
  Using cached six-1.11.0-py2.py3-none-any.whl
Requirement already satisfied: setuptools in ./.pytestdemo/env/lib/python3.6/site-packages (from pytest->pytestdemo==0.1a1)
Collecting termcolor>=1.1.0 (from pytest-sugar->pytestdemo==0.1a1)
  Using cached termcolor-1.1.0.tar.gz
Installing collected packages: pluggy, attrs, py, six, pytest, termcolor, pytest-sugar, pytestdemo
  Running setup.py install for termcolor ... done
  Running setup.py install for pytest-sugar ... done
  Running setup.py develop for pytestdemo
Successfully installed attrs-17.4.0 pluggy-0.6.0 py-1.5.2 pytest-3.4.0 pytest-sugar-0.9.0 pytestdemo six-1.11.0 termcolor-1.1.0

Run the test

$ make run-tests
.pytestdemo/env/bin/py.test
Test session starts (platform: darwin, Python 3.6.4, pytest 3.4.0, pytest-sugar 0.9.0)
rootdir: /Users/jacob/Documents/repos/pytestdemo, inifile:
plugins: sugar-0.9.0

 test/test_foo.py ✓                                                                                                                                         100% ██████████INTERNALERROR> Traceback (most recent call last):
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/_pytest/main.py", line 100, in wrap_session
INTERNALERROR>     session.exitstatus = doit(config, session) or 0
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/_pytest/main.py", line 138, in _main
INTERNALERROR>     config.hook.pytest_runtestloop(session=session)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 216, in <lambda>
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 201, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 76, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 180, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/_pytest/main.py", line 161, in pytest_runtestloop
INTERNALERROR>     item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 216, in <lambda>
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 201, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 76, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 180, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/_pytest/runner.py", line 64, in pytest_runtest_protocol
INTERNALERROR>     nodeid=item.nodeid, location=item.location,
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/__init__.py", line 216, in <lambda>
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 201, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 76, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/pluggy/callers.py", line 180, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/Users/jacob/Documents/repos/pytestdemo/.pytestdemo/env/lib/python3.6/site-packages/_pytest/terminal.py", line 315, in pytest_runtest_logfinish
INTERNALERROR>     last_item = len(self._progress_nodeids_reported) == self._session.testscollected
INTERNALERROR> AttributeError: 'NoneType' object has no attribute 'testscollected'


Results (0.02s):
       1 passed
make: *** [run-tests] Error 3

Remove pytest-sugar

Update setup.py by commenting out the line requiring pytest-sugar, e.g.

install_requires=[
    'pytest',
    # 'pytest-sugar',
],

Recreate the virtual environment

$ make create-virtual-env
if [ -d ".pytestdemo/env" ]; then rm -rf .pytestdemo/env; fi
python3 -m venv .pytestdemo/env
.pytestdemo/env/bin/pip install -e .
Obtaining file:///Users/jacob/Documents/repos/pytestdemo
Collecting pytest (from pytestdemo==0.1a1)
  Using cached pytest-3.4.0-py2.py3-none-any.whl
Collecting six>=1.10.0 (from pytest->pytestdemo==0.1a1)
  Using cached six-1.11.0-py2.py3-none-any.whl
Collecting attrs>=17.2.0 (from pytest->pytestdemo==0.1a1)
  Using cached attrs-17.4.0-py2.py3-none-any.whl
Collecting pluggy<0.7,>=0.5 (from pytest->pytestdemo==0.1a1)
Requirement already satisfied: setuptools in ./.pytestdemo/env/lib/python3.6/site-packages (from pytest->pytestdemo==0.1a1)
Collecting py>=1.5.0 (from pytest->pytestdemo==0.1a1)
  Using cached py-1.5.2-py2.py3-none-any.whl
Installing collected packages: six, attrs, pluggy, py, pytest, pytestdemo
  Running setup.py develop for pytestdemo
Successfully installed attrs-17.4.0 pluggy-0.6.0 py-1.5.2 pytest-3.4.0 pytestdemo six-1.11.0

Run the test again

manzanita:pytestdemo jacob$ make run-tests
.pytestdemo/env/bin/py.test
=========================================================================== test session starts ===========================================================================
platform darwin -- Python 3.6.4, pytest-3.4.0, py-1.5.2, pluggy-0.6.0
rootdir: /Users/jacob/Documents/repos/pytestdemo, inifile:
collected 1 item

test/test_foo.py .                                                                                                                                                  [100%]

======================================================================== 1 passed in 0.01 seconds =========================================================================

Okay with --verbose

Also, in case it's relevant, the problem also goes away when I run py.test with the --verbose flag:

$ .pytestdemo/env/bin/py.test --verbose
Test session starts (platform: darwin, Python 3.6.4, pytest 3.4.0, pytest-sugar 0.9.0)
cachedir: .pytest_cache
rootdir: /Users/jacob/Documents/repos/pytestdemo, inifile:
plugins: sugar-0.9.0

 test/test_foo.py::test_foo_says ✓                                                                                                                          100% ██████████

Results (0.01s):
       1 passed

[nicoddemus]

PR #133 open with a fix. 👍

[m3talstorm]

@nicoddemus I'm not sure that PR fixed the issue, notice the 'collected' line is not shown:

root@host ~/project> pytest -s --collect-only tests/
Test session starts (platform: linux2, Python 2.7.12, pytest 3.4.0, pytest-sugar 0.9.1)
rootdir: /home/user/project, inifile:
plugins: sugar-0.9.1, profiling-1.2.6, html-1.7, flask-0.10.0, cov-2.5.1, xdist-1.15.0, repeat-0.4.1
...snip tests...


Results (0.09s):
root@host ~/project>

root@host ~/project> pytest -s -p no:sugar --collect-only tests/
================================================================================================= test session starts ==================================================================================================
platform linux2 -- Python 2.7.12, pytest-3.4.0, py-1.5.2, pluggy-0.6.0
rootdir: /home/user/project, inifile:
plugins: profiling-1.2.6, html-1.7, flask-0.10.0, cov-2.5.1, xdist-1.15.0, repeat-0.4.1
collected 132 items
...snip tests...

============================================================================================= no tests ran in 0.09 seconds =============================================================================================
root@host ~/project>

[nicoddemus]

@m3talstorm I'm not entirely familiar how pytest-sugar works, my PR intended to fix the crash. Perhaps @Frozenball can chime in here?

[Teemu]

I think originally when I created pytest-sugar the plan was to hide a lot of noise from the test report (such as the number of tests collected). I would say the optimal resolution would be to hide all the extra lines and make them configurable with the theme.

If you look at the GIF in README you can actually notice that we didn't have rootdir or collected lines.