Problem printing or storing longrepr when using pytest-xdist (introduced in 1.18.0)

[mikeage]

Hi,

I currently have the following code, which works with pytest-xdist 1.17.1, but broken in 1.18.0, when running with -nX where X > 0. With X=0, or without -n at all, it works in all versions.

test_foo.py:

def test_fail():
    assert False

conftest.py:

def pytest_runtest_logreport(report):
    print report.longrepr # Sample code; I'm really trying to collect a string representation of the traceback to report later

With 1.18.0 or higher, I get the following error (this log was from 1.20.1):

 py.test -n1
=============================================================================================== test session starts ================================================================================================
platform darwin -- Python 2.7.14, pytest-3.2.3, py-1.4.34, pluggy-0.4.0
rootdir: /Users/mikemi/pytest_xdist_bug, inifile:
plugins: xdist-1.20.1, forked-0.2
gw0 [2]
scheduling tests via LoadScheduling
None
.None
None
None
INTERNALERROR> Traceback (most recent call last):
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/main.py", line 110, in wrap_session
INTERNALERROR>     session.exitstatus = doit(config, session) or 0
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/main.py", line 146, in _main
INTERNALERROR>     config.hook.pytest_runtestloop(session=session)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
INTERNALERROR>     _MultiCall(methods, kwargs, hook.spec_opts).execute()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 614, in execute
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "<remote exec>", line 66, in pytest_runtestloop
INTERNALERROR>   File "<remote exec>", line 82, in run_one_test
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
INTERNALERROR>     _MultiCall(methods, kwargs, hook.spec_opts).execute()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 613, in execute
INTERNALERROR>     return _wrapped_call(hook_impl.function(*args), self.execute)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 254, in _wrapped_call
INTERNALERROR>     return call_outcome.get_result()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 280, in get_result
INTERNALERROR>     _reraise(*ex)  # noqa
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 265, in __init__
INTERNALERROR>     self.result = func()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 613, in execute
INTERNALERROR>     return _wrapped_call(hook_impl.function(*args), self.execute)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 254, in _wrapped_call
INTERNALERROR>     return call_outcome.get_result()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 280, in get_result
INTERNALERROR>     _reraise(*ex)  # noqa
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 265, in __init__
INTERNALERROR>     self.result = func()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 614, in execute
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/runner.py", line 68, in pytest_runtest_protocol
INTERNALERROR>     runtestprotocol(item, nextitem=nextitem)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/runner.py", line 82, in runtestprotocol
INTERNALERROR>     reports.append(call_and_report(item, "call", log))
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/runner.py", line 166, in call_and_report
INTERNALERROR>     hook.pytest_runtest_logreport(report=report)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
INTERNALERROR>     _MultiCall(methods, kwargs, hook.spec_opts).execute()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 614, in execute
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/conftest.py", line 2, in pytest_runtest_logreport
INTERNALERROR>     print report.longrepr
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/_code/code.py", line 694, in __str__
INTERNALERROR>     s = self.__unicode__()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/_code/code.py", line 704, in __unicode__
INTERNALERROR>     self.toterminal(tw)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/_code/code.py", line 749, in toterminal
INTERNALERROR>     self.reprtraceback.toterminal(tw)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/_code/code.py", line 764, in toterminal
INTERNALERROR>     if entry.style == "long":
INTERNALERROR> AttributeError: 'dict' object has no attribute 'style'
Fdef test_fail():
>       assert False
E       assert False

test_xdist.py:5: AssertionError
INTERNALERROR> Traceback (most recent call last):
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/main.py", line 110, in wrap_session
INTERNALERROR>     session.exitstatus = doit(config, session) or 0
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/main.py", line 146, in _main
INTERNALERROR>     config.hook.pytest_runtestloop(session=session)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
INTERNALERROR>     _MultiCall(methods, kwargs, hook.spec_opts).execute()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 614, in execute
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/xdist/dsession.py", line 114, in pytest_runtestloop
INTERNALERROR>     self.loop_once()
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/xdist/dsession.py", line 137, in loop_once
INTERNALERROR>     call(**kwargs)
INTERNALERROR>   File "/Users/mikemi/pytest_xdist_bug/.venv/lib/python2.7/site-packages/xdist/dsession.py", line 175, in slave_slavefinished
INTERNALERROR>     assert not crashitem, (crashitem, node)
INTERNALERROR> AssertionError: ('test_xdist.py::test_fail', <SlaveController gw0>)
INTERNALERROR> assert not 'test_xdist.py::test_fail'

======================================================================================== 1 failed, 1 passed in 0.55 seconds ========================================================================================

Is there a better way to get a traceback when using pytest-xdist? (note that in my real code, I filter on report.failed and report.when as well; the snippet above is just a minimal case to demonstrate the basic concept)

[RonnyPfannschmidt]

at first glance this looks like a artefact of the recently introduced support for serialized tracebacks

[mikeage]

It's tagged "needs information" -- is there anything you need from me?

[RonnyPfannschmidt]

whops, actually not, thanks for the note

[timyhou]

Do you guys want me to take a look?

[nicoddemus]

@timyhou that would be great, thanks for the offer!

[timyhou]

It took a bit but I narrowed down what was happening.

On one thread longrepr.reprtraceback.reprentries was not unserialized fully. It is still in the form as a list of dictionaries. The strange thing is that the rest of the longrepr is unserialized, just not the reprentries portion. In the stack, this thread is the one which is touching the hook pytest_runtest_logreport which I copied from the OP's example. I figure its a 50/50 chance that this one is the slave?

The other thread is unserialized as expected. This makes me feel that something is out of sync between the slave and the master.

[timyhou]

My initial guess was totally wrong. The issue is in the serialize_report method. It will actually mutate the initial report.longrepr object seen here.

I can fix this by doing a deepcopy at line 114 and 115. We can't deepcopy the entire report because of SlaveController. Incidentally this breaks a few tests because of equality, so I have to tweak a few testsDoes this sound like a reasonable approach?

[RonnyPfannschmidt]

at first glance, just copy the dict contents shallow, as far as i can tel lthe mutation is shallow as well

and put a comment on it just to be sure that nobody missunderstands

[mikeage]

I assume you know from your testing, but I just wanted to confirm from my side that this completely resolves the issue (I meant to do so back when the merge was done, but I only remembered when the new release came out). Thank you!