Pytest: Pytest internal error due to infinite recursion on final test

[ceridwen]

The exact logging output with some environment variables specific to our setup snipped:

10:18:20 ============================= test session starts ==============================
10:18:20 platform linux -- Python 3.6.3, pytest-3.2.0, py-1.5.2, pluggy-0.4.0
10:18:20 metadata: {'Python': '3.6.3', 'Platform': 'Linux-3.10.0-327.36.3.el7.x86_64-x86_64-with', 'Packages': {'pytest': '3.2.0', 'py': '1.5.2', 'pluggy': '0.4.0'}, 'Plugins': {'metadata': '1.5.1', 'html': '1.16.1'}}
10:18:20 rootdir: /, inifile:
10:18:20 plugins: metadata-1.5.1, html-1.16.1
10:18:20 collected 221 items
10:18:20 
16:14:04 test_datapath.py FFFFFFFFFF..........F
16:15:57 test_deployment.py .
16:17:44 test_kubernetes.py ...................................................XXX..........ssss.......
16:38:32 test_policy_1_7.py ..F
16:38:32 test_resilience.py ...
16:38:54 test_robs.py ..
20:06:00 test_datapath.py FFFFFFFFFF..........F
20:08:08 test_deployment.py .
20:08:56 test_kubernetes.py ...................................................XXX..........ssss.......
20:24:58 test_policy_1_7.py FFF
20:24:58 test_resilience.py ...
20:31:15 test_robs.py FF
23:54:46 test_scale.py .F.F
23:54:46 INTERNALERROR> Traceback (most recent call last):
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/main.py", line 110, in wrap_session
23:54:46 INTERNALERROR>     session.exitstatus = doit(config, session) or 0
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/main.py", line 146, in _main
23:54:46 INTERNALERROR>     config.hook.pytest_runtestloop(session=session)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
23:54:46 INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
23:54:46 INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
23:54:46 INTERNALERROR>     _MultiCall(methods, kwargs, hook.spec_opts).execute()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 614, in execute
23:54:46 INTERNALERROR>     res = hook_impl.function(*args)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/main.py", line 169, in pytest_runtestloop
23:54:46 INTERNALERROR>     item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
23:54:46 INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
23:54:46 INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
23:54:46 INTERNALERROR>     _MultiCall(methods, kwargs, hook.spec_opts).execute()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 613, in execute
23:54:46 INTERNALERROR>     return _wrapped_call(hook_impl.function(*args), self.execute)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 254, in _wrapped_call
23:54:46 INTERNALERROR>     return call_outcome.get_result()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 279, in get_result
23:54:46 INTERNALERROR>     raise ex[1].with_traceback(ex[2])
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 265, in __init__
23:54:46 INTERNALERROR>     self.result = func()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 613, in execute
23:54:46 INTERNALERROR>     return _wrapped_call(hook_impl.function(*args), self.execute)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 254, in _wrapped_call
23:54:46 INTERNALERROR>     return call_outcome.get_result()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 279, in get_result
23:54:46 INTERNALERROR>     raise ex[1].with_traceback(ex[2])
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 265, in __init__
23:54:46 INTERNALERROR>     self.result = func()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 614, in execute
23:54:46 INTERNALERROR>     res = hook_impl.function(*args)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/runner.py", line 67, in pytest_runtest_protocol
23:54:46 INTERNALERROR>     runtestprotocol(item, nextitem=nextitem)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/runner.py", line 83, in runtestprotocol
23:54:46 INTERNALERROR>     nextitem=nextitem))
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/runner.py", line 159, in call_and_report
23:54:46 INTERNALERROR>     report = hook.pytest_runtest_makereport(item=item, call=call)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
23:54:46 INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
23:54:46 INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
23:54:46 INTERNALERROR>     _MultiCall(methods, kwargs, hook.spec_opts).execute()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 613, in execute
23:54:46 INTERNALERROR>     return _wrapped_call(hook_impl.function(*args), self.execute)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 250, in _wrapped_call
23:54:46 INTERNALERROR>     wrap_controller.send(call_outcome)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/skipping.py", line 213, in pytest_runtest_makereport
23:54:46 INTERNALERROR>     rep = outcome.get_result()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 279, in get_result
23:54:46 INTERNALERROR>     raise ex[1].with_traceback(ex[2])
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 265, in __init__
23:54:46 INTERNALERROR>     self.result = func()
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/vendored_packages/pluggy.py", line 614, in execute
23:54:46 INTERNALERROR>     res = hook_impl.function(*args)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/runner.py", line 306, in pytest_runtest_makereport
23:54:46 INTERNALERROR>     style=item.config.option.tbstyle)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/python.py", line 576, in _repr_failure_py
23:54:46 INTERNALERROR>     style=style)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/main.py", line 476, in _repr_failure_py
23:54:46 INTERNALERROR>     style=style, tbfilter=tbfilter)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/_code/code.py", line 435, in getrepr
23:54:46 INTERNALERROR>     return fmt.repr_excinfo(self)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/_code/code.py", line 669, in repr_excinfo
23:54:46 INTERNALERROR>     reprtraceback = self.repr_traceback(excinfo)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/_code/code.py", line 621, in repr_traceback
23:54:46 INTERNALERROR>     reprentry = self.repr_traceback_entry(entry, einfo)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/_code/code.py", line 581, in repr_traceback_entry
23:54:46 INTERNALERROR>     s = self.get_source(source, line_index, excinfo, short=short)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/_code/code.py", line 526, in get_source
23:54:46 INTERNALERROR>     lines.extend(self.get_exconly(excinfo, indent=indent, markall=True))
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/_code/code.py", line 533, in get_exconly
23:54:46 INTERNALERROR>     exlines = excinfo.exconly(tryshort=True).split('\n')
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/site-packages/_pytest/_code/code.py", line 398, in exconly
23:54:46 INTERNALERROR>     lines = format_exception_only(self.type, self.value)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/traceback.py", line 136, in format_exception_only
23:54:46 INTERNALERROR>     return list(TracebackException(etype, value, None).format_exception_only())
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/traceback.py", line 486, in __init__
23:54:46 INTERNALERROR>     _seen=_seen)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/traceback.py", line 486, in __init__
23:54:46 INTERNALERROR>     _seen=_seen)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/traceback.py", line 486, in __init__
23:54:46 INTERNALERROR>     _seen=_seen)
23:54:46 INTERNALERROR>   [Previous line repeated 228 more times]
23:54:46 INTERNALERROR> RecursionError: maximum recursion depth exceeded while calling a Python object
23:54:46 
23:54:46 ============================== 6 tests deselected ==============================
23:54:46  30 failed, 170 passed, 8 skipped, 6 deselected, 6 xpassed in 48986.49 seconds =

There are five tests in that last file:

collected 5 items
<Module 'test_scale.py'>
  <Class 'TestMultipleServicesOneBackend'>
    <Instance '()'>
      <Function 'test_ips[namespace0-networking_pods0-networking_services0]'>
      <Function 'test_routing[namespace0-networking_pods0-networking_services0]'>
  <Function 'test_pods[namespace0-new_networking_pods0-new_networking_service0]'>
  <Function 'test_reprovision1[robs_test0]'>
  <Function 'test_reprovision2[robs_test0]'>

The last two tests are identical. They share a fixture that uses contextlib.ExitStack. They've been run many, many times before and I've never seen this happen.

Pytest in this case is running inside a Docker container on a Jenkins server. The container is based on python:3.6-alpine and has the following packages:

boltons (17.2.0)
cachetools (2.0.1)
certifi (2018.1.18)
chardet (3.0.4)
ConfigArgParse (0.12.0)
decorator (4.2.1)
dictdiffer (0.7.0)
docker (2.7.0)
docker-pycreds (0.2.1)
dpath (1.4.2)
google-auth (1.3.0)
idna (2.6)
ipaddress (1.0.19)
Jinja2 (2.10)
jsonschema (2.6.0)
kubernetes (4.0.0)
MarkupSafe (1.0)
networkx (2.1)
oauthlib (2.0.6)
openshift (0.4.0a1)
pip (9.0.1)
plumbum (1.6.5)
py (1.5.2)
pyasn1 (0.4.2)
pyasn1-modules (0.2.1)
pytest (3.2.0)
pytest-html (1.16.1)
pytest-metadata (1.5.1)
python-dateutil (2.6.1)
python-string-utils (0.6.0)
PyYAML (3.12)
requests (2.18.4)
requests-oauthlib (0.8.0)
rsa (3.4.2)
ruamel.yaml (0.15.35)
setuptools (36.6.0)
six (1.11.0)
swagger-parser (1.0.0)
swagger-spec-validator (2.1.0)
urllib3 (1.22)
websocket-client (0.46.0)
wheel (0.30.0)

I can try to rerun the exact job that failed with debugging settings if that would help.

[nicoddemus]

Looking at the traceback it indeed seems there is a recursion inside the traceback.format_exception_only method of the standard library:

23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/traceback.py", line 136, in format_exception_only
23:54:46 INTERNALERROR>     return list(TracebackException(etype, value, None).format_exception_only())
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/traceback.py", line 486, in __init__
23:54:46 INTERNALERROR>     _seen=_seen)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/traceback.py", line 486, in __init__
23:54:46 INTERNALERROR>     _seen=_seen)
23:54:46 INTERNALERROR>   File "/usr/local/lib/python3.6/traceback.py", line 486, in __init__
23:54:46 INTERNALERROR>     _seen=_seen)
23:54:46 INTERNALERROR>   [Previous line repeated 228 more times]
23:54:46 INTERNALERROR> RecursionError: maximum recursion depth exceeded while calling a Python object

What options are you passing to pytest? What happens if you pass --tb=native?

Also if you can produce a reproducible case it would be great.

[ceridwen]

The exact options passed to pytest.main were: ['-k', 'not policy_1_6', '--junitxml', 'report.xml', '.'], not including some options set with pytest_addotoption. I will try rerunning this with --tb=native, though I haven't seen this error again so I can't really begin to guess at a reproducible cause.

[nicoddemus]

@ceridwen OK thanks.

Here's some code inside pytest which tries to find recursions in tracebacks:

https://github.com/pytest-dev/pytest/blob/89a55d85a9d30ef2a2394b3969fc7067f1c15b59/_pytest/_code/code.py#L329-L351

Your traceback seems to occur inside the builtin format_exception_only though, I'm just posting this here in case it helps you understand what might be causing this.

[ceridwen]

I took a look at the Python 3.6 bugs and changelog, so if this is a bug in CPython, it doesn't seem to have been reported before. My best guess, though, is that pytest somehow created a traceback with a loop in it, and that when format_exception_only tries to print tracebacks with loops, it infinitely recurses. Is it possible that could happen if pytest receives SIGTERM or some such?

The tests take a long time to run, so I don't have results yet. If the error doesn't show up that will at least tell me it's nondeterministic.