Server does not automatically close TCP connection

[mehaase]

The RFC says:

The underlying TCP connection, in most normal cases, SHOULD be closed
first by the server, so that it holds the TIME_WAIT state and not the
client (as this would prevent it from re-opening the connection for 2
maximum segment lifetimes (2MSL), while there is no corresponding
server impact as a TIME_WAIT connection is immediately reopened upon
a new SYN with a higher seq number). In abnormal cases (such as not
having received a TCP Close from the server after a reasonable amount
of time) a client MAY initiate the TCP Close. As such, when a server
is instructed to Close the WebSocket Connection it SHOULD initiate
a TCP Close immediately, and when a client is instructed to do the
same, it SHOULD wait for a TCP Close from the server.

This doesn't always happen. I noticed this while testing a trio-websocket server with an asyncio websockets client. After doing the WebSocket closing handshake, the client times out after 10 seconds waiting for the server to close the connection.

The server code:

import logging
import trio
from trio_websocket import open_websocket_url, serve_websocket, ConnectionClosed

logging.basicConfig(level=logging.DEBUG)

async def handler(request):
    conn = await request.accept()
    try:
        while True:
            message = await conn.get_message()
            await conn.send_message(message)
    except ConnectionClosed:
        pass
    await conn.aclose()

async def main():
    logging.info('Listening on ws://127.0.0.1:8000')
    try:
        await serve_websocket(handler, '127.0.0.1', 8000, ssl_context=None)
    except KeyboardInterrupt:
        logging.warning('Received interrupt: aborting')

trio.run(main, restrict_keyboard_interrupt_to_checkpoints=True)

The client code:

import asyncio
import logging
import websockets

logging.basicConfig(level=logging.DEBUG)

async def main():
    url = 'ws://localhost:8000'
    logging.info('Connecting to %s', url)
    async with websockets.connect(url) as conn:
        await conn.send('this is a test message')
        response = await conn.recv()
        logging.info('Got response: %s', response)

asyncio.get_event_loop().run_until_complete(main())

And a relevant section of the client's logs:

DEBUG:websockets.protocol:client - state = CLOSING
DEBUG:websockets.protocol:client > Frame(fin=True, opcode=8, data=b'\x03\xe8', rsv1=False, rsv2=False, rsv3=False)
DEBUG:websockets.protocol:client < Frame(fin=True, opcode=8, data=b'\x03\xe8', rsv1=False, rsv2=False, rsv3=False)
DEBUG:websockets.protocol:client ! timed out waiting for TCP close
DEBUG:websockets.protocol:client x half-closing TCP connection
DEBUG:websockets.protocol:client - event = eof_received()
DEBUG:websockets.protocol:client - event = connection_lost(None)
DEBUG:websockets.protocol:client - state = CLOSED
DEBUG:websockets.protocol:client x code = 1000, reason = [no reason]

This is tangled up with #90 a bit but is a bit more urgent for me personally because I'm now using a trio websocket server with an asyncio client.

[basicasicmatrix]

I am receiving cases of hung CLOSE_WAIT as well.

[belm0]

I suspect this bug correlates to the test suite failures reported in #147

[belm0]

So... if I add await self._close_stream() following the channel aclose() in _close_web_socket(), then the example code in this issue works, it fixes all the client and server autobahn failures, and unit tests pass.

https://github.com/HyperionGray/trio-websocket/blob/61258058db3fcd0e325057af14dd4d97034e3b04/trio_websocket/_impl.py#L1011-L1020

But I don't know if this change is correct.

[belm0]

I found that _close_web_socket() is called on a few paths, but the only one seems to matter for the example in this issue and autobahn tests is via _handle_close_connection_event().

Furthermore, corroborating the RFC cited in the original comment, the tests only seem to require closing the TCP stream on connection closed for the server case.

[belm0]

I'm wondering if this early return in WebSocketConnection aclose() is correct:

https://github.com/HyperionGray/trio-websocket/blob/61258058db3fcd0e325057af14dd4d97034e3b04/trio_websocket/_impl.py#L832-L836

Because if I disable that, then the remainder of the function includes a finally with a close of the TCP stream, which is what we want.

https://github.com/HyperionGray/trio-websocket/blob/61258058db3fcd0e325057af14dd4d97034e3b04/trio_websocket/_impl.py#L837-L851

[belm0]

(The fact that the issue doesn't come up with the trio-websocket client, while it does with asyncio and autobahn clients, implies that our client is cheating and closing down its end right after sending a CloseConnection event.)