Terminal output fails with faulthandler + eventlet

[tomviner]

There seems to be an issue with Pytest 5 when testing codebases using eventlet. It only happens when faulthandler is enabled (now the default).

I first saw the issue when running tests against my Nameko service, and it prevented me from seeing my test failures, because the output was truncated.

I narrowed down the reproduction case to just running pytest --help. The effect is to truncate the terminal output, with the following error message sometimes interspersed near the end of wherever the output got up to:

Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>
BlockingIOError: [Errno 35] write could not complete without blocking

this is clearly a race condition, as this error can appear in random parts of the output, and only some of the time. However I did manage to force a similar error to be displayed, via pytest --help | cat which ended with:

Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>
BrokenPipeError: [Errno 32] Broken pipe

To reproduce:

pip install 'pytest>=5.0' eventlet

conftest.py:

def pytest_configure():
    # make sure we monkey_patch before `--help` is run
    import eventlet
    eventlet.monkey_patch()

Random truncation of output:

pytest --help

some of the time this includes the BlockingIOError above.

To force the error:

pytest --help | cat
usage: pytest [options] [file_or_dir] [file_or_dir] [...]

positional arguments:
  file_or_dir

general:
  -k EXPRESSION         only run tests which match the given substring
...
                        'extra_keyword_matcTraceback (most recent call last):
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/bin/pytest", line 10, in <module>
    sys.exit(main())
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/_pytest/config/__init__.py", line 74, in main
    return config.hook.pytest_cmdline_main(config=config)
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/pluggy/hooks.py", line 289, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/pluggy/manager.py", line 87, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/pluggy/manager.py", line 81, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/pluggy/callers.py", line 208, in _multicall
    return outcome.get_result()
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/pluggy/callers.py", line 80, in get_result
    raise ex[1].with_traceback(ex[2])
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/_pytest/helpconfig.py", line 134, in pytest_cmdline_main
    showhelp(config)
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/_pytest/helpconfig.py", line 179, in showhelp
    tw.line(wrapped[0])
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/py/_io/terminalwriter.py", line 273, in line
    self.write('\n')
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/py/_io/terminalwriter.py", line 256, in write
    write_out(self._file, markupmsg)
  File "/Users/me/.virtualenvs/eventlet-pytest-bug/lib/python3.7/site-packages/py/_io/terminalwriter.py", line 421, in write_out
    fil.flush()
BrokenPipeError: [Errno 32] Broken pipe
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>
BrokenPipeError: [Errno 32] Broken pipe

There's no error without faulthandler enabled:

pytest -p no:faulthandler --help | cat
<entire help message shown>

No error before pytest 5:

pip install 'pytest<=5'
pytest --help | cat
<entire help message shown>

I can only reproduce this on OSX. Could not reproduce on Ubuntu. Seems to be independent of Python version and eventlet version. I git bisected the first pytest commit to have the issue, and found a37b902afea216216 where pytest-faulthandler was integrated into pytest. But I could not find an automated method to detect the failure, as I needed the real terminal for the issue to show itself.

My setup:
platform darwin -- Python 3.7.4, pytest-5.0.1, py-1.8.0, pluggy-0.12.0

[asottile]

I can't reproduce:

$ pip freeze -l
atomicwrites==1.3.0
attrs==19.1.0
dnspython==1.16.0
eventlet==0.25.0
greenlet==0.4.15
importlib-metadata==0.19
monotonic==1.5
more-itertools==7.2.0
packaging==19.1
pluggy==0.12.0
py==1.8.0
pyparsing==2.4.2
pytest==5.0.1
six==1.12.0
wcwidth==0.1.7
zipp==0.5.2

platform linux -- Python 3.7.4, pytest-5.0.1, py-1.8.0, pluggy-0.12.0

[asottile]

seems specific to macos, I can reproduce there

[mitzkia]

While I am playing with hypothesis and pytest I have got almost the same backtrace (I believe), please correct me if I am wrong.
My environment is an Ubuntu docker image.
Unfortunately I can not reproduce this issue constantly.

$ lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 18.04.3 LTS
Release:	18.04
Codename:	bionic

Trying example: test_source_format_string(request=<FixtureRequest for <Function test_source_format_string>>, tested_value_1='')
Traceback (most recent call last):
  File "/source/tests/python_functional/syslog_ng_tests/property_based/sourcTraceback (most recent call last):
  File "scripts/run_property_based_tests.py", line 784, in <module>
    exit(main())
  File "scripts/run_property_based_tests.py", line 780, in main
    run_property_based_tests(args.installdir)
  File "scripts/run_property_based_tests.py", line 771, in run_property_based_tests
    pytest.main(shlex.split(start_pytest_cmd))
  File "/usr/local/lib/python3.6/dist-packages/_pytest/config/__init__.py", line 90, in main
    return config.hook.pytest_cmdline_main(config=config)
  File "/usr/local/lib/python3.6/dist-packages/pluggy/hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/usr/local/lib/python3.6/dist-packages/pluggy/manager.py", line 92, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/usr/local/lib/python3.6/dist-packages/pluggy/manager.py", line 86, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/usr/local/lib/python3.6/dist-packages/pluggy/callers.py", line 208, in _multicall
    return outcome.get_result()
  File "/usr/local/lib/python3.6/dist-packages/pluggy/callers.py", line 80, in get_result
    raise ex[1].with_traceback(ex[2])
  File "/usr/local/lib/python3.6/dist-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/usr/local/lib/python3.6/dist-packages/_pytest/main.py", line 228, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "/usr/local/lib/python3.6/dist-packages/_pytest/main.py", line 221, in wrap_session
    session=session, exitstatus=session.exitstatus
  File "/usr/local/lib/python3.6/dist-packages/pluggy/hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/usr/local/lib/python3.6/dist-packages/pluggy/manager.py", line 92, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/usr/local/lib/python3.6/dist-packages/pluggy/manager.py", line 86, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/usr/local/lib/python3.6/dist-packages/pluggy/callers.py", line 203, in _multicall
    gen.send(outcome)
  File "/usr/local/lib/python3.6/dist-packages/_pytest/terminal.py", line 661, in pytest_sessionfinish
    terminalreporter=self, exitstatus=exitstatus, config=self.config
  File "/usr/local/lib/python3.6/dist-packages/pluggy/hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/usr/local/lib/python3.6/dist-packages/pluggy/manager.py", line 92, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/usr/local/lib/python3.6/dist-packages/pluggy/manager.py", line 86, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/usr/local/lib/python3.6/dist-packages/pluggy/callers.py", line 208, in _multicall
    return outcome.get_result()
  File "/usr/local/lib/python3.6/dist-packages/pluggy/callers.py", line 80, in get_result
    raise ex[1].with_traceback(ex[2])
  File "/usr/local/lib/python3.6/dist-packages/pluggy/callers.py", line 182, in _multicall
    next(gen)  # first yield
  File "/usr/local/lib/python3.6/dist-packages/_pytest/terminal.py", line 671, in pytest_terminal_summary
    self.summary_failures()
  File "/usr/local/lib/python3.6/dist-packages/_pytest/terminal.py", line 830, in summary_failures
    self._outrep_summary(rep)
  File "/usr/local/lib/python3.6/dist-packages/_pytest/terminal.py", line 860, in _outrep_summary
    self._tw.line(content)
  File "/usr/local/lib/python3.6/dist-packages/py/_io/terminalwriter.py", line 271, in line
    self.write(s, **kw)
  File "/usr/local/lib/python3.6/dist-packages/py/_io/terminalwriter.py", line 256, in write
    write_out(self._file, markupmsg)
  File "/usr/local/lib/python3.6/dist-packages/py/_io/terminalwriter.py", line 406, in write_out
    fil.write(msg)
BlockingIOError: [Errno 11] write could not complete without blocking

$ python3 -m pip freeze -l
asn1crypto==0.24.0
atomicwrites==1.3.0
attrs==19.3.0
cryptography==2.1.4
devscripts===2.17.12ubuntu1.1
filelock==3.0.12
hypothesis==4.41.2
idna==2.6
importlib-metadata==0.23
keyring==10.6.0
keyrings.alt==3.0
more-itertools==7.2.0
packaging==19.2
pathlib2==2.3.5
pluggy==0.13.0
psutil==5.6.3
py==1.8.0
pycrypto==2.6.1
pygobject==3.26.1
pyparsing==2.4.2
pytest==5.2.1
pyxdg==0.25
PyYAML==3.12
SecretStorage==2.3.1
six==1.12.0
toml==0.10.0
tox==3.14.0
virtualenv==16.7.6
wcwidth==0.1.7
zipp==0.6.0

[mitzkia]

In my actual work I can reproduce this issue several times in a day, and it limits me.
I could add some debug prints into pytest source to analyze this issue, could it be help?
Which pytest statement will be interesting for us?