classification
Title: Undocumented behavior that IsolatedAsyncioTestCase would enable event loop debug mode
Type: behavior Stage:
Components: asyncio, Tests Versions: Python 3.8
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: asvetlov Nosy List: asvetlov, callumquick, legnaleurc, yselivanov
Priority: normal Keywords:

Created on 2019-10-28 01:50 by legnaleurc, last changed 2019-11-07 22:11 by asvetlov.

Messages (11)
msg355509 - (view) Author: Wei-Cheng Pan (legnaleurc) * Date: 2019-10-28 01:50
In bpo-32972 we enabled debug mode in IsolatedAsyncioTestCase._setupAsyncioLoop, which may print some warnings that are not that important to tests.
(e.g. Executing <Future ...> took 0.110 seconds)

I personally don't really like it being turn on by default, but if it needs to be so, maybe include it in document would be a good idea.

Add Andrew to nosy list because he was the author.
msg355519 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-10-28 09:36
This print comes from asyncio debug mode when async function is blocked by time longer than 0.1 sec (see loop.slow_callback_duration at loop.slow_callback_duration).
Usually, it is a sign of a problem in user code, e.g. something should be pushed into executor.

A test case is executed in debug mode. I think it is reasonable for the test run, isn't it?

The mode can be disabled by `asyncio.get_running_loop().set_debug(False)` in `asyncSetUp()` method.
msg355613 - (view) Author: Wei-Cheng Pan (legnaleurc) * Date: 2019-10-29 05:37
> Usually, it is a sign of a problem in user code, e.g. something should be pushed into executor.

Sometimes also happens on low-end CI machines.

And the message is somewhat unclear to me.
I have to grep cpython sources to understand that it is coming from debug mode and it means there is a slow awaitable ... in somewhere, because the displayed file:line is not always the right position.

> A test case is executed in debug mode. I think it is reasonable for the test run, isn't it?

Probably.

> The mode can be disabled by `asyncio.get_running_loop().set_debug(False)` in `asyncSetUp()` method.

Glad to know that. Thanks.
msg355639 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-10-29 10:02
Well, if the reported line is invalid it should be fixed
msg355947 - (view) Author: Callum Ward (callumquick) * Date: 2019-11-04 15:00
Hi, is there anything that needs to be fixed or done here?
msg355961 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-11-04 16:27
At first, would be nice to figure out what "invalid line reported" does mean.  
What text is reported and what is expected?
msg356020 - (view) Author: Wei-Cheng Pan (legnaleurc) * Date: 2019-11-05 10:58
Executing <Handle <TaskWakeupMethWrapper object at 0x10b31ec10>(<Future finis...events.py:418>) created at /.../lib/python3.8/asyncio/queues.py:70> took 0.104 seconds
Executing <Handle <TaskWakeupMethWrapper object at 0x10b31e9d0>(<Future finis...events.py:418>) created at /.../lib/python3.8/asyncio/queues.py:70> took 0.121 seconds

I was expecting it can display the stack of the awaitable.
msg356025 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-11-05 11:09
Thanks for the clarification.
I forgot about this thing; the output can be improved sure.
As a workaround you can use the following hack::

import asyncio.task
asyncio.task.Task = asyncio.task._PyTask

IIRC the pure python version prints a coroutine name at least.
msg356028 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-11-05 11:20
I've assigned myself to never forget about the issue; if somebody wants to fix _CTask and TaskWakeupMethWrapper representation -- you are welcome
msg356029 - (view) Author: Wei-Cheng Pan (legnaleurc) * Date: 2019-11-05 11:23
I cannot import asyncio.task, so I did this instead:

import asyncio.tasks
asyncio.tasks.Task = asyncio.tasks._PyTask

Then it changed to this:

Executing <Task pending name='Task-1' coro=<IsolatedAsyncioTestCase._asyncioLoopRunner() running at /.../lib/python3.8/unittest/async_case.py:96> wait_for=<Future pending cb=[Task.__wakeup()] created at /.../lib/python3.8/asyncio/base_events.py:418> created at /.../lib/python3.8/unittest/async_case.py:118> took 0.187 seconds

I suppose this means the entire test case is slow?
msg356213 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-11-07 22:11
Slower by percents, not in the factor of times.

I guess for tests it is satisfactory.
History
Date User Action Args
2019-11-07 22:11:39asvetlovsetmessages: + msg356213
2019-11-05 11:23:37legnaleurcsetmessages: + msg356029
2019-11-05 11:20:09asvetlovsetassignee: asvetlov
messages: + msg356028
2019-11-05 11:09:55asvetlovsetmessages: + msg356025
2019-11-05 10:58:52legnaleurcsetmessages: + msg356020
2019-11-04 16:27:38asvetlovsetmessages: + msg355961
2019-11-04 15:00:39callumquicksetnosy: + callumquick
messages: + msg355947
2019-10-29 10:02:47asvetlovsetnosy: + yselivanov
components: + asyncio
2019-10-29 10:02:36asvetlovsetmessages: + msg355639
2019-10-29 05:37:09legnaleurcsetmessages: + msg355613
2019-10-28 09:36:40asvetlovsetmessages: + msg355519
2019-10-28 01:50:13legnaleurccreate