test_asyncio: test_run_coroutine_threadsafe_with_timeout() has a race condition

[vstinner]

BPO	38564
Nosy	@vstinner, @1st1, @aeros

^{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:

assignee = None
closed_at = <Date 2021-09-21.22:28:10.793>
created_at = <Date 2019-10-23.14:44:20.212>
labels = ['tests', '3.9']
title = 'test_asyncio: test_run_coroutine_threadsafe_with_timeout() has a race condition'
updated_at = <Date 2021-09-21.22:28:10.792>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2021-09-21.22:28:10.792>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2021-09-21.22:28:10.793>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2019-10-23.14:44:20.212>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 38564
keywords = []
message_count = 6.0
messages = ['355223', '355227', '355228', '355360', '355361', '355365']
nosy_count = 3.0
nosy_names = ['vstinner', 'yselivanov', 'aeros']
pr_nums = []
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue38564'
versions = ['Python 3.9']

[vstinner]

AMD64 FreeBSD Shared 3.x:
https://buildbot.python.org/all/#/builders/371/builds/7

This buildbot worker is known to be very slow.

test_run_coroutine_threadsafe_with_timeout (test.test_asyncio.test_tasks.RunCoroutineThreadsafeTests)
Test coroutine submission from a thread to an event loop ... FAIL

FAIL: test_run_coroutine_threadsafe_with_timeout (test.test_asyncio.test_tasks.RunCoroutineThreadsafeTests)
Test coroutine submission from a thread to an event loop
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/test_asyncio/test_tasks.py", line 3210, in test_run_coroutine_threadsafe_with_timeout
    self.loop.run_until_complete(future)
AssertionError: TimeoutError not raised

[vstinner]

test_run_coroutine_threadsafe_with_timeout() has a race condition. It relies on "await asyncio.sleep(0.05)" synchronization primitive. That's not reliable.

    async def add(self, a, b, fail=False, cancel=False):
        """Wait 0.05 second and return a + b."""
        await asyncio.sleep(0.05)
        if fail:
            raise RuntimeError("Fail!")
        if cancel:
            asyncio.current_task(self.loop).cancel()
            await asyncio.sleep(0)
        return a + b

[vstinner]

I can reproduce the issue with this patch:

diff --git a/Lib/test/test_asyncio/test_tasks.py b/Lib/test/test_asyncio/test_tasks.py
index dde84b84b1..c94113712a 100644
--- a/Lib/test/test_asyncio/test_tasks.py
+++ b/Lib/test/test_asyncio/test_tasks.py
@@ -3160,7 +3160,7 @@ class RunCoroutineThreadsafeTests(test_utils.TestCase):
 
     async def add(self, a, b, fail=False, cancel=False):
         """Wait 0.05 second and return a + b."""
-        await asyncio.sleep(0.05)
+        await asyncio.sleep(1e-9)
         if fail:
             raise RuntimeError("Fail!")
         if cancel:

and the command:

./python -m test test_asyncio -m test_run_coroutine_threadsafe_with_timeout -v -F

[aeros]

I can confirm Victor's method of reproducing the failure consistently, by using asyncio.sleep(1e-9) within RunCoroutineThreadsafeTests.add() instead of the current asyncio.sleep(0.05).

I also experimented with adjusting the sleep time, to figure out the "breaking point" where I could no longer run ./python -m test test_asyncio -m test_run_coroutine_threadsafe_with_timeout -v -F without failures (within ~10,000 tests). From my results, the lowest reliable value was 0.001. At 1e-4, I was able to consistently reproduce the failure reported above:

FAIL: test_run_coroutine_threadsafe_with_timeout (test.test_asyncio.test_tasks.RunCoroutineThreadsafeTests)
Test coroutine submission from a thread to an event loop
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/aeros/repos/cpython/Lib/test/test_asyncio/test_tasks.py", line 3210, in test_run_coroutine_threadsafe_with_timeout
    self.loop.run_until_complete(future)
AssertionError: TimeoutError not raised

The failure becomes increasingly consistent with lowered time as expected, but at 1e-5 I was able to repeatedly reproduce the failure within 10 iterations of the test. At 1e-4 it took around 3000 iterations before failing (across multiple runs).

[vstinner]

IHMO a test must not depend on time.

[aeros]

IHMO a test must not depend on time.

I would agree, the tests should optimally not depend on time. My above comment was primarily to confirm that the failure was able to be consistently reproduced, along with the minimum conditions to do so.

Yury had been the one to change it to "asyncio.sleep(0.05)" from the previous "asyncio.sleep(1)" in the following commit: abe9625 (Nov 13, 2015).

Perhaps he might have some insight or ideas as to how we could improve the test to use a more reliable means of synchronization that has been implemented since that change was made. I'll add him to the nosy list.