py27-xdist and py27-nobyte failing on master

[nicoddemus]

Both AppVeyor and Travis are failing in the current master. Here's the Travis output:

=================================== FAILURES ===================================
______________ TestTraceback_f_g_h.test_traceback_cut_excludepath ______________
[gw0] linux2 -- Python 2.7.6 /home/travis/build/pytest-dev/pytest/.tox/py27-xdist/bin/python2.7
self = <test_excinfo.TestTraceback_f_g_h object at 0x7fe3f6424bd0>
testdir = <Testdir local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_traceback_cut_excludepath0')>
    def test_traceback_cut_excludepath(self, testdir):
        p = testdir.makepyfile("def f(): raise ValueError")
        excinfo = pytest.raises(ValueError, "p.pyimport().f()")
        basedir = py.path.local(pytest.__file__).dirpath()
        newtraceback = excinfo.traceback.cut(excludepath=basedir)
        for x in newtraceback:
            if hasattr(x, 'path'):
>               assert not py.path.local(x.path).relto(basedir)
E               AssertionError: assert not '_pytest/python_api.py'
E                +  where '_pytest/python_api.py' = <bound method LocalPath.relto of local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_traceback_cut_excludepath0/_pytest/python_api.py')>(local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_traceback_cut_excludepath0'))
E                +    where <bound method LocalPath.relto of local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_traceback_cut_excludepath0/_pytest/python_api.py')> = local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_traceback_cut_excludepath0/_pytest/python_api.py').relto
E                +      where local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_traceback_cut_excludepath0/_pytest/python_api.py') = <class 'py._path.local.LocalPath'>('_pytest/python_api.py')
E                +        where <class 'py._path.local.LocalPath'> = <ApiModule 'py.path'>.local
E                +          where <ApiModule 'py.path'> = py.path
E                +        and   '_pytest/python_api.py' = <TracebackEntry _pytest/python_api.py:580>.path
/home/travis/build/pytest-dev/pytest/testing/code/test_excinfo.py:171: AssertionError
________________ TestModule.test_show_traceback_import_error[0] ________________
[gw0] linux2 -- Python 2.7.6 /home/travis/build/pytest-dev/pytest/.tox/py27-xdist/bin/python2.7
self = <collect.TestModule object at 0x7fe3f4807d90>
testdir = <Testdir local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_show_traceback_import_error0')>
verbose = 0
    @pytest.mark.parametrize('verbose', [0, 1, 2])
    def test_show_traceback_import_error(self, testdir, verbose):
        """Import errors when collecting modules should display the traceback (#1976).
    
            With low verbosity we omit pytest and internal modules, otherwise show all traceback entries.
            """
        testdir.makepyfile(
            foo_traceback_import_error="""
                   from bar_traceback_import_error import NOT_AVAILABLE
               """,
            bar_traceback_import_error="",
        )
        testdir.makepyfile("""
                   import foo_traceback_import_error
            """)
        args = ('-v',) * verbose
        result = testdir.runpytest(*args)
        result.stdout.fnmatch_lines([
            "ImportError while importing test module*",
            "Traceback:",
            "*from bar_traceback_import_error import NOT_AVAILABLE",
            "*cannot import name *NOT_AVAILABLE*",
        ])
        assert result.ret == 2
    
        stdout = result.stdout.str()
        for name in ('_pytest', os.path.join('py', '_path')):
            if verbose == 2:
                assert name in stdout
            else:
>               assert name not in stdout
E               AssertionError: assert '_pytest' not in '=====================...=====================\n'
E                 '_pytest' is contained here:
E                   raceback:
E                   _pytest/python.py:395: in _importtestmodule
E                 ? +++++++
E                       ???
E                   _pytest/assertion/rewrite.py:212: in load_module
E                       py.builtin.exec_(co, mod.__dict__)...
E                 
E                 ...Full output truncated (8 lines hidden), use '-vv' to show
/home/travis/build/pytest-dev/pytest/testing/python/collect.py:108: AssertionError
----------------------------- Captured stdout call -----------------------------
============================= test session starts ==============================
platform linux2 -- Python 2.7.6, pytest-3.2.4.dev12+g087d4f7, py-1.4.34, pluggy-0.4.0
rootdir: /tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_show_traceback_import_error0, inifile:
plugins: xdist-1.20.1, forked-0.2, hypothesis-3.33.0
collected 0 items / 1 errors
==================================== ERRORS ====================================
_____________ ERROR collecting test_show_traceback_import_error.py _____________
ImportError while importing test module '/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_show_traceback_import_error0/test_show_traceback_import_error.py'.
Hint: make sure your test modules/packages have valid Python names.
Traceback:
_pytest/python.py:395: in _importtestmodule
    ???
_pytest/assertion/rewrite.py:212: in load_module
    py.builtin.exec_(co, mod.__dict__)
test_show_traceback_import_error.py:1: in <module>
    import foo_traceback_import_error
foo_traceback_import_error.py:1: in <module>
    from bar_traceback_import_error import NOT_AVAILABLE
E   ImportError: cannot import name NOT_AVAILABLE
!!!!!!!!!!!!!!!!!!! Interrupted: 1 errors during collection !!!!!!!!!!!!!!!!!!!!
=========================== 1 error in 0.25 seconds ============================
________________ TestModule.test_show_traceback_import_error[1] ________________
[gw0] linux2 -- Python 2.7.6 /home/travis/build/pytest-dev/pytest/.tox/py27-xdist/bin/python2.7
self = <collect.TestModule object at 0x7fe3f67ef150>
testdir = <Testdir local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_show_traceback_import_error1')>
verbose = 1
    @pytest.mark.parametrize('verbose', [0, 1, 2])
    def test_show_traceback_import_error(self, testdir, verbose):
        """Import errors when collecting modules should display the traceback (#1976).
    
            With low verbosity we omit pytest and internal modules, otherwise show all traceback entries.
            """
        testdir.makepyfile(
            foo_traceback_import_error="""
                   from bar_traceback_import_error import NOT_AVAILABLE
               """,
            bar_traceback_import_error="",
        )
        testdir.makepyfile("""
                   import foo_traceback_import_error
            """)
        args = ('-v',) * verbose
        result = testdir.runpytest(*args)
        result.stdout.fnmatch_lines([
            "ImportError while importing test module*",
            "Traceback:",
            "*from bar_traceback_import_error import NOT_AVAILABLE",
            "*cannot import name *NOT_AVAILABLE*",
        ])
        assert result.ret == 2
    
        stdout = result.stdout.str()
        for name in ('_pytest', os.path.join('py', '_path')):
            if verbose == 2:
                assert name in stdout
            else:
>               assert name not in stdout
E               AssertionError: assert '_pytest' not in '=====================...=====================\n'
E                 '_pytest' is contained here:
E                   raceback:
E                   _pytest/python.py:395: in _importtestmodule
E                 ? +++++++
E                       ???
E                   _pytest/assertion/rewrite.py:212: in load_module
E                       py.builtin.exec_(co, mod.__dict__)...
E                 
E                 ...Full output truncated (8 lines hidden), use '-vv' to show
/home/travis/build/pytest-dev/pytest/testing/python/collect.py:108: AssertionError
----------------------------- Captured stdout call -----------------------------
============================= test session starts ==============================
platform linux2 -- Python 2.7.6, pytest-3.2.4.dev12+g087d4f7, py-1.4.34, pluggy-0.4.0 -- /home/travis/build/pytest-dev/pytest/.tox/py27-xdist/bin/python2.7
cachedir: .cache
rootdir: /tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_show_traceback_import_error1, inifile:
plugins: xdist-1.20.1, forked-0.2, hypothesis-3.33.0
collecting ... collected 0 items / 1 errors
==================================== ERRORS ====================================
_____________ ERROR collecting test_show_traceback_import_error.py _____________
ImportError while importing test module '/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_show_traceback_import_error1/test_show_traceback_import_error.py'.
Hint: make sure your test modules/packages have valid Python names.
Traceback:
_pytest/python.py:395: in _importtestmodule
    ???
_pytest/assertion/rewrite.py:212: in load_module
    py.builtin.exec_(co, mod.__dict__)
test_show_traceback_import_error.py:1: in <module>
    import foo_traceback_import_error
foo_traceback_import_error.py:1: in <module>
    from bar_traceback_import_error import NOT_AVAILABLE
E   ImportError: cannot import name NOT_AVAILABLE
!!!!!!!!!!!!!!!!!!! Interrupted: 1 errors during collection !!!!!!!!!!!!!!!!!!!!
=========================== 1 error in 0.20 seconds ============================
_________________ TestTracebackCutting.test_traceback_argsetup _________________
[gw0] linux2 -- Python 2.7.6 /home/travis/build/pytest-dev/pytest/.tox/py27-xdist/bin/python2.7
self = <collect.TestTracebackCutting object at 0x7fe3f1b796d0>
testdir = <Testdir local('/tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_traceback_argsetup0')>
    def test_traceback_argsetup(self, testdir):
        testdir.makeconftest("""
                import pytest
    
                @pytest.fixture
                def hello(request):
                    raise ValueError("xyz")
            """)
        p = testdir.makepyfile("def test(hello): pass")
        result = testdir.runpytest(p)
        assert result.ret != 0
        out = result.stdout.str()
        assert "xyz" in out
        assert "conftest.py:5: ValueError" in out
        numentries = out.count("_ _ _")  # separator for traceback entries
>       assert numentries == 0
E       assert 26 == 0
/home/travis/build/pytest-dev/pytest/testing/python/collect.py:966: AssertionError
----------------------------- Captured stdout call -----------------------------
============================= test session starts ==============================
platform linux2 -- Python 2.7.6, pytest-3.2.4.dev12+g087d4f7, py-1.4.34, pluggy-0.4.0
rootdir: /tmp/pytest-of-travis/pytest-0/popen-gw0/testdir/test_traceback_argsetup0, inifile:
plugins: xdist-1.20.1, forked-0.2, hypothesis-3.33.0
collected 1 item
test_traceback_argsetup.py E
==================================== ERRORS ====================================
____________________________ ERROR at setup of test ____________________________
self = <CallInfo when='setup' exception: xyz>
func = <function <lambda> at 0x7fe3f4b94488>, when = 'setup'
    def __init__(self, func, when):
        #: context of invocation: one of "setup", "call",
        #: "teardown", "memocollect"
        self.when = when
        self.start = time()
        try:
>           self.result = func()
_pytest/runner.py:196: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
_pytest/runner.py:182: in <lambda>
    return CallInfo(lambda: ihook(item=item, **kwds), when=when)
_pytest/vendored_packages/pluggy.py:745: in __call__
    return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
_pytest/vendored_packages/pluggy.py:339: in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
_pytest/vendored_packages/pluggy.py:302: in __call__
    return outcome.get_result()
_pytest/vendored_packages/pluggy.py:280: in get_result
    _reraise(*ex)  # noqa
_pytest/vendored_packages/pluggy.py:265: in __init__
    self.result = func()
_pytest/vendored_packages/pluggy.py:300: in <lambda>
    outcome = _CallOutcome(lambda: self.oldcall(hook, hook_impls, kwargs))
_pytest/vendored_packages/pluggy.py:334: in <lambda>
    _MultiCall(methods, kwargs, hook.spec_opts).execute()
_pytest/vendored_packages/pluggy.py:613: in execute
    return _wrapped_call(hook_impl.function(*args), self.execute)
_pytest/vendored_packages/pluggy.py:254: in _wrapped_call
    return call_outcome.get_result()
_pytest/vendored_packages/pluggy.py:280: in get_result
    _reraise(*ex)  # noqa
_pytest/vendored_packages/pluggy.py:265: in __init__
    self.result = func()
_pytest/vendored_packages/pluggy.py:614: in execute
    res = hook_impl.function(*args)
_pytest/runner.py:106: in pytest_runtest_setup
    item.session._setupstate.prepare(item)
_pytest/runner.py:500: in prepare
    col.setup()
_pytest/python.py:1173: in setup
    ???
_pytest/fixtures.py:243: in fillfixtures
    ???
_pytest/fixtures.py:386: in _fillfixtures
    ???
_pytest/fixtures.py:428: in getfixturevalue
    ???
_pytest/fixtures.py:454: in _get_active_fixturedef
    ???
_pytest/fixtures.py:519: in _getfixturevalue
    ???
_pytest/fixtures.py:788: in execute
    ???
_pytest/vendored_packages/pluggy.py:745: in __call__
    return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
_pytest/vendored_packages/pluggy.py:339: in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
_pytest/vendored_packages/pluggy.py:302: in __call__
    return outcome.get_result()
_pytest/vendored_packages/pluggy.py:280: in get_result
    _reraise(*ex)  # noqa
_pytest/vendored_packages/pluggy.py:265: in __init__
    self.result = func()
_pytest/vendored_packages/pluggy.py:300: in <lambda>
    outcome = _CallOutcome(lambda: self.oldcall(hook, hook_impls, kwargs))
_pytest/vendored_packages/pluggy.py:334: in <lambda>
    _MultiCall(methods, kwargs, hook.spec_opts).execute()
_pytest/vendored_packages/pluggy.py:613: in execute
    return _wrapped_call(hook_impl.function(*args), self.execute)
_pytest/vendored_packages/pluggy.py:254: in _wrapped_call
    return call_outcome.get_result()
_pytest/vendored_packages/pluggy.py:280: in get_result
    _reraise(*ex)  # noqa
_pytest/vendored_packages/pluggy.py:265: in __init__
    self.result = func()
_pytest/vendored_packages/pluggy.py:614: in execute
    res = hook_impl.function(*args)
_pytest/fixtures.py:819: in pytest_fixture_setup
    ???
_pytest/fixtures.py:713: in call_fixture_func
    ???
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
request = <SubRequest 'hello' for <Function 'test'>>
    @pytest.fixture
    def hello(request):
>       raise ValueError("xyz")
E       ValueError: xyz
conftest.py:5: ValueError
=========================== 1 error in 0.51 seconds ============================
======= 4 failed, 1847 passed, 60 skipped, 13 xfailed in 166.74 seconds ========

[nicoddemus]

I took a few minutes today to investigate this, and the reason seems to in the traceback filtering function.

pytest/_pytest/python.py

Lines 29 to 49 in b61cbc4

	cutdir1 = py.path.local(pluggy.__file__.rstrip("oc"))
	cutdir2 = py.path.local(_pytest.__file__).dirpath()
	cutdir3 = py.path.local(py.__file__).dirpath()
	def filter_traceback(entry):
	"""Return True if a TracebackEntry instance should be removed from tracebacks:
	* dynamically generated code (no code to show up for it);
	* internal traceback from pytest or its internal libraries, py and pluggy.
	"""
	# entry.path might sometimes return a str object when the entry
	# points to dynamically generated code
	# see https://bitbucket.org/pytest-dev/py/issues/71
	raw_filename = entry.frame.code.raw.co_filename
	is_generated = '<' in raw_filename and '>' in raw_filename
	if is_generated:
	return False
	# entry.path might point to an inexisting file, in which case it will
	# alsso return a str object. see #1133
	p = py.path.local(entry.path)
	return p != cutdir1 and not p.relto(cutdir2) and not p.relto(cutdir3)

I've changed the function to log the paths to a file:

diff --git a/_pytest/python.py b/_pytest/python.py
index 6c130f9..8b9a962 100644
--- a/_pytest/python.py
+++ b/_pytest/python.py
@@ -43,9 +43,16 @@ def filter_traceback(entry):
     is_generated = '<' in raw_filename and '>' in raw_filename
     if is_generated:
         return False
-    # entry.path might point to an inexisting file, in which case it will
-    # alsso return a str object. see #1133
+    # entry.path might point to an non-existing file, in which case it will
+    # also return a str object. see #1133
     p = py.path.local(entry.path)
+    with open(r'C:\pytest\log.txt', 'a') as f:
+        f.write('filter_traceback\n')
+        f.write('p = {} {!r}\n'.format(p, p))
+        f.write('  _pytest = {}\n'.format(_pytest.__file__))
+        f.write('  cutdir1 = {} {!r}\n'.format(cutdir1, cutdir1))
+        f.write('  cutdir2 = {} {!r}\n'.format(cutdir2, cutdir2))
+        f.write('  cutdir3 = {} {!r}\n'.format(cutdir3, cutdir3))
     return p != cutdir1 and not p.relto(cutdir2) and not p.relto(cutdir3)

And here is what I get for the first call of the testing\python\collect.py::test_traceback_argsetup test:

py27 normal

$ tox -e py27 -- testing\python\collect.py::TestTracebackCutting::test_traceback_argsetup

filter_traceback
p = C:\pytest\_pytest\runner.py local('C:\\pytest\\_pytest\\runner.py')
  _pytest = C:\pytest\_pytest\__init__.pyc
  cutdir1 = C:\pytest\_pytest\_pluggy.py local('C:\\pytest\\_pytest\\_pluggy.py')
  cutdir2 = C:\pytest\_pytest local('C:\\pytest\\_pytest')
  cutdir3 = C:\pytest\.env27\lib\site-packages\py local('C:\\pytest\\.env27\\lib\\site-packages\\py')

py27-xdist

$ tox -e py27-xdist -- testing\python\collect.py::TestTracebackCutting::test_traceback_argsetup

filter_traceback
  p = c:\users\bruno\appdata\local\temp\pytest-of-Bruno\pytest-836\popen-gw0\testdir\test_traceback_argsetup0\_pytest\runner.py local('c:\\users\\bruno\\appdata\\local\\temp\\pytest-of-Bruno\\pytest-836\\popen-gw0\\testdir\\test_traceback_argsetup0\\_pytest\\runner.py')
  cutdir1 = C:\pytest\_pytest\_pluggy.py local('C:\\pytest\\_pytest\\_pluggy.py')
  cutdir2 = C:\pytest\_pytest local('C:\\pytest\\_pytest')
  cutdir3 = c:\pytest\.tox\py27-xdist\lib\site-packages\py local('c:\\pytest\\.tox\\py27-xdist\\lib\\site-packages\\py')

py36 normal

$ tox -e py36 -- testing\python\collect.py::TestTracebackCutting::test_traceback_argsetup

filter_traceback
  p = c:\pytest\_pytest\runner.py local('c:\\pytest\\_pytest\\runner.py')
  cutdir1 = c:\pytest\_pytest\_pluggy.py local('c:\\pytest\\_pytest\\_pluggy.py')
  cutdir2 = c:\pytest\_pytest local('c:\\pytest\\_pytest')
  cutdir3 = c:\pytest\.env36\lib\site-packages\py local('c:\\pytest\\.env36\\lib\\site-packages\\py')

py36 xdist

$ tox -e py36-xdist -- testing\python\collect.py::TestTracebackCutting::test_traceback_argsetup

filter_traceback
  p = C:\pytest\_pytest\runner.py local('C:\\pytest\\_pytest\\runner.py')
  cutdir1 = C:\pytest\_pytest\_pluggy.py local('C:\\pytest\\_pytest\\_pluggy.py')
  cutdir2 = C:\pytest\_pytest local('C:\\pytest\\_pytest')
  cutdir3 = c:\pytest\.tox\py36-xdist\lib\site-packages\py local('c:\\pytest\\.tox\\py36-xdist\\lib\\site-packages\\py')

I'm posting this to see if anybody has an idea and for my own future reference.

[RonnyPfannschmidt]

@nicoddemus just a note, pluggy is a package by now and on top of features

[nicoddemus]

Thanks, I also realized that. But I don't have an explanation why the paths are relative to testdir on py27-xdist though, hopefully I will have some more time to investigate later.

[RonnyPfannschmidt]

its potentially related to execnet and the subprocesses