Strange WebSocket behavior since version 3.7

[decaz]

Close code of WebSocket became different after upgrading aiohttp from version 3.6.3 to version 3.7.2.

$ python -V
Python 3.9.0

server.py:

from aiohttp import web

async def ws_handler(request):
    ws = web.WebSocketResponse()
    await ws.prepare(request)
    print('Closing')
    await ws.close()
    return ws

app = web.Application()
app.add_routes([web.get('/ws', ws_handler)])
web.run_app(app, port=8888)

Server logs are the same for all versions of aiohttp.

client.py:

import asyncio
import aiohttp

async def main():
    async with aiohttp.ClientSession() as session:
        async with session.ws_connect('http://localhost:8888/ws') as ws:
            print('Sending')
            await ws.send_str('some data')
            await asyncio.sleep(1)
            print('Receiving')
            await ws.receive()
            print('Close code:', ws.close_code)

asyncio.run(main())

Client logs (aiohttp==3.6.3):

$ python client.py
Sending
Receiving
Close code: 1000

Client logs (aiohttp==3.7.2):

$ python client.py
Sending
Receiving
Close code: 1006

[asvetlov]

Timing issue? 1006 is set when pong is not received or the caller was cancelled.

[derlih]

@asvetlov No it's not. Here is the test to reproduce

async def test_ws_close_return_code(aiohttp_client) -> None:
    async def handler(request):
        ws = web.WebSocketResponse()
        await ws.prepare(request)
        await ws.close()
        return ws

    app = web.Application()
    app.router.add_route("GET", "/", handler)
    client = await aiohttp_client(app)
    resp = await client.ws_connect("/")
    await resp.send_str('some data')
    await asyncio.sleep(0.1)
    await resp.receive()
    assert resp.close_code == WSCloseCode.OK

In client_ws.py it calls `close()' :

    async def close(self, *, code: int = 1000, message: bytes = b"") -> bool:
        # we need to break `receive()` cycle first,
        # `close()` may be called from different task
        if self._waiting is not None and not self._closed:
            self._reader.feed_data(WS_CLOSING_MESSAGE, 0)
            await self._waiting

        if not self._closed:
            self._cancel_heartbeat()
            self._closed = True
            try:
                await self._writer.close(code, message)
            except asyncio.CancelledError:
                self._close_code = 1006
                self._response.close()
                raise
            except Exception as exc: # <-- we come to this branch due to ConnectionResetError("Cannot write to closing transport") from WebSocketWriter
                self._close_code = 1006
                self._exception = exc
                self._response.close()
                return True

This overwrites the OK close code.

The real reason IMHO in overcomplicated (closing/closed boolean flags) logic of closing the ws. I would recommend to refactor it using finite state machine.

[asvetlov]

Reread you message again. Looks like your detection is right. Please let me keep the issue open for a while

[derlih]

WS client received the close message from the server and set the code to 1000. Then it tried to send/receive some data. But this action shouldn't overwrite the close code. Or it should?

[decaz]

@asvetlov any thoughts on this?

[asvetlov]

WebSocket problems are on my radar but I have no capacity to analyze them right now. Sure, I'll go over all websocket issues and try to address them before 3.8 release

[Dreamsorcerer]

@bdraco Fancy another websocket one? Test is in https://github.com/aio-libs/aiohttp/issues/5180#issuecomment-720057199

Issue here is the client receives a Close frame, then tries to send a Close frame in response, but then hits this error:

../hacking/aiohttp/aiohttp/client_ws.py:360: in receive
    await self.close()
../hacking/aiohttp/aiohttp/client_ws.py:264: in close
    await self._writer.close(code, message)
../hacking/aiohttp/aiohttp/http_websocket.py:718: in close
    await self._send_frame(
../hacking/aiohttp/aiohttp/http_websocket.py:657: in _send_frame
    self._write(header + mask + message)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <aiohttp.http_websocket.WebSocketWriter object at 0x7f4c20d17ca0>, data = b'\x88\x82h!\x9e\xdak\xc9'

    def _write(self, data: bytes) -> None:
        if self.transport.is_closing():
>           raise ConnectionResetError("Cannot write to closing transport")
E           ConnectionResetError: Cannot write to closing transport

../hacking/aiohttp/aiohttp/http_websocket.py:684: ConnectionResetError

This suggests the server has closed the connection prematurely. The server should wait for the Close frame from the client before closing the connection: https://datatracker.ietf.org/doc/html/rfc6455#section-1.4

[bdraco]

I’ll put it in my queue. Busy this week though so probably next weekend before I look

[bdraco]

Note to self: Need to make sure we don't wait too long for a close frame that never comes as well. Probably needs a timeout for that if we don't already have one

[bdraco]

It took me a while but I realized that this is behaving as expected because the client is sending a string await ws.send_str('some data') which is never received by the server (no receive), and the connection is closed while the message is still on the wire.

[Dreamsorcerer]

Hmm, I suppose that's a bit of an odd case. close() could maybe drain the buffer or something, but shouldn't really be happening in real use cases regardless.