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

non-deterministic deadlock in test_subprocess::test_warn_on_failed_cancel_terminate #1604

Open
pquentin opened this issue Jun 10, 2020 · 6 comments
Open

non-deterministic deadlock in test_subprocess::test_warn_on_failed_cancel_terminate #1604

pquentin opened this issue Jun 10, 2020 · 6 comments

Comments

@pquentin
Copy link
Member

See https://github.com/python-trio/trio/runs/756580934?check_suite_focus=true. I was able to retrieve the test name thanks to the traceback. The test timed out on an acquire() call.

2020-06-10T05:22:22.9465010Z Timeout (0:01:00)!
2020-06-10T05:22:22.9465567Z Thread 0x00007feaed267700 (most recent call first):
2020-06-10T05:22:22.9466805Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/jedi/inference/compiled/subprocess/__init__.py", line 37 in _enqueue_output
2020-06-10T05:22:22.9467371Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/threading.py", line 864 in run
2020-06-10T05:22:22.9467782Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/threading.py", line 916 in _bootstrap_inner
2020-06-10T05:22:22.9468195Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/threading.py", line 884 in _bootstrap
2020-06-10T05:22:22.9468437Z 
2020-06-10T05:22:22.9468695Z Thread 0x00007feaef1be700 (most recent call first):
2020-06-10T05:22:22.9469487Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/trio/_core/tests/test_thread_cache.py", line 102 in acquire
2020-06-10T05:22:22.9470319Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/trio/_core/_thread_cache.py", line 62 in _work
2020-06-10T05:22:22.9470793Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/threading.py", line 864 in run
2020-06-10T05:22:22.9471195Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/threading.py", line 916 in _bootstrap_inner
2020-06-10T05:22:22.9471607Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/threading.py", line 884 in _bootstrap
2020-06-10T05:22:22.9471852Z 
2020-06-10T05:22:22.9472088Z Thread 0x00007feb08802680 (most recent call first):
2020-06-10T05:22:22.9472826Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/trio/_core/_io_epoll.py", line 223 in get_events
2020-06-10T05:22:22.9473561Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/trio/_core/_run.py", line 1890 in run
2020-06-10T05:22:22.9474782Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/trio/testing/_trio_test.py", line 27 in wrapper
2020-06-10T05:22:22.9475534Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/python.py", line 182 in pytest_pyfunc_call
2020-06-10T05:22:22.9476332Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
2020-06-10T05:22:22.9477195Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
2020-06-10T05:22:22.9478034Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
2020-06-10T05:22:22.9478759Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
2020-06-10T05:22:22.9479528Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/python.py", line 1477 in runtest
2020-06-10T05:22:22.9480285Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/runner.py", line 135 in pytest_runtest_call
2020-06-10T05:22:22.9481053Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
2020-06-10T05:22:22.9481766Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
2020-06-10T05:22:22.9482536Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
2020-06-10T05:22:22.9483258Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
2020-06-10T05:22:22.9484024Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/runner.py", line 217 in <lambda>
2020-06-10T05:22:22.9484897Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/runner.py", line 244 in from_call
2020-06-10T05:22:22.9485766Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/runner.py", line 217 in call_runtest_hook
2020-06-10T05:22:22.9486511Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/runner.py", line 186 in call_and_report
2020-06-10T05:22:22.9487294Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/runner.py", line 100 in runtestprotocol
2020-06-10T05:22:22.9488044Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/runner.py", line 85 in pytest_runtest_protocol
2020-06-10T05:22:22.9488841Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
2020-06-10T05:22:22.9489558Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
2020-06-10T05:22:22.9490321Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
2020-06-10T05:22:22.9491048Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
2020-06-10T05:22:22.9491830Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/main.py", line 272 in pytest_runtestloop
2020-06-10T05:22:22.9492548Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
2020-06-10T05:22:22.9493315Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
2020-06-10T05:22:22.9494033Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
2020-06-10T05:22:22.9494796Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
2020-06-10T05:22:22.9495505Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/main.py", line 247 in _main
2020-06-10T05:22:22.9496435Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/main.py", line 191 in wrap_session
2020-06-10T05:22:22.9497225Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/main.py", line 240 in pytest_cmdline_main
2020-06-10T05:22:22.9497954Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
2020-06-10T05:22:22.9498777Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
2020-06-10T05:22:22.9499607Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
2020-06-10T05:22:22.9500722Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
2020-06-10T05:22:22.9501514Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/_pytest/config/__init__.py", line 125 in main
2020-06-10T05:22:22.9501986Z   File "/opt/hostedtoolcache/Python/3.6.10/x64/bin/pytest", line 8 in <module>
2020-06-10T05:30:20.1060105Z ##[error]The operation was canceled.
This was referenced Jun 10, 2020
Open
Merged
@njsmith
Copy link
Member

njsmith commented Jun 10, 2020

Ick.

the acquire call might be a red herring... that's where cached threads park themselves while waiting to be assigned a job, so it might just be an idle thread that's still hanging around in case anyone wants to assign it more work.

njsmith added a commit to njsmith/trio that referenced this issue Jun 10, 2020
@njsmith
Stop leaking a thread in test_race_between_idle_exit_and_job_assignment
236118e 
It can lead to confusion, e.g.: python-trio#1604
@njsmith njsmith mentioned this issue Jun 10, 2020
Merged
@njsmith
Copy link
Member

njsmith commented Jun 10, 2020

OK, yeah, the problem doesn't seem to be test_race_between_idle_exit_and_job_assignment; that's listed up at 31% in the logs:

2020-06-10T05:21:03.4986741Z ../../../../../../opt/hostedtoolcache/Python/3.6.10/x64/lib/python3.6/site-packages/trio/_core/tests/test_thread_cache.py::test_race_between_idle_exit_and_job_assignment PASSED [ 31%]

So that thread is just a stray one left behind by that test. Probably not relevant to this hang.

It's weird for pytest to hang without printing which test it's starting... I guess the next test it would have run is test_warn_on_failed_cancel_terminate, so maybe that's what hung?

@njsmith njsmith changed the title test_race_between_idle_exit_and_job_assignment deadlocked non-deterministic deadlock in test suite, maybe in test_subprocess::test_warn_on_failed_cancel_terminate or thereabouts Jun 10, 2020
@njsmith
Copy link
Member

njsmith commented Jun 10, 2020

It's too bad the faulthandler output is useless here. This is one of those times when #927 would be really helpful

@pquentin
Copy link
Member Author

pquentin commented Jun 12, 2020 •
edited
Loading

https://travis-ci.org/github/python-trio/trio/jobs/697497032 confirms this happens in test_warn_on_failed_cancel_terminate as Travis is much better at showing output while the tests are still running.

The not so relevant stacktrace:

Thread 0x00007ff41382a740 (most recent call first):
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/trio/_core/_io_epoll.py", line 223 in get_events
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/trio/_core/_run.py", line 1889 in run
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/trio/testing/_trio_test.py", line 27 in wrapper
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/python.py", line 182 in pytest_pyfunc_call
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/python.py", line 1477 in runtest
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/runner.py", line 135 in pytest_runtest_call
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/runner.py", line 217 in <lambda>
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/runner.py", line 244 in from_call
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/runner.py", line 217 in call_runtest_hook
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/runner.py", line 186 in call_and_report
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/runner.py", line 100 in runtestprotocol
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/runner.py", line 85 in pytest_runtest_protocol
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/main.py", line 272 in pytest_runtestloop
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/main.py", line 247 in _main
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/main.py", line 191 in wrap_session
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/main.py", line 240 in pytest_cmdline_main
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 87 in <lambda>
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/manager.py", line 93 in _hookexec
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/pluggy/hooks.py", line 286 in __call__
  File "/home/travis/virtualenv/python3.6-dev/lib/python3.6/site-packages/_pytest/config/__init__.py", line 125 in main
  File "/home/travis/virtualenv/python3.6-dev/bin/pytest", line 8 in <module>

@pquentin pquentin changed the title non-deterministic deadlock in test suite, maybe in test_subprocess::test_warn_on_failed_cancel_terminate or thereabouts non-deterministic deadlock in test_subprocess::test_warn_on_failed_cancel_terminate Jun 12, 2020
@pquentin
Copy link
Member Author

And again on FreeBSD: https://travis-ci.org/github/python-trio/trio/jobs/697564639

@pquentin pquentin mentioned this issue Jun 12, 2020
Merged
@pquentin
Copy link
Member Author

I managed to get a pytest traceback by using pytest-timeout and pytest-flakefinder, not sure if it helps or not.

https://github.com/pquentin/trio/runs/765304561

(Notice that the test gets interrupted by pytest-timeout after one second.)


2020-06-12T12:02:52.0688577Z /opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/_pytest/python.py:182: 
2020-06-12T12:02:52.0688733Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2020-06-12T12:02:52.0688870Z 
2020-06-12T12:02:52.0689208Z kwargs = {'monkeypatch': <_pytest.monkeypatch.MonkeyPatch object at 0x7f3735751a10>}
2020-06-12T12:02:52.0689367Z __tracebackhide__ = True, clocks = [], clock = None, instruments = []
2020-06-12T12:02:52.0689574Z 
2020-06-12T12:02:52.0689702Z     @wraps(fn)
2020-06-12T12:02:52.0689829Z     def wrapper(**kwargs):
2020-06-12T12:02:52.0689960Z         __tracebackhide__ = True
2020-06-12T12:02:52.0691061Z         clocks = [c for c in kwargs.values() if isinstance(c, Clock)]
2020-06-12T12:02:52.0691212Z         if not clocks:
2020-06-12T12:02:52.0691351Z             clock = None
2020-06-12T12:02:52.0691482Z         elif len(clocks) == 1:
2020-06-12T12:02:52.0691599Z             clock = clocks[0]
2020-06-12T12:02:52.0691728Z         else:
2020-06-12T12:02:52.0691871Z             raise ValueError("too many clocks spoil the broth!")
2020-06-12T12:02:52.0692021Z         instruments = [i for i in kwargs.values() if isinstance(i, Instrument)]
2020-06-12T12:02:52.0692177Z >       return _core.run(partial(fn, **kwargs), clock=clock, instruments=instruments)
2020-06-12T12:02:52.0692263Z 
2020-06-12T12:02:52.0692383Z __tracebackhide__ = True
2020-06-12T12:02:52.0692509Z clock      = None
2020-06-12T12:02:52.0692629Z clocks     = []
2020-06-12T12:02:52.0692763Z fn         = <function test_warn_on_failed_cancel_terminate at 0x7f373b278f80>
2020-06-12T12:02:52.0692899Z instruments = []
2020-06-12T12:02:52.0693292Z kwargs     = {'monkeypatch': <_pytest.monkeypatch.MonkeyPatch object at 0x7f3735751a10>}
2020-06-12T12:02:52.0693377Z 
2020-06-12T12:02:52.0693731Z /opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/trio/testing/_trio_test.py:27: 
2020-06-12T12:02:52.0693895Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2020-06-12T12:02:52.0693971Z 
2020-06-12T12:02:52.0694129Z async_fn = functools.partial(<function test_warn_on_failed_cancel_terminate at 0x7f373b278f80>, monkeypatch=<_pytest.monkeypatch.MonkeyPatch object at 0x7f3735751a10>)
2020-06-12T12:02:52.0694294Z clock = None, instruments = []
2020-06-12T12:02:52.0695126Z restrict_keyboard_interrupt_to_checkpoints = False, args = ()
2020-06-12T12:02:52.0695225Z 
2020-06-12T12:02:52.0695348Z     def run(
2020-06-12T12:02:52.0695462Z         async_fn,
2020-06-12T12:02:52.0695588Z         *args,
2020-06-12T12:02:52.0695716Z         clock=None,
2020-06-12T12:02:52.0695843Z         instruments=(),
2020-06-12T12:02:52.0695983Z         restrict_keyboard_interrupt_to_checkpoints=False,
2020-06-12T12:02:52.0696118Z     ):
2020-06-12T12:02:52.0696483Z         """Run a Trio-flavored async function, and return the result.
2020-06-12T12:02:52.0696614Z     
2020-06-12T12:02:52.0696765Z         Calling::
2020-06-12T12:02:52.0696889Z     
2020-06-12T12:02:52.0697017Z            run(async_fn, *args)
2020-06-12T12:02:52.0697142Z     
2020-06-12T12:02:52.0697273Z         is the equivalent of::
2020-06-12T12:02:52.0697397Z     
2020-06-12T12:02:52.0697509Z            await async_fn(*args)
2020-06-12T12:02:52.0698011Z     
2020-06-12T12:02:52.0698444Z         except that :func:`run` can (and must) be called from a synchronous
2020-06-12T12:02:52.0698594Z         context.
2020-06-12T12:02:52.0698717Z     
2020-06-12T12:02:52.0699072Z         This is Trio's main entry point. Almost every other function in Trio
2020-06-12T12:02:52.0699228Z         requires that you be inside a call to :func:`run`.
2020-06-12T12:02:52.0699359Z     
2020-06-12T12:02:52.0699466Z         Args:
2020-06-12T12:02:52.0699597Z           async_fn: An async function.
2020-06-12T12:02:52.0699722Z     
2020-06-12T12:02:52.0700038Z           args: Positional arguments to be passed to *async_fn*. If you need to
2020-06-12T12:02:52.0700208Z               pass keyword arguments, then use :func:`functools.partial`.
2020-06-12T12:02:52.0701007Z     
2020-06-12T12:02:52.0702139Z           clock: ``None`` to use the default system-specific monotonic clock;
2020-06-12T12:02:52.0702307Z               otherwise, an object implementing the :class:`trio.abc.Clock`
2020-06-12T12:02:52.0702580Z               interface, like (for example) a :class:`trio.testing.MockClock`
2020-06-12T12:02:52.0702711Z               instance.
2020-06-12T12:02:52.0702838Z     
2020-06-12T12:02:52.0702978Z           instruments (list of :class:`trio.abc.Instrument` objects): Any
2020-06-12T12:02:52.0703139Z               instrumentation you want to apply to this run. This can also be
2020-06-12T12:02:52.0703297Z               modified during the run; see :ref:`instrumentation`.
2020-06-12T12:02:52.0703434Z     
2020-06-12T12:02:52.0703584Z           restrict_keyboard_interrupt_to_checkpoints (bool): What happens if the
2020-06-12T12:02:52.0703951Z               user hits control-C while :func:`run` is running? If this argument
2020-06-12T12:02:52.0704470Z               is False (the default), then you get the standard Python behavior: a
2020-06-12T12:02:52.0704895Z               :exc:`KeyboardInterrupt` exception will immediately interrupt
2020-06-12T12:02:52.0705064Z               whatever task is running (or if no task is running, then Trio will
2020-06-12T12:02:52.0705269Z               wake up a task to be interrupted). Alternatively, if you set this
2020-06-12T12:02:52.0705426Z               argument to True, then :exc:`KeyboardInterrupt` delivery will be
2020-06-12T12:02:52.0705585Z               delayed: it will be *only* be raised at :ref:`checkpoints
2020-06-12T12:02:52.0705739Z               <checkpoints>`, like a :exc:`Cancelled` exception.
2020-06-12T12:02:52.0705875Z     
2020-06-12T12:02:52.0706019Z               The default behavior is nice because it means that even if you
2020-06-12T12:02:52.0706490Z               accidentally write an infinite loop that never executes any
2020-06-12T12:02:52.0707152Z               checkpoints, then you can still break out of it using control-C.
2020-06-12T12:02:52.0707480Z               The alternative behavior is nice if you're paranoid about a
2020-06-12T12:02:52.0707641Z               :exc:`KeyboardInterrupt` at just the wrong place leaving your
2020-06-12T12:02:52.0707808Z               program in an inconsistent state, because it means that you only
2020-06-12T12:02:52.0708537Z               have to worry about :exc:`KeyboardInterrupt` at the exact same
2020-06-12T12:02:52.0708706Z               places where you already have to worry about :exc:`Cancelled`.
2020-06-12T12:02:52.0709250Z     
2020-06-12T12:02:52.0709394Z               This setting has no effect if your program has registered a custom
2020-06-12T12:02:52.0709554Z               SIGINT handler, or if :func:`run` is called from anywhere but the
2020-06-12T12:02:52.0710041Z               main thread (this is a Python limitation), or if you use
2020-06-12T12:02:52.0710469Z               :func:`open_signal_receiver` to catch SIGINT.
2020-06-12T12:02:52.0710591Z     
2020-06-12T12:02:52.0710720Z         Returns:
2020-06-12T12:02:52.0711372Z           Whatever ``async_fn`` returns.
2020-06-12T12:02:52.0711510Z     
2020-06-12T12:02:52.0711630Z         Raises:
2020-06-12T12:02:52.0712037Z           TrioInternalError: if an unexpected error is encountered inside Trio's
2020-06-12T12:02:52.0713197Z               internal machinery. This is a bug and you should `let us know
2020-06-12T12:02:52.0713630Z               <https://github.com/python-trio/trio/issues>`__.
2020-06-12T12:02:52.0713782Z     
2020-06-12T12:02:52.0713907Z           Anything else: if ``async_fn`` raises an exception, then :func:`run`
2020-06-12T12:02:52.0714058Z               propagates it.
2020-06-12T12:02:52.0714182Z     
2020-06-12T12:02:52.0714304Z         """
2020-06-12T12:02:52.0714425Z     
2020-06-12T12:02:52.0714664Z         __tracebackhide__ = True
2020-06-12T12:02:52.0714796Z     
2020-06-12T12:02:52.0714907Z         runner = setup_runner(
2020-06-12T12:02:52.0715614Z             clock, instruments, restrict_keyboard_interrupt_to_checkpoints
2020-06-12T12:02:52.0716185Z         )
2020-06-12T12:02:52.0716309Z     
2020-06-12T12:02:52.0716718Z         gen = unrolled_run(runner, async_fn, args)
2020-06-12T12:02:52.0716978Z         next_send = None
2020-06-12T12:02:52.0717109Z         while True:
2020-06-12T12:02:52.0717237Z             try:
2020-06-12T12:02:52.0717360Z                 timeout = gen.send(next_send)
2020-06-12T12:02:52.0717499Z             except StopIteration:
2020-06-12T12:02:52.0717634Z                 break
2020-06-12T12:02:52.0717766Z >           next_send = runner.io_manager.get_events(timeout)
2020-06-12T12:02:52.0717843Z 
2020-06-12T12:02:52.0717964Z __tracebackhide__ = True
2020-06-12T12:02:52.0718089Z args       = ()
2020-06-12T12:02:52.0718858Z async_fn   = functools.partial(<function test_warn_on_failed_cancel_terminate at 0x7f373b278f80>, monkeypatch=<_pytest.monkeypatch.MonkeyPatch object at 0x7f3735751a10>)
2020-06-12T12:02:52.0719029Z clock      = None
2020-06-12T12:02:52.0719161Z gen        = <generator object unrolled_run at 0x7f37357915d0>
2020-06-12T12:02:52.0719295Z instruments = []
2020-06-12T12:02:52.0719414Z next_send  = []
2020-06-12T12:02:52.0719545Z restrict_keyboard_interrupt_to_checkpoints = False
2020-06-12T12:02:52.0720103Z runner     = Runner(clock=SystemClock(offset=158945.3707038472), instruments=[], io_manager=EpollIOManager(_epoll=<select.epoll obj..._autojump_threshold=inf, is_guest=False, guest_tick_scheduled=False, ki_pending=False, waiting_for_idle=SortedDict({}))
2020-06-12T12:02:52.0720494Z timeout    = 86400
2020-06-12T12:02:52.0720577Z 
2020-06-12T12:02:52.0721044Z /opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/trio/_core/_run.py:1889: 
2020-06-12T12:02:52.0721827Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2020-06-12T12:02:52.0721911Z 
2020-06-12T12:02:52.0723433Z self = EpollIOManager(_epoll=<select.epoll object at 0x7f37357154f0>, _registered=defaultdict(<class 'trio._core._io_epoll.Ep...ags=1)}), _force_wakeup=<trio._core._wakeup_socketpair.WakeupSocketpair object at 0x7f37335ca0d0>, _force_wakeup_fd=15)
2020-06-12T12:02:52.0723622Z timeout = 86400
2020-06-12T12:02:52.0723702Z 
2020-06-12T12:02:52.0724265Z     def get_events(self, timeout):
2020-06-12T12:02:52.0724403Z         # max_events must be > 0 or epoll gets cranky
2020-06-12T12:02:52.0725705Z         # accessing self._registered from a thread looks dangerous, but it's
2020-06-12T12:02:52.0726093Z         # OK because it doesn't matter if our value is a little bit off.
2020-06-12T12:02:52.0726248Z         max_events = max(1, len(self._registered))
2020-06-12T12:02:52.0726387Z >       return self._epoll.poll(timeout, max_events)
2020-06-12T12:02:52.0726460Z 
2020-06-12T12:02:52.0726578Z max_events = 2
2020-06-12T12:02:52.0728176Z self       = EpollIOManager(_epoll=<select.epoll object at 0x7f37357154f0>, _registered=defaultdict(<class 'trio._core._io_epoll.Ep...ags=1)}), _force_wakeup=<trio._core._wakeup_socketpair.WakeupSocketpair object at 0x7f37335ca0d0>, _force_wakeup_fd=15)
2020-06-12T12:02:52.0728602Z timeout    = 86400
2020-06-12T12:02:52.0728683Z 
2020-06-12T12:02:52.0729056Z /opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/trio/_core/_io_epoll.py:223: 
2020-06-12T12:02:52.0729225Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2020-06-12T12:02:52.0729304Z 
2020-06-12T12:02:52.0729421Z signum = 14
2020-06-12T12:02:52.0731066Z frame = <frame at 0x7f3733718b30, file '/opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/trio/_core/_io_epoll.py', line 223, code get_events>
2020-06-12T12:02:52.0731496Z 
2020-06-12T12:02:52.0731630Z     def handler(signum, frame):
2020-06-12T12:02:52.0731764Z         __tracebackhide__ = True
2020-06-12T12:02:52.0732027Z >       timeout_sigalrm(item, params.timeout)
2020-06-12T12:02:52.0732101Z 
2020-06-12T12:02:52.0732220Z __tracebackhide__ = True
2020-06-12T12:02:52.0733011Z frame      = <frame at 0x7f3733718b30, file '/opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/trio/_core/_io_epoll.py', line 223, code get_events>
2020-06-12T12:02:52.0733195Z item       = <Function test_warn_on_failed_cancel_terminate[166]>
2020-06-12T12:02:52.0734639Z params     = Settings(timeout=1.0, method='signal', func_only=False)
2020-06-12T12:02:52.0734899Z signum     = 14
2020-06-12T12:02:52.0734962Z 
2020-06-12T12:02:52.0735311Z /opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/pytest_timeout.py:149: 
2020-06-12T12:02:52.0735477Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2020-06-12T12:02:52.0736035Z 
2020-06-12T12:02:52.0736171Z item = <Function test_warn_on_failed_cancel_terminate[166]>, timeout = 1.0
2020-06-12T12:02:52.0736250Z 
2020-06-12T12:02:52.0736387Z     def timeout_sigalrm(item, timeout):
2020-06-12T12:02:52.0736530Z         """Dump stack of threads and raise an exception
2020-06-12T12:02:52.0737118Z     
2020-06-12T12:02:52.0737807Z         This will output the stacks of any threads other then the
2020-06-12T12:02:52.0737954Z         current to stderr and then raise an AssertionError, thus
2020-06-12T12:02:52.0738099Z         terminating the test.
2020-06-12T12:02:52.0738228Z         """
2020-06-12T12:02:52.0738363Z         if SUPPRESS_TIMEOUT:
2020-06-12T12:02:52.0738494Z             return
2020-06-12T12:02:52.0738622Z         __tracebackhide__ = True
2020-06-12T12:02:52.0738760Z         nthreads = len(threading.enumerate())
2020-06-12T12:02:52.0738895Z         if nthreads > 1:
2020-06-12T12:02:52.0739023Z             write_title("Timeout", sep="+")
2020-06-12T12:02:52.0739483Z         dump_stacks()
2020-06-12T12:02:52.0739615Z         if nthreads > 1:
2020-06-12T12:02:52.0739751Z             write_title("Timeout", sep="+")
2020-06-12T12:02:52.0739889Z >       pytest.fail("Timeout >%ss" % timeout)
2020-06-12T12:02:52.0740328Z 
2020-06-12T12:02:52.0740455Z __tracebackhide__ = True
2020-06-12T12:02:52.0740863Z item       = <Function test_warn_on_failed_cancel_terminate[166]>
2020-06-12T12:02:52.0741000Z nthreads   = 2
2020-06-12T12:02:52.0741120Z timeout    = 1.0
2020-06-12T12:02:52.0741184Z 
2020-06-12T12:02:52.0741600Z /opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/pytest_timeout.py:323: 
2020-06-12T12:02:52.0742109Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2020-06-12T12:02:52.0742206Z 
2020-06-12T12:02:52.0742485Z msg = 'Timeout >1.0s', pytrace = True
2020-06-12T12:02:52.0742569Z 
2020-06-12T12:02:52.0742691Z     @_with_exception(Failed)
2020-06-12T12:02:52.0744116Z     def fail(msg: str = "", pytrace: bool = True) -> "NoReturn":
2020-06-12T12:02:52.0744261Z         """
2020-06-12T12:02:52.0744389Z         Explicitly fail an executing test with the given message.
2020-06-12T12:02:52.0744526Z     
2020-06-12T12:02:52.0744673Z         :param str msg: the message to show the user as reason for the failure.
2020-06-12T12:02:52.0745162Z         :param bool pytrace: if false the msg represents the full failure information and no
2020-06-12T12:02:52.0745325Z             python traceback will be reported.
2020-06-12T12:02:52.0745455Z         """
2020-06-12T12:02:52.0745584Z         __tracebackhide__ = True
2020-06-12T12:02:52.0745716Z >       raise Failed(msg=msg, pytrace=pytrace)
2020-06-12T12:02:52.0746269Z E       Failed: Timeout >1.0s
2020-06-12T12:02:52.0746338Z 
2020-06-12T12:02:52.0746772Z __tracebackhide__ = True
2020-06-12T12:02:52.0747096Z msg        = 'Timeout >1.0s'
2020-06-12T12:02:52.0747224Z pytrace    = True
2020-06-12T12:02:52.0747288Z 
2020-06-12T12:02:52.0747636Z /opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/_pytest/outcomes.py:158: Failed
2020-06-12T12:02:52.0747986Z ----------------------------- Captured stderr call -----------------------------
2020-06-12T12:02:52.0748068Z 
2020-06-12T12:02:52.0748323Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
2020-06-12T12:02:52.0748425Z 
2020-06-12T12:02:52.0748557Z ~~~~~~~~~~~~~~~ Stack of Trio worker thread 0 (139875048146688) ~~~~~~~~~~~~~~~~
2020-06-12T12:02:52.0750206Z   File "/opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/threading.py", line 890, in _bootstrap
2020-06-12T12:02:52.0750441Z     self._bootstrap_inner()
2020-06-12T12:02:52.0750795Z   File "/opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/threading.py", line 926, in _bootstrap_inner
2020-06-12T12:02:52.0750941Z     self.run()
2020-06-12T12:02:52.0751125Z   File "/opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/threading.py", line 870, in run
2020-06-12T12:02:52.0751291Z     self._target(*self._args, **self._kwargs)
2020-06-12T12:02:52.0751806Z   File "/opt/hostedtoolcache/Python/3.7.7/x64/lib/python3.7/site-packages/trio/_core/_thread_cache.py", line 61, in _work
2020-06-12T12:02:52.0751983Z     if self._worker_lock.acquire(timeout=IDLE_TIMEOUT):
2020-06-12T12:02:52.0752082Z 
2020-06-12T12:02:52.0752216Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
2020-06-12T12:02:52.0753120Z __________________ test_warn_on_failed_cancel_terminate[167] ___________________

@njsmith njsmith mentioned this issue Jun 23, 2020
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@pquentin @njsmith