Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Pytest internal error due to infinite recursion on final test #3163

Closed
ceridwen opened this issue Jan 29, 2018 · 4 comments
Closed

Pytest internal error due to infinite recursion on final test #3163

ceridwen opened this issue Jan 29, 2018 · 4 comments
Labels
status: needs information reporter needs to provide more information; can be closed after 2 or more weeks of inactivity topic: reporting related to terminal output and user-facing messages and errors type: bug problem that needs to be addressed

Comments

@ceridwen
Copy link
Contributor

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.
@pytestbot pytestbot added the type: bug problem that needs to be addressed label Jan 29, 2018
@nicoddemus
Copy link
Member

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.

@nicoddemus nicoddemus added topic: reporting related to terminal output and user-facing messages and errors status: needs information reporter needs to provide more information; can be closed after 2 or more weeks of inactivity labels Jan 31, 2018
@ceridwen
Copy link
Contributor Author

ceridwen commented Jan 31, 2018 •
edited
Loading

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
Copy link
Member

@ceridwen OK thanks.

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

pytest/_pytest/_code/code.py

Lines 329 to 351 in 89a55d8

def recursionindex(self):
""" return the index of the frame/TracebackEntry where recursion
originates if appropriate, None if no recursion occurred
"""
cache = {}
for i, entry in enumerate(self):
# id for the code.raw is needed to work around
# the strange metaprogramming in the decorator lib from pypi
# which generates code objects that have hash/value equality
# XXX needs a test
key = entry.frame.code.path, id(entry.frame.code.raw), entry.lineno
# print "checking for recursion at", key
values = cache.setdefault(key, [])
if values:
f = entry.frame
loc = f.f_locals
for otherloc in values:
if f.is_true(f.eval(co_equal,
__recursioncache_locals_1=loc,
__recursioncache_locals_2=otherloc)):
return i
values.append(entry.frame.f_locals)
return None

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
Copy link
Contributor Author

ceridwen commented Feb 1, 2018

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.

@pytestbot pytestbot mentioned this issue Mar 27, 2018
Closed
4 tasks
@pytestbot pytestbot mentioned this issue Jun 8, 2018
Closed
@The-Compiler The-Compiler mentioned this issue Jan 22, 2025
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
status: needs information reporter needs to provide more information; can be closed after 2 or more weeks of inactivity topic: reporting related to terminal output and user-facing messages and errors type: bug problem that needs to be addressed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@nicoddemus @ceridwen @pytestbot