The Wayback Machine - https://web.archive.org/web/20221222110415/https://github.com/python/cpython/issues/100419
Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

gathering asyncio open_connection ends up with timing gaps #100419

Open
CastixGitHub opened this issue Dec 21, 2022 · 1 comment
Open

gathering asyncio open_connection ends up with timing gaps #100419

CastixGitHub opened this issue Dec 21, 2022 · 1 comment
Labels
expert-asyncio type-bug An unexpected behavior, bug, or error

Comments

@CastixGitHub
Copy link

CastixGitHub commented Dec 21, 2022

description at bottom (ok it may seem a public webserver scanner, but that's the simpler reproducible example to reason about, our purpose is different)

# © 2022 Vincenzo Castiglia <[email protected]> 3F2AD937F3D77362
import asyncio
import socket
import errno
import random
import struct
import sys
from time import time


STATUSES = {
    0: 'OK',
    errno.ETIMEDOUT: 'TIMEDOUT',
    errno.ECONNREFUSED: 'REFUSED',
    errno.EHOSTUNREACH: 'NOROUTE',
    errno.ENETUNREACH: 'UNREACHABLE',
    errno.ECONNRESET: 'CONNRESET',
    # errno.ECONNABORTED: 'ABORTED',  # this host's network is broken
    # broken pipes: we never write on the socket so should never happen
}


TIMEOUT = 15.0


async def handle_connection(host, port, proto=socket.IPPROTO_TCP, name=''):
    beginning_t = time()
    status = 'OK'
    try:
        c = await asyncio.wait_for(
            asyncio.open_connection(
                host,
                port,
                family=socket.AF_INET,
                proto=proto,
            ),
            timeout=TIMEOUT,
        )
        c[1].close()
    except asyncio.TimeoutError:
        # also OsError can be timeout
        status = 'TIMEDOUT'
    except OSError as ex:
        status = STATUSES[ex.errno]
        if ex.errno == errno.ETIMEDOUT:
            sys.stdout.write('actual oserror timeout')
            sys.stdout.flush()
    return {
        'status': status,
        'elapsed': time() - beginning_t,
        'host': host,
        'port': port,
        'proto': proto,
        'name': name,
    }


def ip_generator():
    ip = socket.inet_ntoa(struct.pack('>I', random.randint(1, 0xffffffff)))
    splitted_ip = [int(n) for n in ip.split('.')]
    if (
            splitted_ip[0] == 0
            or 255 in splitted_ip
            or splitted_ip[0] >= 224
            or splitted_ip[0] == 127
    ):
        yield next(ip_generator())
    yield ip


class SocketGroup(asyncio.TaskGroup):
    def __init__(self):
        super().__init__()
        for v in STATUSES.values():
            setattr(self, v, 0)
        self.elapsed = {}

    def _on_task_done(self, task):
        res = task.result()
        # python has a nice ++ operator
        setattr(self, res['status'], (getattr(self, res['status']) + 1))
        if res['elapsed'] < .1:
            self.elapsed.setdefault(.1, []).append(res['elapsed'])
        elif res['elapsed'] < .3:
            self.elapsed.setdefault(.3, []).append(res['elapsed'])
        elif res['elapsed'] < .5:
            self.elapsed.setdefault(.5, []).append(res['elapsed'])
        elif res['elapsed'] < 1:
            self.elapsed.setdefault(1, []).append(res['elapsed'])
        elif res['elapsed'] < 1.2:
            self.elapsed.setdefault(1.2, []).append(res['elapsed'])
        elif res['elapsed'] < 2.9:
            self.elapsed.setdefault(2.9, []).append(res['elapsed'])
        elif res['elapsed'] < 3.4:
            self.elapsed.setdefault(3.4, []).append(res['elapsed'])
        elif res['elapsed'] < 5:
            self.elapsed.setdefault(5, []).append(res['elapsed'])
        else:
            self.elapsed.setdefault('+', []).append(res['elapsed'])
        return super()._on_task_done(task)


async def main():
    print(f'with timeout set to {TIMEOUT} seconds')
    while True:
        async with SocketGroup() as tg:
            for i in range(512):
                # cannot exceed 1024 otherwise too
                # many file descriptors are open!
                ip = next(ip_generator())
                tg.create_task(
                    handle_connection(
                        ip,
                        80,
                        name=str(i),
                    ),
                )
        times = [f"{s}: {len(v)}" for s, v in tg.elapsed.items()]
        print(f'OK={tg.OK} TIMEDOUT={tg.TIMEDOUT} elapsed={times}')

asyncio.run(main())

execution example

$ python connection_test.py
with timeout set to 15.0 seconds
OK=511 TIMEDOUT=1 elapsed=['0.1: 161', '1.2: 133', '3.4: 132', '+: 86']
OK=512 TIMEDOUT=0 elapsed=['0.1: 130', '0.3: 30', '1.2: 197', '3.4: 132', '+: 23']
OK=511 TIMEDOUT=1 elapsed=['0.1: 92', '0.3: 103', '1.2: 243', '3.4: 73', '+: 1']
OK=512 TIMEDOUT=0 elapsed=['0.1: 148', '0.3: 23', '1.2: 141', '3.4: 130', '+: 70']
OK=512 TIMEDOUT=0 elapsed=['0.1: 157', '0.3: 14', '1.2: 131', '3.4: 135', '+: 75']
OK=511 TIMEDOUT=1 elapsed=['0.1: 153', '0.3: 46', '1.2: 214', '3.4: 98', '+: 1']
OK=512 TIMEDOUT=0 elapsed=['0.1: 136', '0.3: 39', '1.2: 202', '3.4: 124', '+: 11']
OK=512 TIMEDOUT=0 elapsed=['0.1: 107', '0.3: 74', '1.2: 134', '3.4: 127', '+: 70']
OK=512 TIMEDOUT=0 elapsed=['0.1: 122', '0.3: 56', '1.2: 131', '3.4: 130', '+: 73']
OK=511 TIMEDOUT=1 elapsed=['0.1: 77', '0.3: 84', '1.2: 139', '3.4: 137', '+: 75']
OK=512 TIMEDOUT=0 elapsed=['0.1: 146', '0.3: 25', '1.2: 179', '3.4: 130', '+: 32']
OK=512 TIMEDOUT=0 elapsed=['0.1: 138', '0.3: 36', '1.2: 129', '3.4: 129', '+: 80']
OK=512 TIMEDOUT=0 elapsed=['0.1: 123', '0.3: 49', '1.2: 277', '3.4: 63']
OK=512 TIMEDOUT=0 elapsed=['0.1: 157', '0.3: 2', '1.2: 138', '3.4: 129', '+: 86']
OK=512 TIMEDOUT=0 elapsed=['0.1: 142', '0.3: 25', '1.2: 133', '3.4: 129', '+: 83']
OK=512 TIMEDOUT=0 elapsed=['0.1: 112', '0.3: 49', '1.2: 255', '3.4: 96']
OK=512 TIMEDOUT=0 elapsed=['0.1: 161', '0.3: 3', '1.2: 148', '3.4: 133', '+: 67']
OK=512 TIMEDOUT=0 elapsed=['0.1: 145', '0.3: 7', '1.2: 143', '3.4: 125', '+: 92']
OK=512 TIMEDOUT=0 elapsed=['0.1: 117', '0.3: 39', '1.2: 131', '3.4: 129', '+: 96']
OK=512 TIMEDOUT=0 elapsed=['0.1: 122', '0.3: 74', '1.2: 162', '3.4: 141', '+: 13']
OK=512 TIMEDOUT=0 elapsed=['0.1: 153', '1.2: 130', '3.4: 128', '+: 101']
OK=512 TIMEDOUT=0 elapsed=['0.1: 168', '1.2: 247', '3.4: 97']
OK=512 TIMEDOUT=0 elapsed=['0.1: 105', '0.3: 105', '1.2: 196', '3.4: 106']
OK=512 TIMEDOUT=0 elapsed=['0.1: 157', '1.2: 137', '3.4: 127', '+: 91']
OK=512 TIMEDOUT=0 elapsed=['0.1: 162', '1.2: 222', '3.4: 117', '+: 11']
OK=512 TIMEDOUT=0 elapsed=['0.1: 158', '1.2: 151', '3.4: 121', '+: 82']
OK=512 TIMEDOUT=0 elapsed=['0.1: 162', '0.3: 1', '1.2: 130', '3.4: 128', '+: 91']
OK=512 TIMEDOUT=0 elapsed=['0.1: 148', '1.2: 257', '3.4: 107']
OK=512 TIMEDOUT=0 elapsed=['0.1: 162', '1.2: 165', '3.4: 131', '+: 54']
OK=512 TIMEDOUT=0 elapsed=['0.1: 87', '0.3: 69', '1.2: 134', '3.4: 120', '+: 102']
OK=512 TIMEDOUT=0 elapsed=['0.1: 130', '0.3: 26', '1.2: 253', '3.4: 103']
OK=512 TIMEDOUT=0 elapsed=['0.1: 135', '0.3: 21', '1.2: 143', '3.4: 128', '+: 85']
OK=512 TIMEDOUT=0 elapsed=['0.1: 92', '0.3: 69', '1.2: 139', '3.4: 130', '+: 82']
OK=512 TIMEDOUT=0 elapsed=['0.1: 125', '0.3: 38', '1.2: 144', '3.4: 130', '+: 75']
OK=512 TIMEDOUT=0 elapsed=['0.1: 160', '1.2: 142', '3.4: 125', '+: 85']
OK=512 TIMEDOUT=0 elapsed=['0.1: 129', '0.3: 47', '1.2: 136', '3.4: 132', '+: 68']
OK=512 TIMEDOUT=0 elapsed=['0.1: 107', '0.3: 63', '1.2: 135', '3.4: 130', '+: 77']
OK=512 TIMEDOUT=0 elapsed=['0.1: 135', '0.3: 32', '1.2: 128', '3.4: 130', '+: 87']
OK=512 TIMEDOUT=0 elapsed=['0.1: 161', '1.2: 142', '3.4: 123', '+: 86']
OK=512 TIMEDOUT=0 elapsed=['0.1: 132', '0.3: 22', '1.2: 181', '3.4: 126', '+: 51']
OK=512 TIMEDOUT=0 elapsed=['0.1: 85', '0.3: 70', '1.2: 234', '3.4: 116', '+: 7']
OK=503 TIMEDOUT=9 elapsed=['0.1: 135', '1.2: 127', '3.4: 130', '+: 120']
OK=512 TIMEDOUT=0 elapsed=['0.1: 153', '0.3: 12', '1.2: 208', '3.4: 126', '+: 13']
OK=511 TIMEDOUT=1 elapsed=['0.1: 121', '0.3: 49', '1.2: 240', '3.4: 101', '+: 1']
OK=512 TIMEDOUT=0 elapsed=['0.1: 101', '0.3: 78', '1.2: 133', '3.4: 126', '+: 74']
OK=512 TIMEDOUT=0 elapsed=['0.1: 153', '0.3: 7', '1.2: 133', '3.4: 131', '+: 88']
OK=512 TIMEDOUT=0 elapsed=['0.1: 64', '0.3: 197', '1.2: 164', '3.4: 87']
OK=510 TIMEDOUT=2 elapsed=['0.1: 157', '1.2: 247', '3.4: 106', '+: 2']
OK=508 TIMEDOUT=4 elapsed=['0.1: 106', '0.3: 52', '1.2: 127', '3.4: 128', '+: 99']
OK=512 TIMEDOUT=0 elapsed=['0.1: 140', '0.3: 23', '1.2: 227', '3.4: 117', '+: 5']
OK=512 TIMEDOUT=0 elapsed=['0.1: 156', '0.3: 10', '1.2: 130', '3.4: 130', '+: 86']
OK=511 TIMEDOUT=1 elapsed=['0.1: 146', '0.3: 16', '1.2: 140', '3.4: 123', '+: 87']
OK=512 TIMEDOUT=0 elapsed=['0.1: 124', '0.3: 46', '1.2: 137', '3.4: 132', '+: 73']
OK=512 TIMEDOUT=0 elapsed=['0.1: 109', '0.3: 50', '1.2: 138', '3.4: 134', '+: 81']
OK=512 TIMEDOUT=0 elapsed=['0.1: 77', '0.3: 165', '1.2: 194', '3.4: 76']
OK=512 TIMEDOUT=0 elapsed=['0.1: 146', '0.3: 9', '1.2: 246', '3.4: 110', '+: 1']
OK=511 TIMEDOUT=1 elapsed=['0.1: 144', '0.3: 14', '1.2: 140', '3.4: 129', '+: 85']
OK=512 TIMEDOUT=0 elapsed=['0.1: 134', '0.3: 79', '1.2: 135', '3.4: 134', '+: 30']
OK=512 TIMEDOUT=0 elapsed=['0.1: 162', '1.2: 259', '3.4: 91']
OK=510 TIMEDOUT=2 elapsed=['0.1: 159', '1.2: 181', '3.4: 130', '+: 42']
OK=512 TIMEDOUT=0 elapsed=['0.1: 162', '1.2: 228', '3.4: 118', '+: 4']
OK=510 TIMEDOUT=2 elapsed=['0.1: 153', '1.2: 130', '3.4: 129', '+: 100']
OK=512 TIMEDOUT=0 elapsed=['0.1: 164', '1.2: 133', '3.4: 124', '+: 91']
OK=512 TIMEDOUT=0 elapsed=['0.1: 95', '0.3: 107', '1.2: 156', '3.4: 134', '+: 20']
OK=512 TIMEDOUT=0 elapsed=['0.1: 146', '0.3: 7', '1.2: 172', '3.4: 132', '+: 55']
OK=512 TIMEDOUT=0 elapsed=['0.1: 122', '0.3: 40', '1.2: 207', '3.4: 137', '+: 6']
OK=511 TIMEDOUT=1 elapsed=['0.1: 127', '0.3: 40', '1.2: 196', '3.4: 122', '+: 27']
OK=511 TIMEDOUT=1 elapsed=['0.1: 132', '0.3: 87', '1.2: 257', '3.4: 35', '+: 1']
OK=512 TIMEDOUT=0 elapsed=['0.1: 158', '0.3: 10', '1.2: 146', '3.4: 130', '+: 68']
OK=512 TIMEDOUT=0 elapsed=['0.1: 166', '0.3: 7', '1.2: 132', '3.4: 131', '+: 76']
OK=512 TIMEDOUT=0 elapsed=['0.1: 160', '1.2: 258', '3.4: 94']
OK=512 TIMEDOUT=0 elapsed=['0.1: 133', '0.3: 46', '1.2: 208', '3.4: 117', '+: 8']
OK=512 TIMEDOUT=0 elapsed=['0.1: 166', '0.3: 2', '1.2: 134', '3.4: 133', '+: 77']
OK=512 TIMEDOUT=0 elapsed=['0.1: 137', '0.3: 61', '1.2: 222', '3.4: 92']
OK=512 TIMEDOUT=0 elapsed=['0.1: 96', '0.3: 90', '1.2: 268', '3.4: 58']
OK=512 TIMEDOUT=0 elapsed=['0.1: 109', '0.3: 57', '1.2: 266', '3.4: 80']
OK=512 TIMEDOUT=0 elapsed=['0.1: 147', '0.3: 14', '1.2: 133', '3.4: 129', '+: 89']
OK=512 TIMEDOUT=0 elapsed=['0.1: 123', '0.3: 46', '1.2: 263', '3.4: 80']
OK=512 TIMEDOUT=0 elapsed=['0.1: 159', '1.2: 136', '3.4: 114', '+: 103']
OK=512 TIMEDOUT=0 elapsed=['0.1: 130', '0.3: 31', '1.2: 259', '3.4: 92']
OK=512 TIMEDOUT=0 elapsed=['0.1: 132', '0.3: 26', '1.2: 143', '3.4: 123', '+: 88']
OK=511 TIMEDOUT=1 elapsed=['0.1: 120', '0.3: 46', '1.2: 138', '3.4: 137', '+: 71']
OK=512 TIMEDOUT=0 elapsed=['0.1: 159', '1.2: 221', '3.4: 123', '+: 9']
OK=511 TIMEDOUT=1 elapsed=['0.1: 101', '0.3: 63', '1.2: 124', '3.4: 132', '+: 92']
OK=512 TIMEDOUT=0 elapsed=['0.1: 157', '0.3: 5', '1.2: 268', '3.4: 82']
OK=511 TIMEDOUT=1 elapsed=['0.1: 103', '0.3: 63', '1.2: 264', '3.4: 81', '+: 1']
OK=512 TIMEDOUT=0 elapsed=['0.1: 64', '0.3: 99', '1.2: 272', '3.4: 77']
OK=512 TIMEDOUT=0 elapsed=['0.1: 111', '0.3: 47', '1.2: 125', '3.4: 134', '+: 95']
OK=512 TIMEDOUT=0 elapsed=['0.1: 98', '0.3: 83', '1.2: 169', '3.4: 129', '+: 33']
OK=511 TIMEDOUT=1 elapsed=['0.1: 153', '1.2: 216', '3.4: 125', '+: 18']
OK=512 TIMEDOUT=0 elapsed=['0.1: 102', '0.3: 56', '1.2: 246', '3.4: 108']
OK=511 TIMEDOUT=1 elapsed=['0.1: 112', '0.3: 67', '1.2: 130', '3.4: 130', '+: 73']
OK=512 TIMEDOUT=0 elapsed=['0.1: 75', '0.3: 94', '1.2: 131', '3.4: 138', '+: 74']
OK=512 TIMEDOUT=0 elapsed=['0.1: 113', '0.3: 48', '1.2: 162', '3.4: 130', '+: 59']
OK=512 TIMEDOUT=0 elapsed=['0.1: 82', '0.3: 81', '1.2: 131', '3.4: 121', '+: 97']
OK=512 TIMEDOUT=0 elapsed=['0.1: 116', '0.3: 46', '1.2: 135', '3.4: 131', '+: 84']
OK=512 TIMEDOUT=0 elapsed=['0.1: 111', '0.3: 49', '1.2: 263', '3.4: 89']
OK=512 TIMEDOUT=0 elapsed=['0.1: 153', '1.2: 216', '3.4: 119', '+: 24']
OK=512 TIMEDOUT=0 elapsed=['0.1: 80', '0.3: 127', '1.2: 137', '3.4: 126', '+: 42']
OK=512 TIMEDOUT=0 elapsed=['0.1: 95', '0.3: 71', '1.2: 125', '3.4: 134', '+: 87']

As you can see there are no responses in the 0.3-1.0 range, neither in the 1.2-2.9 or 3.4-5 ranges

Can you explain what's going on?

Thanks

Your environment

  • CPython versions tested on: 3.11.0 (and 3.10 using gather instead of TaskGroup)
  • Operating system and architecture: archlinux x86_64
  • cpu: i7-1165G7
  • network controllers: RTL8111/8168/8411 and intel AX201
  • two network connections from different ISP
@CastixGitHub CastixGitHub added the type-bug An unexpected behavior, bug, or error label Dec 21, 2022
@gvanrossum
Copy link
Member

gvanrossum commented Dec 22, 2022

I'm sorry, I'm not going to try to debug that much code. I'm not even sure what you're saying the problem is. Just that the distribution of timeouts is not what you expected? Why should that point to a bug in asyncio?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
expert-asyncio type-bug An unexpected behavior, bug, or error
Projects
asyncio
Status: Todo
Milestone
No milestone
Development

No branches or pull requests
3 participants
@gvanrossum @CastixGitHub @AlexWaygood