Unexpected asyncio.CancelledError

[TheTechromancer]

First off, thanks for making this library, it's very useful.

There appears a rare condition where on issuing an asynchronous web request, an asyncio.CancelledError is raised from somewhere deep inside httpcore. Nowhere are we cancelling tasks, however we are enforcing timeouts via a timeout=20 kwarg to AsyncClient.

We are issuing a large number of web requests (in the millions), so while I haven't been able to reproduce this in isolation, I was able to capture a traceback from our production logs:

Traceback (most recent call last):
  File "/root/bbot/bbot/core/helpers/web.py", line 116, in request
    response = await client.request(*args, **kwargs)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1530, in request
    return await self.send(request, auth=auth, follow_redirects=follow_redirects)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1617, in send
    response = await self._send_handling_auth(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1645, in _send_handling_auth
    response = await self._send_handling_redirects(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1682, in _send_handling_redirects
    response = await self._send_single_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1719, in _send_single_request
    response = await transport.handle_async_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_transports/default.py", line 353, in handle_async_request
    resp = await self._pool.handle_async_request(req)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 262, in handle_async_request
    raise exc
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 245, in handle_async_request
    response = await connection.handle_async_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 69, in handle_async_request
    stream = await self._connect(request)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 117, in _connect
    stream = await self._network_backend.connect_tcp(**kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_backends/auto.py", line 31, in connect_tcp
    return await self._backend.connect_tcp(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_backends/anyio.py", line 114, in connect_tcp
    stream: anyio.abc.ByteStream = await anyio.connect_tcp(
                                   ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/anyio/_core/_sockets.py", line 221, in connect_tcp
    await event.wait()
  File "/usr/lib/python3.11/site-packages/anyio/_backends/_asyncio.py", line 1778, in wait
    if await self._event.wait():
       ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/locks.py", line 213, in wait
    await fut
asyncio.exceptions.CancelledError

[zanieb]

Hey! Thanks for opening a discussion.

Is there anywhere in your code that could be starting cancellation? Asynchronous cancellation fires on the first unshielded await and that may just happen to be during establishment of a connection by HTTPX.

[TheTechromancer]

Talked to the creator of AnyIO, who was very helpful. He had this to say:

Concurrency in programming is hard. We're trying to make it less painful (structured concurrency helps a lot), but we still have ways to go.

As far as your traceback goes, it's hard to say where this cancellation comes from, but it doesn't seem to come from AnyIO, as the exception would not fall out of a task. If you want to be sure, try with AnyIO 4.0 (you should see a message associated with the exception if, by some chance, an AnyIO exception did in fact fall out of a task). It's a good idea to switch anyway given the myriad cancellation related fixes that went into the release. Best of luck!

[tomchristie]

So... that looks like a connection timeout that's somehow ending up as a CancelledError rather than a TimeoutError.

Linking to where we call into anyio.connect_tcp for ease of reference.

Perhaps a good approach would be for someone to try to reproduce this in isolation with a large number of concurrent anyio.connect_tcp() calls wrapped in anyio.fail_after(), and determine if there's some fuzziness there where a CancelledError sometimes occurs instead of a TimeoutError.

Going through some of the anyio/httpcore source code, I'm starting to realize how much of a pain this type of bug is to troubleshoot.
Am I wrong in thinking there's no way to actually tell which task was cancelled, or where?

Incidental... at what point do we push folks more strongly towards trio as the best practise for async codebases?

[zanieb]

I'm starting to realize how much of a pain this type of bug is to troubleshoot. Am I wrong in thinking there's no way to actually tell which task was cancelled, or where?

Yeah unfortunately this is the state of Python's asyncio https://discuss.python.org/t/tracking-the-source-of-cancellation-in-tasks/18352

[TheTechromancer]

Perhaps a good approach would be for someone to try to reproduce this in isolation with a large number of concurrent anyio.connect_tcp() calls wrapped in anyio.fail_after(), and determine if there's some fuzziness there where a CancelledError sometimes occurs instead of a TimeoutError.

In my own efforts to reproduce this, I've tried creating a large number of request timeouts, but I haven't been able to reproduce it.

I suspect that whatever condition is causing this is very specific -- maybe a protocol mismatch, an abrupt server-side abort, or something similar.

[TheTechromancer]

My fuzzing so far has coaxed out two separate errors:

• anyio.EndOfStream
• ssl.SSLError

I suspect these are two different bugs and may not be relevant to this specific issue. I have already encountered these in my code and am handling them. However it's possible they exist in close proximity.

The errors can be reproduced by spinning up a local python -m http.server, issuing a large number of HTTPS requests (protocol mismatch) while repeatedly killing and restarting the server process:

Server:

#!/bin/bash

# Function to handle SIGINT
function handle_sigint {
    echo "Stopping server..."
    kill -9 $SERVER_PID
    exit 1
}

# Set the trap
trap 'handle_sigint' INT

while true; do
    # Start the Python HTTP server in the background
    python -m http.server 5555 &

    # Save the process ID
    SERVER_PID=$!

    # Let it run for .1 seconds
    sleep .1

    # Kill the server
    kill -9 $SERVER_PID

    sleep .1
done

Client:

import ssl
import anyio
import httpx
import random
import asyncio

async def main():

    async def request():
        async with httpx.AsyncClient(timeout=random.random()/2) as client:
            try:
                return await client.get('https://127.0.0.1:5555')
            except httpx.RequestError as e:
                print('.', end='', flush=True)
            except ssl.SSLError:
                print('+', end='', flush=True)
            except anyio.EndOfStream:
                print('=', end='', flush=True)

    while 1:
        tasks = [asyncio.create_task(request()) for _ in range(100)]
        await asyncio.gather(*tasks)

asyncio.run(main())

anyio.EndOfStream:

Traceback (most recent call last):
  File "test.py", line 41, in <module>
    asyncio.run(main())
  File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/home/bls/Downloads/code/bbot/stuff3.py", line 38, in main
    await asyncio.gather(*tasks)
  File "/home/bls/Downloads/code/bbot/stuff3.py", line 28, in request
    return await client.get('https://127.0.0.1:5555')
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1757, in get
    return await self.request(
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1530, in request
    return await self.send(request, auth=auth, follow_redirects=follow_redirects)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1617, in send
    response = await self._send_handling_auth(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1645, in _send_handling_auth
    response = await self._send_handling_redirects(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1682, in _send_handling_redirects
    response = await self._send_single_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1719, in _send_single_request
    response = await transport.handle_async_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_transports/default.py", line 353, in handle_async_request
    resp = await self._pool.handle_async_request(req)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 262, in handle_async_request
    raise exc
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 245, in handle_async_request
    response = await connection.handle_async_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 92, in handle_async_request
    raise exc
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 69, in handle_async_request
    stream = await self._connect(request)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 149, in _connect
    stream = await stream.start_tls(**kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_backends/anyio.py", line 78, in start_tls
    raise exc
  File "/usr/lib/python3.11/site-packages/httpcore/_backends/anyio.py", line 69, in start_tls
    ssl_stream = await anyio.streams.tls.TLSStream.wrap(
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/anyio/streams/tls.py", line 125, in wrap
    await wrapper._call_sslobject_method(ssl_object.do_handshake)
  File "/usr/lib/python3.11/site-packages/anyio/streams/tls.py", line 165, in _call_sslobject_method
    raise EndOfStream from None
anyio.EndOfStream

ssl.SSLError:

Traceback (most recent call last):
  File "test.py", line 41, in <module>
    asyncio.run(main())
  File "/usr/lib/python3.11/asyncio/runners.py", line 190, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "test.py", line 38, in main
    await asyncio.gather(*tasks)
  File "test.py", line 28, in request
    return await client.get('https://127.0.0.1:5555')
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1757, in get
    return await self.request(
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1530, in request
    return await self.send(request, auth=auth, follow_redirects=follow_redirects)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1617, in send
    response = await self._send_handling_auth(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1645, in _send_handling_auth
    response = await self._send_handling_redirects(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1682, in _send_handling_redirects
    response = await self._send_single_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_client.py", line 1719, in _send_single_request
    response = await transport.handle_async_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpx/_transports/default.py", line 353, in handle_async_request
    resp = await self._pool.handle_async_request(req)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 262, in handle_async_request
    raise exc
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 245, in handle_async_request
    response = await connection.handle_async_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 92, in handle_async_request
    raise exc
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 69, in handle_async_request
    stream = await self._connect(request)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 149, in _connect
    stream = await stream.start_tls(**kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/httpcore/_backends/anyio.py", line 78, in start_tls
    raise exc
  File "/usr/lib/python3.11/site-packages/httpcore/_backends/anyio.py", line 69, in start_tls
    ssl_stream = await anyio.streams.tls.TLSStream.wrap(
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/anyio/streams/tls.py", line 125, in wrap
    await wrapper._call_sslobject_method(ssl_object.do_handshake)
  File "/usr/lib/python3.11/site-packages/anyio/streams/tls.py", line 133, in _call_sslobject_method
    result = func(*args)
             ^^^^^^^^^^^
  File "/usr/lib/python3.11/ssl.py", line 979, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: WRONG_VERSION_NUMBER] wrong version number (_ssl.c:1002)

[TheTechromancer]

Okay!!! I was able to reliably reproduce the CancelledError with the following code. The bug only triggers when a custom transport is specified, and only when retries are greater than zero. (httpx.AsyncHTTPTransport(retries=2))

import httpx
import random
import asyncio

## STEP 1:
##   python -m http.server 5555

async def main():
    async def request():
        transport = httpx.AsyncHTTPTransport(retries=5) # <-----------------------
        async with httpx.AsyncClient(transport=transport, timeout=random.random() / 10) as client:
            try:
                return await client.get("http://127.0.0.1:5555")
            except httpx.TimeoutException:
                print("_", end="", flush=True)

    while 1:
        tasks = [asyncio.create_task(request()) for _ in range(100)]
        await asyncio.gather(*tasks)


asyncio.run(main())

[TheTechromancer]

Aaaaaaaaand.....it's no longer reproducible with anyio==4.0.0rc1. Thanks folks! It's been lovely talking to you all!