test_asyncio fails with PYTHONASYNCIODEBUG=1 #76817
Comments
|
(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 (2) 43 failures and 55 errors: ERROR: test_context_manager (test.test_asyncio.test_locks.ConditionTests) These errors can be reproduced using attached fails file: PYTHONASYNCIODEBUG=1 ./python -m test -v test_asyncio --matchfile=failsNote: I found these issue when trying to run the full Python test suite using -X dev. |
vstinner
added
3.7 (EOL)
|
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 |
|
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: cpython/Lib/asyncio/coroutines.py Lines 135 to 149 in 6b273f7 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 5f841b5 ? |
|
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: ====================================================================== 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====================================================================== 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? |
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". |
Victor, can you submit a new PR for this? Let's merge this right away. |
Ok, done: #5302 |
|
This can probably be closed now. Thanks Victor and Nathaniel! |
Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.
Show more details
GitHub fields:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: