Request.transport is sometimes None

[hynek]

Long story short

The transport attribute on requests is sometimes (like 1/month on a rather idle system!?) None – I cannot figure out why?

Expected behaviour

Either never be None or an explanation in http://docs.aiohttp.org/en/stable/web_reference.html#aiohttp.web.BaseRequest.transport

Could it be some kind of cancellation behavior!?

Actual behaviour

I get an email from Sentry that 'NoneType' object has no attribute 'get_extra_info'.

Steps to reproduce

I have no idea. I don’t even have an idea whether it’s a behavioral or documentation bug. :(

Your environment

Bionic Beaver in a Docker container; aiohttp 3.4.4. This doesn’t appear to be a recent regression though, I just lived with it because I had no clue what to do about it.

[webknjaz]

Hey @hynek, maybe it's asyncio's bug? As mentioned in home-assistant/core#9762 (comment)

[webknjaz]

Ref #889

[hynek]

FWIW I’m on Python 3.7.0 so it shouldn’t be an issue; however I’m using uvloop.

[hellysmile]

it seems when request if fully finished and underlying connection is returned to the pool transport is None, as well if You request is small, transport might be None, even before read()

[hynek]

This is server-side, so I hope the request can't be finished before I return something. ;)

[hellysmile]

Sorry, I was lost, had similar issues with client

[asvetlov]

What is your stack trace?
I suspect it is something like #3177

[hynek]

There is no stack trace: I have an incoming request and I need to find out the peer IP. So I look at request.transport and it’s sometimes None. I just need to find out what it means. :)

[mykola-mokhnach]

Not sure if this is connected, but I observe a random AssertionError while calling await ws.prepare(request) method in aiohttp 3.8.3

The exception is raised by the following call stack:

    async def prepare(self, request: BaseRequest) -> AbstractStreamWriter:
        # make pre-check to don't hide it by do_handshake() exceptions
        if self._payload_writer is not None:
            return self._payload_writer

>>>        protocol, writer = self._pre_start(request)
        payload_writer = await super().prepare(request)
        assert payload_writer is not None
        self._post_start(request, protocol, writer)
        await payload_writer.drain()
        return payload_writer

....

    def _pre_start(self, request: BaseRequest) -> Tuple[str, WebSocketWriter]:
        self._loop = request._loop

        headers, protocol, compress, notakeover = self._handshake(request)

        self.set_status(101)
        self.headers.update(headers)
        self.force_close()
        self._compress = compress
        transport = request._protocol.transport
>>>        assert transport is not None
        writer = WebSocketWriter(
            request._protocol, transport, compress=compress, notakeover=notakeover
        )

        return protocol, writer

[sedrakk]

Same

Task exception was never retrieved
future: <Task finished name='Task-51442' coro=<RequestHandler.start() done, defined at /layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_protocol.py:462> exception=AssertionError()>
Traceback (most recent call last):
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 505, in start
    request = self._request_factory(message, payload, self, writer, handler)
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_app.py", line 446, in _make_request
    return _cls(
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_request.py", line 811, in __init__
    super().__init__(*args, **kwargs)
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_request.py", line 188, in __init__
    assert transport is not None
AssertionError

[andig]

I can repro this 100% all the time when connecting via proxy:

self.websession = aiohttp.ClientSession(trace_configs=[trace_config], trust_env=True, connector=aiohttp.TCPConnector(verify_ssl=False))

Gives

Traceback (most recent call last):
  File "/Users/andig/htdocs/pypo/cli.py", line 4, in <module>
    cli()
  File "/Users/andig/htdocs/pypo/pyporscheconnectapi/cli.py", line 270, in cli
    loop.run_until_complete(main(args))
  File "/opt/homebrew/Cellar/[email protected]/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/Users/andig/htdocs/pypo/pyporscheconnectapi/cli.py", line 47, in main
    data = await client.getVehicles()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/andig/htdocs/pypo/pyporscheconnectapi/client.py", line 448, in getVehicles
    vehicles = await self._connection.get(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/andig/htdocs/pypo/pyporscheconnectapi/connection.py", line 236, in get
    async with self.websession.get(url, params=params, headers=headers) as resp:
  File "/opt/homebrew/lib/python3.11/site-packages/aiohttp/client.py", line 1141, in __aenter__
    self._resp = await self._coro
                 ^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/aiohttp/client.py", line 536, in _request
    conn = await self._connector.connect(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/aiohttp/connector.py", line 540, in connect
    proto = await self._create_connection(req, traces, timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/aiohttp/connector.py", line 899, in _create_connection
    _, proto = await self._create_proxy_connection(req, traces, timeout)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/aiohttp/connector.py", line 1325, in _create_proxy_connection
    return await self._start_tls_connection(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/aiohttp/connector.py", line 1124, in _start_tls_connection
    tls_proto.connection_made(
  File "/opt/homebrew/lib/python3.11/site-packages/aiohttp/base_protocol.py", line 62, in connection_made
    tcp_nodelay(tr, True)
  File "/opt/homebrew/lib/python3.11/site-packages/aiohttp/tcp_helpers.py", line 25, in tcp_nodelay
    sock = transport.get_extra_info("socket")
           ^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get_extra_info'
ERROR:asyncio:Unclosed client session
client_session: <aiohttp.client.ClientSession object at 0x1023fda50>

Proxy is up and running. As soon as I remove the trust_env: True everything is back to normal.

I'm totally blocked from connecting via proxy right now. Given this issue is already from 2018: what can we do to move it forward?

[Dreamsorcerer]

I'm totally blocked from connecting via proxy right now. Given this issue is already from 2018: what can we do to move it forward?

Your traceback shows the transport was created at https://github.com/aio-libs/aiohttp/blob/3.8/aiohttp/connector.py#L1091
And then it's just passed through without modification. So, this looks like a cpython bug.

If you can log the values around that call to be sure (both the return value, and the input values), then I suggest creating a cpython bug report including that information (or go a step further and start debugging that call itself: https://github.com/python/cpython/blob/dba72175116373c1d15e25d84c88b516daf9f5c4/Lib/asyncio/base_events.py#L1242).

[andig]

Unfortunately I have zero knowledge about (c)python which makes even logging difficult. If you have concrete suggestions what to log and how to test that (build cpython from scratch?) I'd be happy to give it a try.

[Dreamsorcerer]

print(underlying_transport)
print(tls_transport)

You should be able to clone the aiohttp repo and run it from there directly (using PYTHONPATH to import it from your project).
For cpython, I'm lazy and often just end up editing the installed files as root, then reverting the changes or reinstalling Python when I'm done (it is in a container though).

[andig]

Here we go:

underlying_transport <_SelectorSocketTransport closing fd=6 read=idle write=<idle, bufsize=0>>
tls_transport None

Going further into

tls_transport = await self._loop.start_tls(...)

doesn't work as this seems to be abstract.

[Dreamsorcerer]

Maybe it has something to do with the closing...
Possibly still a cpython bug that it returns None, but I guess the root of the problem is that it is already closing.

[Dreamsorcerer]

OK, I'm not sure of the exact flow, but I think because it is closing, inside that call the connection_made() method gets called, which sets it to None before it returns.

[andig]

Looks like this might be the cause: #6239 (comment)

[Dreamsorcerer]

Yep, that seems to match what I said. I guess that code didn't exist in 3.7, it was probably added in relation to TLS in proxies.

[Dreamsorcerer]

I've asked what the expected behaviour is:
python/cpython#105993

[Dreamsorcerer]

That thread has resolved, so we do need to check for None, and future mypy versions will also highlight the error.

[andig]

@Dreamsorcerer I'm not a Python guy but it seems (without having tested) that this is the wrong fix. According to #3355 (comment) I can repro the issue 100% of time when using proxy. #7333 "fixes" that by raising a client error. I cannot say if that error is later handled, but if not proxy connection will still be broken.

Unless the conjecture is wrong- given this fix we have error handling now but still no working proxy connection?

[Dreamsorcerer]

I think there are multiple causes. The PR fixes the type error, which should cause any errors to be handled more gracefully.

Please retest with the next release and open any new issues that still occur. I suspect the proxy issue is still there, but maybe the intermittent errors other people are seeing will no longer be an issue. But, I'm pretty sure there are several root causes all resulting in this type error, so this should help to separate them into different issues.

[sedrakk]

Any ideas when would this be released?

[Dreamsorcerer]

Probably a bugfix release in the coming weeks, then I'll start preparing a beta release for 3.9.

[andig]

I will retest the proxy behaviour as soon as I find a way to depend on the package. If that's possible on the git version happy to follow up if I get a hint.

[Dreamsorcerer]

If you want to run from source, you can just add it to PYTHONPATH or pip install . and get the pure Python install used easily. If you want the C extensions for performance, then you need init the vendor/llhttp/ submodule and run make cythonize first.

Remember to checkout the 3.8 branch, rather than master.

[sedrakk]

I think still reproducing in my case on 3.8.5. Tbh I'm not even sure this is always related to web socket, it happens in the rest api code too. And I can't figure out which part of the code results in this error. Can happen in any end point in a random place.

python.exc_info: "Traceback (most recent call last):
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 505, in start
    request = self._request_factory(message, payload, self, writer, handler)
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_app.py", line 446, in _make_request
    return _cls(
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_request.py", line 811, in __init__
    super().__init__(*args, **kwargs)
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_request.py", line 188, in __init__
    assert transport is not None
AssertionError
"
python.filename: "functools.py"
python.funcName: "update_wrapper"
python.lineno: 50
python.logger_name: "asyncio"
python.module: "functools"
python.pid: 15

python.exc_info: "Traceback (most recent call last):
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 505, in start
    request = self._request_factory(message, payload, self, writer, handler)
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_app.py", line 446, in _make_request
    return _cls(
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_request.py", line 811, in __init__
    super().__init__(*args, **kwargs)
  File "/layers/google.python.pip/pip/lib/python3.10/site-packages/aiohttp/web_request.py", line 188, in __init__
    assert transport is not None
AssertionError
"
python.filename: "__init__.py"
python.funcName: "decode_all"
python.lineno: 1122
python.logger_name: "asyncio"
python.module: "__init__"
python.pid: 15
python.thread: "ThreadPoolExecutor-0_0"

[Dreamsorcerer]

I think still reproducing in my case on 3.8.5. Tbh I'm not even sure this is always related to web socket, it happens in the rest api code too. And I can't figure out which part of the code results in this error. Can happen in any end point in a random place.

That's a different traceback from above posts, so looks like a different cause. Looking at the code which leads to there, my only guess is that there is a race condition. There is an await self._waiter line, and I think it's possible that the connection could be closed after that future has been set, but before the event loop runs the code waiting on it.

Could you add a print(self._force_close, self._close) line before

aiohttp/aiohttp/web_protocol.py

Line 505 in 8d701c3

request = self._request_factory(message, payload, self, writer, handler)

Then we can confirm if it has been closed. To double check, you could also print at

aiohttp/aiohttp/web_protocol.py

Line 347 in 8d701c3

waiter.set_result(None)

I'd expect to see it is not closed in the latter line, and then closed in the former.