(1) test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests.test_wait_with_exception() hangs:

vstinner@apu$ PYTHONASYNCIODEBUG=1 ./python -m test test_asyncio -m test_wait_with_exception -v
== CPython 3.7.0a4+ (heads/freebsd_configure:27218edef7, Jan 23 2018, 11:52:08) [GCC 7.2.1 20170915 (Red Hat 7.2.1-2)]
== Linux-4.14.13-300.fc27.x86_64-x86_64-with-fedora-27-Twenty_Seven little-endian
== cwd: /home/vstinner/prog/python/master/build/test_python_24675
== CPU count: 8
== encodings: locale=UTF-8, FS=utf-8
Run tests sequentially
0:00:00 load avg: 1.37 [1/1] test_asyncio
test_wait_with_exception (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests) ... /home/vstinner/prog/python/master/Lib/test/test_asyncio/test_tasks.py:1009: RuntimeWarning: coroutine 'sleep' was never awaited
Coroutine created at (most recent call last)
  File "/home/vstinner/prog/python/master/Lib/unittest/case.py", line 615, in run
    testMethod()
  File "/home/vstinner/prog/python/master/Lib/test/test_asyncio/test_tasks.py", line 1021, in test_wait_with_exception
    loop.run_until_complete(self.new_task(loop, foo()))
  File "/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 423, in run_until_complete
    self.run_forever()
  File "/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 391, in run_forever
    self._run_once()
  File "/home/vstinner/prog/python/master/Lib/test/test_asyncio/utils.py", line 454, in _run_once
    super()._run_once()
  File "/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 1521, in _run_once
    handle._run()
  File "/home/vstinner/prog/python/master/Lib/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/home/vstinner/prog/python/master/Lib/test/test_asyncio/test_tasks.py", line 2289, in _step
    return super()._step(*args)
  File "/home/vstinner/prog/python/master/Lib/asyncio/coroutines.py", line 61, in send
    return self.gen.send(value)
  File "/home/vstinner/prog/python/master/Lib/test/test_asyncio/test_tasks.py", line 1009, in sleeper
    yield from asyncio.sleep(0.15, loop=loop)
  yield from asyncio.sleep(0.15, loop=loop)


(2) 43 failures and 55 errors:

ERROR: test_context_manager (test.test_asyncio.test_locks.ConditionTests)
ERROR: test_context_manager (test.test_asyncio.test_locks.LockTests)
ERROR: test_context_manager_cant_reuse (test.test_asyncio.test_locks.LockTests)
ERROR: test_lock (test.test_asyncio.test_locks.LockTests)
ERROR: test_lock_by_with_statement (test.test_asyncio.test_locks.LockTests)
ERROR: test_repr (test.test_asyncio.test_locks.LockTests)
ERROR: test_context_manager (test.test_asyncio.test_locks.SemaphoreTests)
ERROR: test_semaphore (test.test_asyncio.test_locks.SemaphoreTests)
ERROR: test_as_completed (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
ERROR: test_as_completed_duplicate_coroutines (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
ERROR: test_sleep (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
ERROR: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
ERROR: test_tb_logger_not_called_after_cancel (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
ERROR: test_as_completed (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
ERROR: test_as_completed_duplicate_coroutines (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
ERROR: test_sleep (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
ERROR: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
ERROR: test_tb_logger_not_called_after_cancel (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
ERROR: test_as_completed (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
ERROR: test_as_completed_duplicate_coroutines (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
ERROR: test_sleep (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
ERROR: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
ERROR: test_tb_logger_not_called_after_cancel (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
ERROR: test_foobar (test.test_asyncio.test_tasks.CTask_Future_Tests)
ERROR: test_as_completed (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
ERROR: test_as_completed_duplicate_coroutines (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
ERROR: test_sleep (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
ERROR: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
ERROR: test_tb_logger_not_called_after_cancel (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
ERROR: test_await_old_style_coro (test.test_asyncio.test_tasks.CompatibilityTests)
ERROR: test_yield_from_awaitable (test.test_asyncio.test_tasks.CompatibilityTests)
ERROR: test_as_completed (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
ERROR: test_as_completed_duplicate_coroutines (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
ERROR: test_sleep (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
ERROR: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
ERROR: test_tb_logger_not_called_after_cancel (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
ERROR: test_as_completed (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
ERROR: test_as_completed_duplicate_coroutines (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
ERROR: test_sleep (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
ERROR: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
ERROR: test_tb_logger_not_called_after_cancel (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
ERROR: test_as_completed (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
ERROR: test_as_completed_duplicate_coroutines (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
ERROR: test_sleep (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
ERROR: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
ERROR: test_tb_logger_not_called_after_cancel (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
ERROR: test_as_completed (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
ERROR: test_as_completed_duplicate_coroutines (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
ERROR: test_sleep (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
ERROR: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
ERROR: test_tb_logger_not_called_after_cancel (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
ERROR: test_run_coroutine_threadsafe (test.test_asyncio.test_tasks.RunCoroutineThreadsafeTests)
ERROR: test_run_coroutine_threadsafe_task_cancelled (test.test_asyncio.test_tasks.RunCoroutineThreadsafeTests)
ERROR: test_run_coroutine_threadsafe_with_exception (test.test_asyncio.test_tasks.RunCoroutineThreadsafeTests)
ERROR: test_sleep_zero (test.test_asyncio.test_tasks.SleepTests)
FAIL: test_default_exc_handler_coro (test.test_asyncio.test_base_events.BaseEventLoopTests)
FAIL: test_nonstream_socket (test.test_asyncio.test_base_events.BaseLoopSendfileTests)
FAIL: test_as_completed (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
FAIL: test_sleep (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
FAIL: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests)
FAIL: test_as_completed (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
FAIL: test_sleep (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
FAIL: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.CTask_CFuture_SubclassTests)
FAIL: test_as_completed (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
FAIL: test_sleep (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
FAIL: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.CTask_CFuture_Tests)
FAIL: test_as_completed (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
FAIL: test_sleep (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
FAIL: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.CTask_PyFuture_Tests)
FAIL: test_as_completed (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
FAIL: test_sleep (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
FAIL: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.PyTask_CFutureSubclass_Tests)
FAIL: test_as_completed (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
FAIL: test_sleep (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
FAIL: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.PyTask_CFuture_Tests)
FAIL: test_as_completed (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
FAIL: test_sleep (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
FAIL: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.PyTask_PyFuture_SubclassTests)
FAIL: test_as_completed (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
FAIL: test_baseexception_during_cancel (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
FAIL: test_sleep (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
FAIL: test_task_cancel_sleeping_task (test.test_asyncio.test_tasks.PyTask_PyFuture_Tests)
FAIL: test_run_coroutine_threadsafe_task_factory_exception (test.test_asyncio.test_tasks.RunCoroutineThreadsafeTests)
FAILED (failures=43, errors=55, skipped=5)

These errors can be reproduced using attached fails file:

PYTHONASYNCIODEBUG=1 ./python -m test -v test_asyncio --matchfile=fails


Note: I found these issue when trying to run the full Python test suite using -X dev.

I used this change to skip the test which hangs, (1):

diff --git a/Lib/test/test_asyncio/test_tasks.py b/Lib/test/test_asyncio/test_tasks.py
index 1c361c8ec1..cf01df7061 100644
--- a/Lib/test/test_asyncio/test_tasks.py
+++ b/Lib/test/test_asyncio/test_tasks.py
@@ -991,7 +991,7 @@ class BaseTaskTests:
         loop.advance_time(10)
         loop.run_until_complete(asyncio.wait([a, b], loop=loop))
 
-    def test_wait_with_exception(self):
+    def Xtest_wait_with_exception(self):
 
         def gen():
             when = yield

Nathaniel, this is is a regression of fc2f407829d9817ddacccae6944dd0879cfaca24 -- bpo-32591: Add native coroutine origin tracking.

Please take a look.

Huh, weird. I'll take a look.

Question: there are lots of tests -- for example test.test_asyncio.test_tasks.CTaskSubclass_PyFuture_Tests.test_wait_with_exception, which freezes for me -- that use 'yield from asyncio.sleep(...)', e.g.:

        @asyncio.coroutine
        def sleeper():
            yield from asyncio.sleep(0.15, loop=loop)
            raise ZeroDivisionError('really')

But Andrew switch asyncio.sleep to be an ordinary 'async def' coroutine back in December. How does this work at all?

My tentative hypothesis about the actual bug is that the code above is working in regular mode, but stops working in debug mode, probably because in debug mode @asyncio.coroutine takes a different path involving CoroWrapper and we changed CoroWrapper. But I'm having trouble knowing how to verify or fix that because I don't understand how it ever works in the first place :-)

(However, I can report that at least that particular test starts working again if I convert 'sleeper' into an 'async def' coroutine.)

asyncio.coroutine sets the co_flags bit CO_ITERABLE_COROUTINE for generator functions' code objects.

With that bit flag, Python allows to 'yield from' native coroutines.

CoroWrapper.send() -> wrapped_generator.send() -> YIELD_FROM(native_coro) -> native_coro.send()

How confident are we that this is a regression from the coroutine origin tracking changes? (I'd double-check myself, but my cpython checkout is tied up for the next few hours doing --enable-optimizations builds.)

Looking at @asyncio.coroutine, in particular this branch that gets taken when debug mode is enabled:

https://github.com/python/cpython/blob/6b273f7f4056f8276f61a97c789d6bb4425e653c/Lib/asyncio/coroutines.py#L135-L149

I'm not seeing anything that would toggle the CO_ITERABLE_COROUTINE flag, and if I use pdb I can see that in the broken test the 'sleeper' function indeed doesn't have that flag set. But I didn't touch that code in the origin tracking patch, which makes me think that the proximal cause here might have been 5f841b553814969220b096a2b4f959b7f6fcbaf6 ?

No, it's this specific commit.  I can double check later, but I'm pretty sure about that.

Ah-hah, I get what's going on.

@asyncio.coroutine has always been buggy: when debug mode is turned on, then it fails to set CO_ITERABLE_COROUTINE.

However, when debug mode is turned on, then traditionally native coroutines got wrapped into CoroWrapper objects. We've always been lazy and reused the same CoroWrapper type for both native coroutines and old-style @asyncio.coroutine coroutines, so CoroWrapper has both coroutine and generator attributes.

This means that until my patch, in debug mode, native coroutines were *getting turned back into generators*. So this hid the bug in @asyncio.coroutine, because it doesn't matter if you can't call native coroutines if you've just turned them into generators.

The fix is trivial, we just need to always use @types.coroutine in @asyncio.coroutine, I'll put up a PR momentarily.

Good. Using PR 5291, test_asyncio doesn't hang anymore, and only 2 tests still fail:

======================================================================
ERROR: test_foobar (test.test_asyncio.test_tasks.CTask_Future_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/test/test_asyncio/test_tasks.py", line 2473, in test_foobar
    self.loop.call_later(0.1, fut.set_result(1))
  File "/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 509, in call_later
    context=context)
  File "/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 522, in call_at
    self._check_callback(callback, 'call_at')
  File "/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 556, in _check_callback
    f'a callable object was expected by {method}(), '
TypeError: a callable object was expected by call_at(), got None

======================================================================
FAIL: test_nonstream_socket (test.test_asyncio.test_base_events.BaseLoopSendfileTests)
----------------------------------------------------------------------
ValueError: the socket must be non-blocking

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/test/test_asyncio/test_base_events.py", line 1922, in test_nonstream_socket
    self.run_loop(self.loop.sock_sendfile(sock, self.file))
AssertionError: "only SOCK_STREAM type" does not match "the socket must be non-blocking"

----------------------------------------------------------------------
Ran 1874 tests in 49.198s

FAILED (failures=1, errors=1, skipped=5)

Fix for the two remaining bugs:

diff --git a/Lib/test/test_asyncio/test_base_events.py b/Lib/test/test_asyncio/test_base_events.py
index 8d72df6a72..6489f50f27 100644
--- a/Lib/test/test_asyncio/test_base_events.py
+++ b/Lib/test/test_asyncio/test_base_events.py
@@ -1917,6 +1917,7 @@ class BaseLoopSendfileTests(test_utils.TestCase):
 
     def test_nonstream_socket(self):
         sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
+        sock.setblocking(False)
         self.addCleanup(sock.close)
         with self.assertRaisesRegex(ValueError, "only SOCK_STREAM type"):
             self.run_loop(self.loop.sock_sendfile(sock, self.file))
diff --git a/Lib/test/test_asyncio/test_tasks.py b/Lib/test/test_asyncio/test_tasks.py
index d2162c31b4..9b62d207e4 100644
--- a/Lib/test/test_asyncio/test_tasks.py
+++ b/Lib/test/test_asyncio/test_tasks.py
@@ -2470,7 +2470,7 @@ class CTask_Future_Tests(test_utils.TestCase):
         self.loop = asyncio.new_event_loop()
         try:
             fut = Fut(loop=self.loop)
-            self.loop.call_later(0.1, fut.set_result(1))
+            self.loop.call_later(0.1, fut.set_result, 1)
             task = asyncio.Task(coro(), loop=self.loop)
             res = self.loop.run_until_complete(task)
         finally:

---

Nathaniel: do you want to include these fixes in your PR as well?

Hum, I'm concerned that "self.loop.call_later(0.1, fut.set_result(1))" bug wasn't spotted previously.

I plan to always run the Python test suite (especially when running on our CIs) in the new Python 3.7 "development mode" (python3 -X dev) which enables asyncio debug mode. Are you ok with that?

> I plan to always run the Python test suite (especially when running on our CIs) in the new Python 3.7 "development mode" (python3 -X dev) which enables asyncio debug mode. Are you ok with that?

Oh, I forgot to mention the obvious drawback: asyncio debug mode is slower. test_asyncio: 36 seconds => 48 seconds (+12 seconds).

"./python -m test test_asyncio" will not use the asyncio debug mode, only an explicit "./python -X dev -m test test_asyncio" and "make buildbottest".

> Nathaniel: do you want to include these fixes in your PR as well?

Victor, can you submit a new PR for this? Let's merge this right away.

> Victor, can you submit a new PR for this? Let's merge this right away.

Ok, done: https://github.com/python/cpython/pull/5302

New changeset fb5a7ad421ac20c49218ee4b86fb0d85ca4cd664 by Yury Selivanov (Nathaniel J. Smith) in branch 'master':
bpo-32636: Fix @asyncio.coroutine debug mode bug exposed by gh-5250 (#5291)
https://github.com/python/cpython/commit/fb5a7ad421ac20c49218ee4b86fb0d85ca4cd664

New changeset 789e359f51d2b27bea01b8c6c3bf090aaedf8839 by Yury Selivanov (Victor Stinner) in branch 'master':
bpo-32636: Fix two bugs in test_asyncio (#5302)
https://github.com/python/cpython/commit/789e359f51d2b27bea01b8c6c3bf090aaedf8839

This can probably be closed now. Thanks Victor and Nathaniel!