Server does not automatically close TCP connection

mehaase commented 5 years ago

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.