test_asyncio: test_get_cancelled() fails randomly on x86-64 macOS 3.x

[vstinner]

BPO	47076
Nosy	@vstinner, @asvetlov, @1st1, @kumaraditya303
PRs	bpo-47076: fix test_asyncio: test_get_cancelled() #32020 bpo-47076: Make asyncio.Queue stable on slow test boxes #32040

^{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 2022-03-22.14:01:59.619>
created_at = <Date 2022-03-21.03:14:47.170>
labels = ['3.11', 'tests', 'expert-asyncio']
title = 'test_asyncio: test_get_cancelled() fails randomly on x86-64 macOS 3.x'
updated_at = <Date 2022-03-22.14:47:03.896>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2022-03-22.14:47:03.896>
actor = 'asvetlov'
assignee = 'none'
closed = True
closed_date = <Date 2022-03-22.14:01:59.619>
closer = 'asvetlov'
components = ['Tests', 'asyncio']
creation = <Date 2022-03-21.03:14:47.170>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 47076
keywords = ['patch']
message_count = 9.0
messages = ['415653', '415655', '415680', '415682', '415729', '415770', '415771', '415774', '415778']
nosy_count = 4.0
nosy_names = ['vstinner', 'asvetlov', 'yselivanov', 'kumaraditya']
pr_nums = ['32020', '32040']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue47076'
versions = ['Python 3.11']

[vstinner]

x86-64 macOS 3.x failures:

• https://buildbot.python.org/all/#/builders/366/builds/2085
• https://buildbot.python.org/all/#/builders/366/builds/2078
• https://buildbot.python.org/all/#/builders/366/builds/2077
• https://buildbot.python.org/all/#/builders/366/builds/2073
• https://buildbot.python.org/all/#/builders/366/builds/2072
• https://buildbot.python.org/all/#/builders/366/builds/2069

Logs:
---
0:18:33 load avg: 2.21 Re-running test_asyncio in verbose mode (matching: test_get_cancelled)
test_get_cancelled (test.test_asyncio.test_queues.QueueGetTests) ... ERROR

======================================================================
ERROR: test_get_cancelled (test.test_asyncio.test_queues.QueueGetTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.billenstein-macos/build/Lib/asyncio/tasks.py", line 490, in wait_for
    return fut.result()
           ^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.billenstein-macos/build/Lib/asyncio/queues.py", line 158, in get
    await getter
    ^^^^^^^^^^^^
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.billenstein-macos/build/Lib/unittest/async_case.py", line 66, in _callTestMethod
    if self._callMaybeAsync(method) is not None:
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.billenstein-macos/build/Lib/unittest/async_case.py", line 93, in _callMaybeAsync
    return self._asyncioTestLoop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.billenstein-macos/build/Lib/asyncio/base_events.py", line 650, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.billenstein-macos/build/Lib/test/test_asyncio/test_queues.py", line 179, in test_get_cancelled
    self.assertEqual(1, await get_task)
                        ^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.billenstein-macos/build/Lib/test/test_asyncio/test_queues.py", line 174, in queue_get
    return await asyncio.wait_for(q.get(), 0.051)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.billenstein-macos/build/Lib/asyncio/tasks.py", line 492, in wait_for
    raise exceptions.TimeoutError() from exc
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
TimeoutError

---

Recent change related to this test:

commit e707ceb
Author: Andrew Svetlov <andrew.svetlov@gmail.com>
Date: Wed Mar 16 16:59:12 2022 +0200

Rewrite asyncio.Queue tests with IsolatedAsyncioTestCace (bpo-31935)

[vstinner]

Recent change related to this test: commit e707ceb

This change comes from bpo-47035 "Rewrite asyncio queue tests with IsolatedAsyncioTestCase".

[asvetlov]

Again a relative short timeouts and super slow test boxes.
I₩'ll relax numbers.
Thanks forbthe report!

[vstinner]

Again a relative short timeouts and super slow test boxes.

The problem is more that a sleep is not a reliable synchronization primitive:
https://pythondev.readthedocs.io/unstable_tests.html#don-t-use-sleep-as-synchronization

[asvetlov]

The problem is more that a sleep is not a reliable synchronization primitive

Yes, sure! I'm trying to avoid 'sleep for synchronization' when I'm writing new tests or fixing existing ones.

The problem with this particular queue tests is: I rewrote old-styled tests that used a loop time shift generator with IsolatedAsyncioTestCase keeping the minimal invasive changes. It doesn't work well, now tiny shifts are removed; only 'await sleep(0)' are left when a bare context switch is needed without a delay.

[asvetlov]

New changeset 673755b by Andrew Svetlov in branch 'main':
bpo-47076: Make asyncio.Queue stable on slow test boxes (GH-32040)
673755b

[asvetlov]

Fixed.

[vstinner]

Thank you Andrew!

[asvetlov]

Welcome!