Repository navigation
BaseSelectorEventLoop.sock_{recv,sendall}() don't remove their callbacks when canceled #74250
Description
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 = 'https://github.com/asvetlov'
closed_at = None
created_at = <Date 2017-04-13.08:55:09.854>
labels = ['type-bug', '3.9', '3.10', 'expert-asyncio']
title = "BaseSelectorEventLoop.sock_{recv,sendall}() don't remove their callbacks when canceled"
updated_at = <Date 2020-06-15.16:37:16.856>
user = 'https://bugs.python.org/abacabadabacaba'bugs.python.org fields:
activity = <Date 2020-06-15.16:37:16.856>
actor = 'vstinner'
assignee = 'asvetlov'
closed = False
closed_date = None
closer = None
components = ['asyncio']
creation = <Date 2017-04-13.08:55:09.854>
creator = 'abacabadabacaba'
dependencies = []
files = ['49146']
hgrepos = []
issue_num = 30064
keywords = ['patch']
message_count = 41.0
messages = ['291593', '326294', '329746', '355272', '355273', '357989', '358011', '358098', '358108', '362637', '362671', '362690', '368553', '368701', '368702', '370123', '370131', '370143', '370147', '370159', '370161', '370205', '370215', '370218', '370219', '370234', '370268', '370269', '371240', '371247', '371467', '371478', '371479', '371485', '371489', '371490', '371491', '371492', '371495', '371498', '371499']
nosy_count = 9.0
nosy_names = ['fantix', 'ned.deily', 'asvetlov', 'abacabadabacaba', 'lukasz.langa', 'yselivanov', 'achimnol', 'miss-islington', 'aeros']
pr_nums = ['10419', '20369', '20460', '20485', '20487', '20494', '20503', '20868', '20869']
priority = 'high'
resolution = None
stage = 'commit review'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue30064'
versions = ['Python 3.9', 'Python 3.10']Metadata
Metadata
Assignees
Projects
- Status
Activity
asvetlov commentedon Dec 9, 2019
As I wrote, I don't think that we should fix the code but the failed uvloop test is slightly weird instead.
Maybe I'm wrong, I need to communicate with Yuri anyway.
ambv commentedon Feb 25, 2020
Downgrading priority on this one.
1st1 commentedon Feb 25, 2020
Hm, cancellation should work correctly no matter how "sane" or "insane" the user code is.
But we're not discussing using a socket concurrently -- asyncio explicitly does not support that for the sock_ api.
AFAICT this issue is about consequent cancel operation not working as expected in asyncio, no?
asvetlov commentedon Feb 26, 2020
This is a very interesting question.
In asyncio, task cancellation is not executed on
task.cancel()call immediately but the task is marked for cancellation.The actual cancellation requires a context switch (await asyncio.sleep(0) or similar) to propagate
asyncio.CancelledErrorinto the task code and unwind the exception.As I said, the test needs a context switch between
cancel()call and analyzing the state after the task cancellation.Futures are canceled immediately, that's why the previous implementation passed uvloop's test suite untouched. Unfortunately, it had own flaws.
Also please note, sock_connect()/sock_accept() were implemented this way about two years before my changes, they also suffer from cancel-without-actual-cancellation problems as well.
fantix commentedon May 9, 2020
Following the discussion - looks like
add_reader()will cancel the previoushandleon the samefdif found, so I think it is reasonable to solve this cancellation-race issue by checking if thehandleis cancelled as shown in the attached patch (tests in uvloop passed with this patch). WDTY?achimnol commentedon May 12, 2020
I just encountered this issue when doing "sys.exit(1)" on a Click-based CLI program that internally uses asyncio event loop via wrapped via a context manager, on Python 3.8.2.
Using uvloop or adding "time.sleep(0.1)" before "sys.exit(1)" removes the error.
achimnol commentedon May 12, 2020
And I suspect that this issue is something simliar to what I did in a recent janus PR:
https://github.com/aio-libs/janus/blob/ec8592b91254971473b508313fb91b01623f13d7/janus/__init__.py#L84
to give a chance for specific callbacks to execute via an extra context switch.
1st1 commentedon May 27, 2020
New changeset 210a137 by Fantix King in branch 'master':
bpo-30064: Fix asyncio loop.sock_* race condition issue (bpo-20369)
210a137
miss-islington commentedon May 27, 2020
New changeset 3a2667d by Miss Islington (bot) in branch '3.9':
bpo-30064: Fix asyncio loop.sock_* race condition issue (GH-20369)
3a2667d
vstinner commentedon May 27, 2020
The new test_sock_client_racing() test seems to have... a race condition...
AMD64 FreeBSD Non-Debug 3.9:
https://buildbot.python.org/all/#/builders/750/builds/11
ERROR: test_sock_client_racing (test.test_asyncio.test_sock_lowlevel.KqueueEventLoopTests)
ERROR: test_sock_client_racing (test.test_asyncio.test_sock_lowlevel.PollEventLoopTests)
ERROR: test_sock_client_racing (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests)
Example:
ERROR: test_sock_client_racing (test.test_asyncio.test_sock_lowlevel.PollEventLoopTests)
----------------------------------------------------------------------
fantix commentedon May 27, 2020
Ouch ... looks like FreeBSD also needs a few more retries than a single retry. I'll test on a FreeBSD and create a PR for that.
fantix commentedon May 28, 2020
Not a simple one - FreeBSD is returning ECONNREFUSED immediately when trying to connect to a non-listening port on the loopback address:
https://lists.freebsd.org/pipermail/freebsd-current/2005-May/049876.html
Then all following connect attempts on the same socket return ECONNREFUSED regardless of whether the port is listening or not. I think I'll have to skip this test on FreeBSD.
aeros commentedon May 28, 2020
I'm also a bit skeptical about relying on
time.sleep(0.01)at the end of the loop in_basetest_sock_recv_racing(), but I don't have an idea for a better approach at the moment.vstinner commentedon May 28, 2020
I created #20485 to skip the unstable tests until someone fix them. IMO it's better to skip the test than reverting the fix, since the fix does fix a race condition.
The test is still failing on buildbots which makes analysis of buildbot failures more difficult. For example, a SQLite change got 3 different 4 different bugs on buildbots:
#20448 (comment)
See the "revert on fail" policy for buildbots:
https://pythondev.readthedocs.io/ci.html#revert-on-fail
Yeah, please avoid sleep as a synchronization primitive:
https://pythondev.readthedocs.io/unstable_tests.html#don-t-use-sleep-as-synchronization
vstinner commentedon May 28, 2020
New changeset 84ee7e1 by Victor Stinner in branch 'master':
bpo-30064: Fix unstable asyncio "racing" socket tests (GH-20485)
84ee7e1
miss-islington commentedon May 28, 2020
New changeset 1d82f00 by Miss Islington (bot) in branch '3.9':
bpo-30064: Fix unstable asyncio "racing" socket tests (GH-20485)
1d82f00
vstinner commentedon May 28, 2020
Sorry. You should read "Skip" tests, not "Fix" tests :-p
fantix commentedon May 28, 2020
Thanks for the comments! Added PR 20494 to properly fix/skip the test for (hopefully) all platforms.
1st1 commentedon May 28, 2020
New changeset dc4eee9 by Fantix King in branch 'master':
bpo-30064: Properly skip unstable loop.sock_connect() racing test (GH-20494)
dc4eee9
miss-islington commentedon May 28, 2020
New changeset 6637bd4 by Miss Islington (bot) in branch '3.9':
bpo-30064: Properly skip unstable loop.sock_connect() racing test (GH-20494)
6637bd4
vstinner commentedon Jun 10, 2020
Another kind of failure on x86 Gentoo Installed with X 3.x:
https://buildbot.python.org/all/#/builders/128/builds/1030
ERROR: test_sock_client_racing (test.test_asyncio.test_sock_lowlevel.EPollEventLoopTests)
----------------------------------------------------------------------
fantix commentedon Jun 10, 2020
I'm checking now
fantix commentedon Jun 13, 2020
I've been testing on local VMs with Gentoo and Ubuntu, but the issue cannot be reproduced. The error log is not really revealing anything useful, other than that the send was blocked when it was supposed to be successful. As it is not constantly failing on buildbot (https://buildbot.python.org/all/#/builders/128), I don't know if it is worth it to add some more debug code to this test in master and wait for the next hang. Please kindly advise.
aeros commentedon Jun 14, 2020
I was able to replicate the failure locally by running the large number of jobs in parallel. We typically use this to test for tricky race conditions, to simulate maximum load:
[aeros:~/repos/cpython]$ ./python -m test test_asyncio.test_sock_lowlevel --match test_sock_client_racing -j100 -F -v
# [snip]
======================================================================
ERROR: test_sock_client_racing (test.test_asyncio.test_sock_lowlevel.EPollEventLoopTests)
----------------------------------------------------------------------
======================================================================
ERROR: test_sock_client_racing (test.test_asyncio.test_sock_lowlevel.PollEventLoopTests)
----------------------------------------------------------------------
======================================================================
ERROR: test_sock_client_racing (test.test_asyncio.test_sock_lowlevel.SelectEventLoopTests)
----------------------------------------------------------------------
I'll try to add some debug lugs to find the source of the failure(s). This one might be a bit tricky to assess though.
@fantix I'd recommend trying to run the local test with the above command, and increasing the parallel job count until it occurs. If it takes more than a minute or two for the tests to run, slowly lower the number. At the moment, the failure has only occurred once in the buildbots, but we might need to temporarily disable it if it occurs repeatedly or find some form of workaround (as it will potentially mask other bugs).
aeros commentedon Jun 14, 2020
I believe that I might have identified a simple fix for the issue, but first I'd like to clarify on something:
What exactly is the reason that we need to use asyncio.wait_for() with a timeout of 10 seconds in these tests? We typically avoid using short duration timeouts on individual tests, largely because we don't want them to fail based on the performance of the device they're ran on. This can be a concern for slower devices running the test suite w/ parallel jobs.
If asyncio.wait_for() is necessary in this case, I'd advise increasing the timeout substantially. I didn't experiment with a wide variety of numbers, but increasing the duration from 10 to 60 seconds seems to have fixed the failure locally, so that might be a decent starting point. If it's not necessary, I'd prefer to simply remove the asyncio.wait_for()s in test_sock_client_racing.
fantix commentedon Jun 14, 2020
Oh thank you for the clue, that's super helpful! Let me try locally.
This fix PR was originally done to solve a hanging call in a race condition, so the test would hang forever if the fix is not working as expected. The 10 seconds wait_for() is to make sure that we don't end up with a test hanging forever.
If enlarging the timeout works in some of your cases, that really inspires me on a potential cause of the issue in the test. To simulate the race condition specifically for loop.sock_sendall(), I needed a connected socket with a full send buffer so that the next sock_sendall() call would block. To achieve this, I wrote something like this:
And another loop in a subtask to consume the data:
It might be that it cost too much time in these loops (especially the 2nd one because the logs showed that it was blocked on calling sock_sendall()). But that's just a guess yet, let me add some more debug logs and test locally.
aeros commentedon Jun 14, 2020
No problem at all, and thanks for clarifying.
That seems reasonable to me and would make the most sense at a glance. If this is confirmed to be the source of the issue, we should be able to just reduce the size of the socket's send buffer via SO_SNDBUF before sending to it so that it fills up much more quickly.
fantix commentedon Jun 14, 2020
OK I think I solved the problem by improving the two loops using smarter buffer sizes:
and
This test is now running ~25x faster, and the load test crashed my laptop a few times before it hits a timeout.
Last question before PR pls: given the fact that this test is to cover a fixed case when loop.sock_*() was hanging forever, should I keep the wait_for(..., timeout=10)?
fantix commentedon Jun 14, 2020
and yes, updated the SO_SNDBUF too
aeros commentedon Jun 14, 2020
For now, I think we can keep the asyncio.wait_for() w/ 10 the sec timeout. I'll have to run the tests locally though w/ the patch to double check (once the PR is opened), and it may still end up needing to be increased if the test fails again in the future. It should be okay though.
miss-islington commentedon Jun 14, 2020
New changeset 8f04a84 by Fantix King in branch 'master':
bpo-30064: Fix slow asyncio sock test (GH-20868)
8f04a84
miss-islington commentedon Jun 14, 2020
New changeset 83cd968 by Miss Islington (bot) in branch '3.9':
bpo-30064: Fix slow asyncio sock test (GH-20868)
83cd968
aeros commentedon Jun 14, 2020
Thanks again for working on this @fantix, and for the continued vigilance on the issue after the test failures occurred in the buildbots. I think this recent PR-20868 will do the trick. At the very least, it will make the failure much more rare than before, which is definitely an improvement.