Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TypeError when connection is closed in connect() #244

Closed
ostcar opened this issue Nov 14, 2018 · 18 comments · Fixed by #704 or #881
Closed

TypeError when connection is closed in connect() #244

ostcar opened this issue Nov 14, 2018 · 18 comments · Fixed by #704 or #881

Comments

@ostcar
Copy link

ostcar commented Nov 14, 2018

I have the same problem then #185 but I think, I can reproduce it.

When you close a connection in the connect() method of a WebsocketConsumer, it works fine with daphne but uvicorn raises a TypeError

Traceback (most recent call last):
  File "/home/ossi/src/channels-examples/.venv/lib/python3.7/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
    result = await asgi(self.asgi_receive, self.asgi_send)
  File "/home/ossi/src/channels-examples/.venv/lib/python3.7/site-packages/channels/sessions.py", line 179, in __call__
    return await self.inner(receive, self.send)
  File "/home/ossi/src/channels-examples/.venv/lib/python3.7/site-packages/channels/middleware.py", line 41, in coroutine_call
    await inner_instance(receive, send)
  File "/home/ossi/src/channels-examples/.venv/lib/python3.7/site-packages/channels/consumer.py", line 59, in __call__
    [receive, self.channel_receive], self.dispatch
  File "/home/ossi/src/channels-examples/.venv/lib/python3.7/site-packages/channels/utils.py", line 59, in await_many_dispatch
    await task
  File "/home/ossi/src/channels-examples/.venv/lib/python3.7/site-packages/channels/utils.py", line 51, in await_many_dispatch
    result = task.result()
  File "/home/ossi/src/channels-examples/.venv/lib/python3.7/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 222, in asgi_receive
    data = await self.recv()
  File "/home/ossi/src/channels-examples/.venv/lib/python3.7/site-packages/websockets/protocol.py", line 419, in recv
    return_when=asyncio.FIRST_COMPLETED,
  File "/usr/lib/python3.7/asyncio/tasks.py", line 361, in wait
    fs = {ensure_future(f, loop=loop) for f in set(fs)}
  File "/usr/lib/python3.7/asyncio/tasks.py", line 361, in <setcomp>
    fs = {ensure_future(f, loop=loop) for f in set(fs)}
  File "/usr/lib/python3.7/asyncio/tasks.py", line 592, in ensure_future
    raise TypeError('An asyncio.Future, a coroutine or an awaitable is '
TypeError: An asyncio.Future, a coroutine or an awaitable is required

I created this branch on the django-channels-example repository: https://github.com/ostcar/channels-examples/tree/uvicorn-test

All I changed was, that the websocket connection is always closed: andrewgodwin/channels-examples@master...ostcar:uvicorn-test

I think the problem is, that you call websockets.WebSocketServerProtocol.recv() before the websocket connection is open so websockets.WebSocketServerProtocol.connection_open() was not called. In this case the attribute transfer_data_task is still None. So when websockets.WebSocketServerProtocol.recv() calls

yield from asyncio.wait(
                    [pop_message_waiter, self.transfer_data_task],
                    loop=self.loop,
                    return_when=asyncio.FIRST_COMPLETED,
                )

it tries to await None what causes the exception.

I don't know, if this is a but in the websockets package or if you should check self.closed before calling self.recv()

@matteing
Copy link

matteing commented Jan 7, 2019

I'm also facing this issue - when connections are closed, several errors pop up. Doesn't affect operation, but quite concerning nonetheless.

Full stack trace (may be mixed with other errs...):

[2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 674, in transfer_data
Jan 07 11:56:32 makerlog gunicorn[19800]:     message = yield from self.read_message()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 742, in read_message
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_data_frame(max_size=self.max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 815, in read_data_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_frame(max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 884, in read_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     extensions=self.extensions,
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/framing.py", line 99, in read
Jan 07 11:56:32 makerlog gunicorn[19800]:     data = yield from reader(2)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/usr/lib/python3.6/asyncio/streams.py", line 672, in readexactly
Jan 07 11:56:32 makerlog gunicorn[19800]:     raise IncompleteReadError(incomplete, n)
Jan 07 11:56:32 makerlog gunicorn[19800]: asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes
Jan 07 11:56:32 makerlog gunicorn[19800]: The above exception was the direct cause of the following exception:
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await dispatch(result)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 73, in dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await handler(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 175, in websocket_connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.connect()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/makerlog2/notifications/sockets/consumers.py", line 19, in connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send_json(count)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 273, in send_json
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send(text_data=await self.encode_json(content), close=close)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 211, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send({"type": "websocket.send", "text": text_data})
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 81, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.base_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 232, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.real_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 198, in asgi_send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send(data)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 462, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 11:56:32 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 11:56:32 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await dispatch(result)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 73, in dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await handler(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 175, in websocket_connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.connect()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/makerlog2/notifications/sockets/consumers.py", line 19, in connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send_json(count)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 273, in send_json
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send(text_data=await self.encode_json(content), close=close)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 211, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send({"type": "websocket.send", "text": text_data})
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 81, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.base_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 232, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.real_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 198, in asgi_send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send(data)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 462, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 11:56:32 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 11:56:32 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await dispatch(result)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 73, in dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await handler(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 175, in websocket_connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.connect()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/makerlog2/notifications/sockets/consumers.py", line 19, in connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send_json(count)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 273, in send_json
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send(text_data=await self.encode_json(content), close=close)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 211, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send({"type": "websocket.send", "text": text_data})
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 81, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.base_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 232, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.real_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 198, in asgi_send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send(data)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 462, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 11:56:32 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 11:56:32 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 674, in transfer_data
Jan 07 11:56:32 makerlog gunicorn[19800]:     message = yield from self.read_message()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 742, in read_message
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_data_frame(max_size=self.max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 815, in read_data_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_frame(max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 884, in read_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     extensions=self.extensions,
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/framing.py", line 99, in read
Jan 07 11:56:32 makerlog gunicorn[19800]:     data = yield from reader(2)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/usr/lib/python3.6/asyncio/streams.py", line 672, in readexactly
Jan 07 11:56:32 makerlog gunicorn[19800]:     raise IncompleteReadError(incomplete, n)
Jan 07 11:56:32 makerlog gunicorn[19800]: asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes
Jan 07 11:56:32 makerlog gunicorn[19800]: The above exception was the direct cause of the following exception:
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await dispatch(result)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 73, in dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await handler(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 175, in websocket_connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.connect()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/makerlog2/notifications/sockets/consumers.py", line 19, in connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send_json(count)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 273, in send_json
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send(text_data=await self.encode_json(content), close=close)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 211, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send({"type": "websocket.send", "text": text_data})
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 81, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.base_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 232, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.real_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 198, in asgi_send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send(data)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 462, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 11:56:32 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 11:56:32 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await dispatch(result)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 73, in dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await handler(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 175, in websocket_connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.connect()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/makerlog2/notifications/sockets/consumers.py", line 19, in connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send_json(count)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 273, in send_json
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send(text_data=await self.encode_json(content), close=close)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 211, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send({"type": "websocket.send", "text": text_data})
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 81, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.base_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 232, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.real_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 198, in asgi_send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send(data)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 462, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 11:56:32 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 11:56:32 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 674, in transfer_data
Jan 07 11:56:32 makerlog gunicorn[19800]:     message = yield from self.read_message()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 742, in read_message
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_data_frame(max_size=self.max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 815, in read_data_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_frame(max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 884, in read_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     extensions=self.extensions,
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/framing.py", line 99, in read
Jan 07 11:56:32 makerlog gunicorn[19800]:     data = yield from reader(2)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/usr/lib/python3.6/asyncio/streams.py", line 672, in readexactly
Jan 07 11:56:32 makerlog gunicorn[19800]:     raise IncompleteReadError(incomplete, n)
Jan 07 11:56:32 makerlog gunicorn[19800]: asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes
Jan 07 11:56:32 makerlog gunicorn[19800]: The above exception was the direct cause of the following exception:
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await dispatch(result)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 73, in dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await handler(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 175, in websocket_connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.connect()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/makerlog2/notifications/sockets/consumers.py", line 19, in connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send_json(count)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 273, in send_json
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send(text_data=await self.encode_json(content), close=close)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 211, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send({"type": "websocket.send", "text": text_data})
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 81, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.base_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 232, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.real_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 198, in asgi_send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send(data)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 462, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 11:56:32 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 11:56:32 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19809] [INFO] None - "WebSocket /explore/stream/" [accepted]
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await dispatch(result)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 73, in dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await handler(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 175, in websocket_connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.connect()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/makerlog2/notifications/sockets/consumers.py", line 19, in connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send_json(count)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 273, in send_json
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send(text_data=await self.encode_json(content), close=close)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 211, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send({"type": "websocket.send", "text": text_data})
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 81, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.base_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 232, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.real_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 198, in asgi_send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send(data)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 462, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 11:56:32 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 11:56:32 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 674, in transfer_data
Jan 07 11:56:32 makerlog gunicorn[19800]:     message = yield from self.read_message()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 742, in read_message
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_data_frame(max_size=self.max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 815, in read_data_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_frame(max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 884, in read_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     extensions=self.extensions,
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/framing.py", line 99, in read
Jan 07 11:56:32 makerlog gunicorn[19800]:     data = yield from reader(2)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/usr/lib/python3.6/asyncio/streams.py", line 672, in readexactly
Jan 07 11:56:32 makerlog gunicorn[19800]:     raise IncompleteReadError(incomplete, n)
Jan 07 11:56:32 makerlog gunicorn[19800]: asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes
Jan 07 11:56:32 makerlog gunicorn[19800]: The above exception was the direct cause of the following exception:
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await dispatch(result)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 73, in dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:     await handler(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 175, in websocket_connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.connect()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/makerlog2/notifications/sockets/consumers.py", line 19, in connect
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send_json(count)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 273, in send_json
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send(text_data=await self.encode_json(content), close=close)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/generic/websocket.py", line 211, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await super().send({"type": "websocket.send", "text": text_data})
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 81, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.base_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 232, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.real_send(message)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 198, in asgi_send
Jan 07 11:56:32 makerlog gunicorn[19800]:     await self.send(data)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 462, in send
Jan 07 11:56:32 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 11:56:32 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 11:56:32 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason
Jan 07 11:56:32 makerlog gunicorn[19800]: [2019-01-07 11:56:32 +0000] [19806] [ERROR] Exception in ASGI application
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 674, in transfer_data
Jan 07 11:56:32 makerlog gunicorn[19800]:     message = yield from self.read_message()
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 742, in read_message
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_data_frame(max_size=self.max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 815, in read_data_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     frame = yield from self.read_frame(max_size)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 884, in read_frame
Jan 07 11:56:32 makerlog gunicorn[19800]:     extensions=self.extensions,
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/framing.py", line 99, in read
Jan 07 11:56:32 makerlog gunicorn[19800]:     data = yield from reader(2)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/usr/lib/python3.6/asyncio/streams.py", line 672, in readexactly
Jan 07 11:56:32 makerlog gunicorn[19800]:     raise IncompleteReadError(incomplete, n)
Jan 07 11:56:32 makerlog gunicorn[19800]: asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes
Jan 07 11:56:32 makerlog gunicorn[19800]: The above exception was the direct cause of the following exception:
Jan 07 11:56:32 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 140, in run_asgi
Jan 07 11:56:32 makerlog gunicorn[19800]:     result = await asgi(self.asgi_receive, self.asgi_send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/sessions.py", line 179, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     return await self.inner(receive, self.send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/middleware.py", line 41, in coroutine_call
Jan 07 11:56:32 makerlog gunicorn[19800]:     await inner_instance(receive, send)
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/consumer.py", line 59, in __call__
Jan 07 11:56:32 makerlog gunicorn[19800]:     [receive, self.channel_receive], self.dispatch
Jan 07 11:56:32 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/channels/utils.py", line 52, in await_many_dispatch
Jan 07 11:57:19 makerlog gunicorn[19800]: [2019-01-07 11:57:19 +0000] [19808] [INFO] None - "HEAD /health HTTP/1.1" 200
Jan 07 11:57:24 makerlog gunicorn[19800]: [2019-01-07 11:57:24 +0000] [19806] [INFO] None - "WebSocket /notifications/" [accepted]
Jan 07 11:57:27 makerlog gunicorn[19800]: [2019-01-07 11:57:27 +0000] [19809] [INFO] None - "POST /apps/todoist/event/ HTTP/1.1" 400
Jan 07 11:57:30 makerlog gunicorn[19800]: [2019-01-07 11:57:30 +0000] [19806] [INFO] None - "WebSocket /notifications/" [accepted]
Jan 07 11:57:31 makerlog gunicorn[19800]: [2019-01-07 11:57:31 +0000] [19808] [INFO] None - "WebSocket /explore/stream/" [accepted]
Jan 07 11:57:32 makerlog gunicorn[19800]: [2019-01-07 11:57:32 +0000] [19809] [INFO] None - "POST /apps/todoist/event/ HTTP/1.1" 400
Jan 07 11:57:46 makerlog gunicorn[19800]: [2019-01-07 11:57:46 +0000] [19808] [INFO] None - "POST /apps/todoist/event/ HTTP/1.1" 400
Jan 07 11:57:55 makerlog gunicorn[19800]: [2019-01-07 11:57:55 +0000] [19808] [INFO] None - "POST /apps/todoist/event/ HTTP/1.1" 400
Jan 07 11:58:01 makerlog gunicorn[19800]: [2019-01-07 11:58:01 +0000] [19806] [INFO] None - "GET /health HTTP/1.1" 200
Jan 07 11:58:01 makerlog gunicorn[19800]: [2019-01-07 11:58:01 +0000] [19808] [INFO] None - "GET /explore/stream/ HTTP/1.1" 200
Jan 07 11:58:01 makerlog gunicorn[19800]: [2019-01-07 11:58:01 +0000] [19809] [INFO] None - "GET /explore/stream/2019/jan/7/ HTTP/1.1" 200
Jan 07 11:58:06 makerlog gunicorn[19800]: [2019-01-07 11:58:06 +0000] [19808] [INFO] None - "WebSocket /explore/stream/" [accepted]
Jan 07 11:58:08 makerlog gunicorn[19800]: [2019-01-07 11:58:08 +0000] [19806] [INFO] None - "POST /apps/todoist/event/ HTTP/1.1" 400
Jan 07 11:58:09 makerlog gunicorn[19800]: [2019-01-07 11:58:09 +0000] [19809] [INFO] None - "POST /apps/todoist/event/ HTTP/1.1" 400
Jan 07 11:58:20 makerlog gunicorn[19800]: [2019-01-07 11:58:20 +0000] [19808] [INFO] None - "WebSocket /explore/stream/" [accepted]
Jan 07 11:58:20 makerlog gunicorn[19800]: [2019-01-07 11:58:20 +0000] [19806] [INFO] None - "WebSocket /notifications/" [accepted]
Jan 07 11:58:49 makerlog gunicorn[19800]: [2019-01-07 11:58:49 +0000] [19806] [INFO] None - "GET /projects/408/related/ HTTP/1.1" 200
Jan 07 11:59:12 makerlog gunicorn[19800]: [2019-01-07 11:59:12 +0000] [19809] [INFO] None - "GET /health HTTP/1.1" 200
Jan 07 11:59:12 makerlog gunicorn[19800]: [2019-01-07 11:59:12 +0000] [19808] [INFO] None - "GET /products/books/ HTTP/1.1" 200
Jan 07 11:59:12 makerlog gunicorn[19800]: [2019-01-07 11:59:12 +0000] [19809] [INFO] None - "GET /products/books/stream/ HTTP/1.1" 200
Jan 07 11:59:12 makerlog gunicorn[19800]: [2019-01-07 11:59:12 +0000] [19809] [INFO] None - "GET /users/1338/ HTTP/1.1" 200
Jan 07 11:59:19 makerlog gunicorn[19800]: [2019-01-07 11:59:19 +0000] [19808] [INFO] None - "HEAD /health HTTP/1.1" 200
Jan 07 12:00:02 makerlog gunicorn[19800]: [2019-01-07 12:00:02 +0000] [19806] [INFO] None - "GET /health HTTP/1.1" 200
Jan 07 12:00:02 makerlog gunicorn[19800]: [2019-01-07 12:00:02 +0000] [19808] [INFO] None - "GET /products/use-makerlog-redesign/ HTTP/1.1" 200
Jan 07 12:00:02 makerlog gunicorn[19800]: [2019-01-07 12:00:02 +0000] [19809] [INFO] None - "GET /products/use-makerlog-redesign/stream/ HTTP/1.1" 200
Jan 07 12:00:02 makerlog gunicorn[19800]: [2019-01-07 12:00:02 +0000] [19809] [INFO] None - "GET /users/969/ HTTP/1.1" 200
Jan 07 12:00:02 makerlog gunicorn[19800]: [2019-01-07 12:00:02 +0000] [19808] [INFO] None - "GET /products/use-makerlog-redesign/2018/dec/23/ HTTP/1.1" 200
Jan 07 12:00:23 makerlog gunicorn[19800]: [2019-01-07 12:00:23 +0000] [19806] [INFO] None - "WebSocket /explore/stream/" [accepted]
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19808] [INFO] None - "GET /health HTTP/1.1" 200
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19806] [INFO] None - "OPTIONS /tasks/sync/ HTTP/1.1" 200
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19808] [INFO] None - "OPTIONS /me/stats/ HTTP/1.1" 200
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19809] [INFO] None - "OPTIONS /projects/ HTTP/1.1" 200
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19806] [INFO] None - "OPTIONS /notifications/ HTTP/1.1" 200
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19808] [INFO] None - "OPTIONS /explore/stream/ HTTP/1.1" 200
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19809] [INFO] None - "OPTIONS /me/following/ HTTP/1.1" 200
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19806] [INFO] None - "OPTIONS /products/me/ HTTP/1.1" 200
Jan 07 12:00:36 makerlog gunicorn[19800]: [2019-01-07 12:00:36 +0000] [19809] [INFO] None - "GET /tasks/sync/ HTTP/1.1" 200
Jan 07 12:00:37 makerlog gunicorn[19800]: [2019-01-07 12:00:37 +0000] [19809] [INFO] None - "GET /projects/ HTTP/1.1" 200
Jan 07 12:00:37 makerlog gunicorn[19800]: [2019-01-07 12:00:37 +0000] [19808] [INFO] None - "GET /me/stats/ HTTP/1.1" 200
Jan 07 12:00:37 makerlog gunicorn[19800]: [2019-01-07 12:00:37 +0000] [19808] [INFO] None - "GET /me/following/ HTTP/1.1" 200
Jan 07 12:00:37 makerlog gunicorn[19800]: [2019-01-07 12:00:37 +0000] [19806] [INFO] None - "GET /explore/stream/ HTTP/1.1" 200
Jan 07 12:00:37 makerlog gunicorn[19800]: [2019-01-07 12:00:37 +0000] [19806] [INFO] None - "GET /notifications/ HTTP/1.1" 200
Jan 07 12:00:37 makerlog gunicorn[19800]: [2019-01-07 12:00:37 +0000] [19809] [INFO] None - "GET /products/me/ HTTP/1.1" 200
Jan 07 12:00:38 makerlog gunicorn[19800]: [2019-01-07 12:00:38 +0000] [19808] [INFO] None - "OPTIONS /stats/world/ HTTP/1.1" 200
Jan 07 12:00:38 makerlog gunicorn[19800]: [2019-01-07 12:00:38 +0000] [19806] [INFO] None - "OPTIONS /stats/world/ HTTP/1.1" 200
Jan 07 12:00:38 makerlog gunicorn[19800]: [2019-01-07 12:00:38 +0000] [19806] [INFO] None - "OPTIONS /explore/stream/2019/jan/7/ HTTP/1.1" 200
Jan 07 12:00:39 makerlog gunicorn[19800]: [2019-01-07 12:00:39 +0000] [19808] [INFO] None - "GET /stats/world/ HTTP/1.1" 200
Jan 07 12:00:39 makerlog gunicorn[19800]: [2019-01-07 12:00:39 +0000] [19809] [INFO] None - "GET /explore/stream/2019/jan/7/ HTTP/1.1" 200
Jan 07 12:00:39 makerlog gunicorn[19800]: [2019-01-07 12:00:39 +0000] [19809] [INFO] None - "GET /stats/world/ HTTP/1.1" 200
Jan 07 12:00:39 makerlog gunicorn[19800]: [2019-01-07 12:00:39 +0000] [19808] [INFO] None - "OPTIONS /discussions/recent_questions/ HTTP/1.1" 200
Jan 07 12:00:39 makerlog gunicorn[19800]: [2019-01-07 12:00:39 +0000] [19806] [INFO] None - "GET /discussions/recent_questions/ HTTP/1.1" 200
Jan 07 12:00:41 makerlog gunicorn[19800]: [2019-01-07 12:00:41 +0000] [19808] [INFO] None - "WebSocket /notifications/" [accepted]
Jan 07 12:00:42 makerlog gunicorn[19800]: [2019-01-07 12:00:42 +0000] [19806] [INFO] None - "WebSocket /explore/stream/" [accepted]
Jan 07 12:00:45 makerlog gunicorn[19800]: [2019-01-07 12:00:45 +0000] [19809] [INFO] None - "GET /health HTTP/1.1" 200
Jan 07 12:00:45 makerlog gunicorn[19800]: [2019-01-07 12:00:45 +0000] [19808] [INFO] None - "GET /users/username/dexter/ HTTP/1.1" 200
Jan 07 12:00:45 makerlog gunicorn[19800]: [2019-01-07 12:00:45 +0000] [19809] [INFO] None - "GET /users/1008/stats/ HTTP/1.1" 200
Jan 07 12:00:45 makerlog gunicorn[19800]: [2019-01-07 12:00:45 +0000] [19806] [INFO] None - "GET /users/1008/stream/ HTTP/1.1" 200
Jan 07 12:00:45 makerlog gunicorn[19800]: [2019-01-07 12:00:45 +0000] [19808] [INFO] None - "GET /users/1008/products/ HTTP/1.1" 200
Jan 07 12:00:45 makerlog gunicorn[19800]: [2019-01-07 12:00:45 +0000] [19809] [INFO] None - "GET /users/1008/stream/2019/jan/2/ HTTP/1.1" 200
Jan 07 12:00:47 makerlog gunicorn[19800]: [2019-01-07 12:00:47 +0000] [19808] [INFO] None - "OPTIONS /projects/408/related/ HTTP/1.1" 200
Jan 07 12:00:47 makerlog gunicorn[19800]: [2019-01-07 12:00:47 +0000] [19806] [INFO] None - "GET /projects/408/related/ HTTP/1.1" 200
Jan 07 12:00:49 makerlog gunicorn[19800]: [2019-01-07 12:00:49 +0000] [19808] [INFO] None - "OPTIONS /tasks/26850/can_praise/ HTTP/1.1" 200
Jan 07 12:00:49 makerlog gunicorn[19800]: [2019-01-07 12:00:49 +0000] [19806] [INFO] None - "OPTIONS /tasks/26850/comments/ HTTP/1.1" 200
Jan 07 12:00:49 makerlog gunicorn[19800]: [2019-01-07 12:00:49 +0000] [19809] [INFO] None - "GET /tasks/26850/can_praise/ HTTP/1.1" 200
Jan 07 12:00:49 makerlog gunicorn[19800]: [2019-01-07 12:00:49 +0000] [19808] [INFO] None - "GET /tasks/26850/comments/ HTTP/1.1" 200
Jan 07 12:00:53 makerlog gunicorn[19800]: [2019-01-07 12:00:53 +0000] [19809] [INFO] None - "GET /tasks/26850/can_praise/ HTTP/1.1" 200
Jan 07 12:00:59 makerlog gunicorn[19800]: [2019-01-07 12:00:59 +0000] [19808] [INFO] None - "GET /tasks/26850/can_praise/ HTTP/1.1" 200
Jan 07 12:00:59 makerlog gunicorn[19800]: [2019-01-07 12:00:59 +0000] [19809] [INFO] None - "GET /tasks/26850/comments/ HTTP/1.1" 200
Jan 07 12:01:07 makerlog gunicorn[19800]: [2019-01-07 12:01:07 +0000] [19808] [INFO] None - "GET / HTTP/1.1" 200
Jan 07 12:01:16 makerlog gunicorn[19800]: [2019-01-07 12:01:16 +0000] [19809] [INFO] None - "GET / HTTP/1.1" 200
Jan 07 12:01:19 makerlog gunicorn[19800]: [2019-01-07 12:01:19 +0000] [19809] [INFO] None - "GET /users/ HTTP/1.1" 200
Jan 07 12:01:19 makerlog gunicorn[19800]: [2019-01-07 12:01:19 +0000] [19809] [INFO] None - "HEAD /health HTTP/1.1" 200
Jan 07 12:01:19 makerlog gunicorn[19800]: [2019-01-07 12:01:19 +0000] [19809] [INFO] None - "GET /notifications/ HTTP/1.1" 200
Jan 07 12:01:20 makerlog gunicorn[19800]: [2019-01-07 12:01:20 +0000] [19809] [INFO] None - "OPTIONS /notifications/mark_all_read/ HTTP/1.1" 200
Jan 07 12:01:20 makerlog gunicorn[19800]: [2019-01-07 12:01:20 +0000] [19809] [INFO] None - "GET /notifications/mark_all_read/ HTTP/1.1" 200
Jan 07 12:01:22 makerlog gunicorn[19800]: [2019-01-07 12:01:22 +0000] [19808] [INFO] None - "GET /v1/docs/ HTTP/1.1" 200
Jan 07 12:01:23 makerlog gunicorn[19800]: [2019-01-07 12:01:23 +0000] [19809] [INFO] None - "GET /v1/docs/ HTTP/1.1" 200
Jan 07 12:01:29 makerlog gunicorn[19800]: [2019-01-07 12:01:29 +0000] [19809] [INFO] None - "GET / HTTP/1.1" 200
Jan 07 12:01:31 makerlog gunicorn[19800]: Error in data transfer
Jan 07 12:01:31 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 674, in transfer_data
Jan 07 12:01:31 makerlog gunicorn[19800]:     message = yield from self.read_message()
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 742, in read_message
Jan 07 12:01:31 makerlog gunicorn[19800]:     frame = yield from self.read_data_frame(max_size=self.max_size)
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 825, in read_data_frame
Jan 07 12:01:31 makerlog gunicorn[19800]:     yield from self.write_close_frame(frame.data)
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 958, in write_close_frame
Jan 07 12:01:31 makerlog gunicorn[19800]:     True, OP_CLOSE, data, _expected_state=State.CLOSING
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 919, in write_frame
Jan 07 12:01:31 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 12:01:31 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 12:01:31 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1001 (going away), no reason
Jan 07 12:01:31 makerlog gunicorn[19800]: Error in data transfer
Jan 07 12:01:31 makerlog gunicorn[19800]: Traceback (most recent call last):
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 674, in transfer_data
Jan 07 12:01:31 makerlog gunicorn[19800]:     message = yield from self.read_message()
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 742, in read_message
Jan 07 12:01:31 makerlog gunicorn[19800]:     frame = yield from self.read_data_frame(max_size=self.max_size)
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 825, in read_data_frame
Jan 07 12:01:31 makerlog gunicorn[19800]:     yield from self.write_close_frame(frame.data)
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 958, in write_close_frame
Jan 07 12:01:31 makerlog gunicorn[19800]:     True, OP_CLOSE, data, _expected_state=State.CLOSING
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 919, in write_frame
Jan 07 12:01:31 makerlog gunicorn[19800]:     yield from self.ensure_open()
Jan 07 12:01:31 makerlog gunicorn[19800]:   File "/home/sergio/server/lib/python3.6/site-packages/websockets/protocol.py", line 646, in ensure_open
Jan 07 12:01:31 makerlog gunicorn[19800]:     ) from self.transfer_data_exc
Jan 07 12:01:31 makerlog gunicorn[19800]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1001 (going away), no reason

@matteing
Copy link

matteing commented Apr 8, 2019

Still facing this issue.

@tomchristie
Copy link
Member

Okay - can someone break this issue down to something smaller, not involving channels.
Also does the issue replicate on both websocket implementations or just one?

(Use --ws wsproto and --ws websockets to switch between the two implementations.)

@sergicolladosopra
Copy link

sergicolladosopra commented Apr 11, 2019

Hi, I think we have the same problem in our app:

TypeError: An asyncio.Future, a coroutine or an awaitable is required
at ensure_future (/usr/local/lib/python3.6/asyncio/tasks.py:526)
at <setcomp> (/usr/local/lib/python3.6/asyncio/tasks.py:311)
at wait (/usr/local/lib/python3.6/asyncio/tasks.py:311)
at recv (/usr/local/lib/python3.6/site-packages/websockets/protocol.py:419)
at asgi_receive (/usr/local/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py:227)
at await_many_dispatch (/usr/local/lib/python3.6/site-packages/channels/utils.py:51)
at await_many_dispatch (/usr/local/lib/python3.6/site-packages/channels/utils.py:59)
at __call__ (/usr/local/lib/python3.6/site-packages/channels/consumer.py:59)
at run_asgi (/usr/local/lib/python3.6/site-packages/uvicorn/protocols/websockets/websockets_impl.py:147)

@tomchristie
Copy link
Member

@sergicolladosopra Okay, with Channels or something else?

What's the smallest possible codebase someone can reduce this down too, so that I've got a good place to start digging from?

@ostcar
Copy link
Author

ostcar commented Apr 13, 2019

Here is a minimal example without using django:

class Application:
    def __init__(self, scope):
        self.scope = scope

    async def __call__(self, receive, send):
        if self.scope["type"] != "websocket":
            return

        while True:
            # what for the 'websocket.connect' event.
            await receive()

            # Close the connection
            await send({'type': 'websocket.close'})

To test it, you have to start it with an asgi server an open a websocket connection.

With daphne:

$ daphne asgi:Application
2019-04-13 23:49:51,867 INFO     Starting server at tcp:port=8000:interface=127.0.0.1
2019-04-13 23:49:51,867 INFO     HTTP/2 support not enabled (install the http2 and tls Twisted extras)
2019-04-13 23:49:51,867 INFO     Configuring endpoint tcp:port=8000:interface=127.0.0.1
2019-04-13 23:49:51,868 INFO     Listening on TCP address 127.0.0.1:8000
127.0.0.1:58152 - - [13/Apr/2019:23:50:00] "WSCONNECTING /" - -
127.0.0.1:58152 - - [13/Apr/2019:23:50:00] "WSREJECT /" - -
127.0.0.1:58152 - - [13/Apr/2019:23:50:00] "WSDISCONNECT /" - -
^C2019-04-13 23:50:01,841 INFO     Killed 1 pending application instances

With uvicorn and websockets:

$ uvicorn asgi:Application --ws websockets
INFO: Started server process [23052]
INFO: Waiting for application startup.
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO: ('127.0.0.1', 58172) - "WebSocket /" 403
ERROR: Exception in ASGI application
Traceback (most recent call last):
  File "/home/ossi/src/uvicorn_test/venv/lib/python3.7/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 147, in run_asgi
    result = await asgi(self.asgi_receive, self.asgi_send)
  File "./asgi.py", line 12, in __call__
    await receive()
  File "/home/ossi/src/uvicorn_test/venv/lib/python3.7/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 227, in asgi_receive
    data = await self.recv()
  File "/home/ossi/src/uvicorn_test/venv/lib/python3.7/site-packages/websockets/protocol.py", line 419, in recv
    return_when=asyncio.FIRST_COMPLETED,
  File "/usr/lib/python3.7/asyncio/tasks.py", line 361, in wait
    fs = {ensure_future(f, loop=loop) for f in set(fs)}
  File "/usr/lib/python3.7/asyncio/tasks.py", line 361, in <setcomp>
    fs = {ensure_future(f, loop=loop) for f in set(fs)}
  File "/usr/lib/python3.7/asyncio/tasks.py", line 592, in ensure_future
    raise TypeError('An asyncio.Future, a coroutine or an awaitable is '
TypeError: An asyncio.Future, a coroutine or an awaitable is required
^CINFO: Shutting down
INFO: Waiting for application shutdown.
INFO: Finished server process [23052]

With uvicorn and wsproto:

$ uvicorn asgi:Application --ws wsproto
INFO: Started server process [23092]
INFO: Waiting for application startup.
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO: ('127.0.0.1', 58178) - "WebSocket /" 403
ERROR: Exception in ASGI application
Traceback (most recent call last):
  File "/home/ossi/src/uvicorn_test/venv/lib/python3.7/site-packages/uvicorn/protocols/websockets/wsproto_impl.py", line 208, in run_asgi
    result = await asgi(self.receive, self.send)
  File "./asgi.py", line 15, in __call__
    await send({'type': 'websocket.close'})
  File "/home/ossi/src/uvicorn_test/venv/lib/python3.7/site-packages/uvicorn/protocols/websockets/wsproto_impl.py", line 257, in send
    output = self.conn.send(msg)
  File "/home/ossi/src/uvicorn_test/venv/lib/python3.7/site-packages/wsproto/__init__.py", line 35, in send
    data += self.handshake.send(event)
  File "/home/ossi/src/uvicorn_test/venv/lib/python3.7/site-packages/wsproto/handshake.py", line 97, in send
    "Event {} cannot be sent during the handshake".format(event)
wsproto.utilities.LocalProtocolError: Event Response(status_code=403, headers=[], http_version=b'1.1', reason=b'') cannot be sent during the handshake
^CINFO: Shutting down
INFO: Waiting for application shutdown.
INFO: Finished server process [23092]

The error seems to be, that the while True: loop does not break. But when I look into the django channels code, it seems, that django channels also does not close the loop.

The loop in django channels is here: https://github.com/django/channels/blob/03d221792e6881477911728615a6d51ec9fab73b/channels/utils.py#L45

The close message is send here: https://github.com/django/channels/blob/03d221792e6881477911728615a6d51ec9fab73b/channels/generic/websocket.py#L226

An exception, that could break the loop is raised when websocket.disconnect is handled: https://github.com/django/channels/blob/03d221792e6881477911728615a6d51ec9fab73b/channels/generic/websocket.py#L241

@mozartilize
Copy link

mozartilize commented May 17, 2019

Channels allows to call close() during connection handshake in connect(), but in example above with wsproto it doesn't, neither does websockets protocol which doesn't handle websocket.close (closed_event is set) in asgi_receive.

I took a look into websockets docs which says:

calls process_request() which may abort the WebSocket handshake and return a HTTP response instead; this hook only makes sense on the server side;

and seems like it's implemented on the web servers and maybe also in channels' middlewares.

So calling close() when connection handshaking is not a right thing to do?

@oTree-org
Copy link

oTree-org commented Aug 11, 2019

I also have this issue, using uvicorn 0.8.6 and channels 2.2.0. My channels consumers don't call .close() anywhere. I'm getting various errors whether I use wsproto or not. The problem doesn't occur with Daphne. The app works fine in the browser but I am concerned about all the tracebacks.

In websockets/server.py, the handshake stops at this line in WebSocketServerProtocol.handshake:

        if self.state != State.CONNECTING:
            raise CancelHandshake()

At that point, self.state is State.CLOSED. It was set to CLOSED here:

  c:\users\wicke\appdata\local\programs\python\python37-32\lib\runpy.py(85)_run_code()
-> exec(code, run_globals)
  c:\otree\ve-channels2\scripts\uvicorn.exe\__main__.py(9)<module>()
-> sys.exit(main())
  c:\otree\ve-channels2\lib\site-packages\click\core.py(764)__call__()
-> return self.main(*args, **kwargs)
  c:\otree\ve-channels2\lib\site-packages\click\core.py(717)main()
-> rv = self.invoke(ctx)
  c:\otree\ve-channels2\lib\site-packages\click\core.py(956)invoke()
-> return ctx.invoke(self.callback, **ctx.params)
  c:\otree\ve-channels2\lib\site-packages\click\core.py(555)invoke()
-> return callback(*args, **kwargs)
  c:\otree\ve-channels2\lib\site-packages\uvicorn\main.py(258)main()
-> run(**kwargs)
  c:\otree\ve-channels2\lib\site-packages\uvicorn\main.py(279)run()
-> server.run()
  c:\otree\ve-channels2\lib\site-packages\uvicorn\main.py(307)run()
-> loop.run_until_complete(self.serve(sockets=sockets))
  c:\users\wicke\appdata\local\programs\python\python37-32\lib\asyncio\base_events.py(571)run_until_complete()
-> self.run_forever()
  c:\users\wicke\appdata\local\programs\python\python37-32\lib\asyncio\base_events.py(539)run_forever()
-> self._run_once()
  c:\users\wicke\appdata\local\programs\python\python37-32\lib\asyncio\base_events.py(1775)_run_once()
-> handle._run()
  c:\users\wicke\appdata\local\programs\python\python37-32\lib\asyncio\events.py(88)_run()
-> self._context.run(self._callback, *self._args)
  c:\users\wicke\appdata\local\programs\python\python37-32\lib\asyncio\selector_events.py(913)_call_connection_lost()
-> super()._call_connection_lost(exc)
  c:\users\wicke\appdata\local\programs\python\python37-32\lib\asyncio\selector_events.py(687)_call_connection_lost()
-> self._protocol.connection_lost(exc)
  c:\otree\ve-channels2\lib\site-packages\uvicorn\protocols\websockets\websockets_impl.py(65)connection_lost()
-> super().connection_lost(exc)
> c:\otree\ve-channels2\lib\site-packages\websockets\protocol.py(1236)connection_lost()
-> logger.debug("%s - state = CLOSED", self.side)

The exc variable in the above traceback is:

ConnectionAbortedError(10053, 'An established connection was aborted by the software in your host machine', None, 10053, None)

I also see this:

('%s ! failing WebSocket connection in the %s state: %d %s', 'server', 'CLOSED', 1006, '[no reason]')

I tested on Linux (WSL) and I get basically the same traceback.

Happy to provide any additional info to troubleshoot this.

@tomchristie
Copy link
Member

The thing that would help most with progressing this would be to try to replicate the issue in a plain ASGI application, or in Starlette, or something more minimal than installing Channels.

If anyone's able to reduce the issue like that then I'd be very happy to dig into it.

@matteing
Copy link

The thing that would help most with progressing this would be to try to replicate the issue in a plain ASGI application, or in Starlette, or something more minimal than installing Channels.

If anyone's able to reduce the issue like that then I'd be very happy to dig into it.

#244 (comment)

@bjornSayers
Copy link

Is there any update or workaround for this? I can post more info about what I'm seeing, but it looks like the connection closes and things are fine browser side, but if I call .close() in the .connect() function I end up with type errors in the logs. Having stack traces in the logs is obviously not ideal, but it would help to clarify that's the extent of the issue...

@ostcar
Copy link
Author

ostcar commented Dec 14, 2019

My workaround is to open the connection and close it immediately.

adamhooper added a commit to adamhooper/uvicorn that referenced this issue Jun 19, 2020
Fixes encode#244. The unit test already existed, but it logged exceptions that
weren't being noticed.

* websockets_impl: `transfer_data_task` is unset if the handshake fails,
  so we can't call recv().
* wsproto_impl: `h11.Reject` is invalid during handshake; send
  `RejectConnection` instead.
@adamhooper
Copy link
Contributor

adamhooper commented Jun 19, 2020

Turns out this error was being logged -- and ignored -- in the unit-test suite already.

I'm not 100% confident in my reading of the ASGI-to-websockets spec. The Websockets spec (as cited in the websockets codebase) suggests it's wrong to call recv() before a successful handshake -- which is why this stack trace is logged. But the ASGI spec doesn't say anything.

For all I know, all real-world ASGI applications call recv() before the handshakes completes, whether that's ideal or not. So my pull request [#704] makes recv() return an error message -- the same one that would be returned after unexpected disconnect.

adamhooper added a commit to adamhooper/uvicorn that referenced this issue Jun 19, 2020
Fixes encode#244. The unit test already existed, but it logged exceptions that
weren't being noticed.

* websockets_impl: `transfer_data_task` is unset if the handshake fails,
  so we can't call recv().
* wsproto_impl: `h11.Reject` is invalid during handshake; send
  `RejectConnection` instead.
@adamhooper
Copy link
Contributor

If anyone's able to reduce the issue like that then I'd be very happy to dig into it.

@tomchristie ping? I have reduced the issue by enabling logging in Uvicorn's own test suite. I also submitted pull request #704 with a sketch of a fix. Are you still keen to dig into it? :)

@adamhooper
Copy link
Contributor

Is there any way at all I can be of any more help? I've helped diagnose, I've authored a pull request, I've written helpful notes on all issues I could find that seemed relevant. I'm doing my best, and I'm prepared to do better. Please direct me.

Our project experiences this stack trace >35,000 times per day. I worry that real, as-yet unknown errors are hiding among all those duplicates.

@cb109
Copy link

cb109 commented Nov 23, 2020

My workaround is to open the connection and close it immediately.

This has been the only way so far to silence the uvicorn errors we are seeing.

@florimondmanca
Copy link
Member

florimondmanca commented Dec 8, 2020

Hi all,

I'm taking a look at this given pings on #704.

I was able to reproduce the TypeError from OP using this setup.

async def app(scope, receive, send):
    assert scope["type"] == "websocket"

    # Pull up first recv message.
    message = await receive()
    assert message["type"] == "websocket.connect"

    # Reject the connection.
    await send({"type": "websocket.close"})
    # -- At this point websockets' recv() is unusable. --

    # This raises the `TypeError` on the server.
    message = await receive()
    # But we would expect it to succeed and return this:
    assert message["type"] == "websocket.disconnect"

Client:

$ python -m asyncio
>>> import websockets
>>> await websockets.connect("ws://localhost:8000")
websockets.exceptions.InvalidStatusCode: server rejected WebSocket connection: HTTP 403

The client sees the 403 after we sent websocket.close, which is expected, but it's the server that's having an issue with the extra TypeError there.

@euri10
Copy link
Member

euri10 commented Dec 9, 2020

maybe this is relevant too:

python-websockets/websockets#670

adamhooper added a commit to adamhooper/uvicorn that referenced this issue Dec 9, 2020
[closes encode#244]

Previously, if the application tried to close the connection before the
handshake completed, uvicorn would log:

    TypeError: An asyncio.Future, a coroutine or an awaitable is required.

These TypeErrors happen in tests/protocols/test_websocket.py. pytest is
hiding them. In my initial pull request, I added `caplog` to
`test_websocket.py` to expose the bug:

    def test_close_connection(protocol_cls, caplog):
        caplog.set_level(logging.ERROR)
        # ...
        assert not [r.message for r in caplog.records]

... but this caused unrelated errors on Windows; so @florimondmanca
suggests leaving the test suite alone, in
encode#704 (comment)
florimondmanca pushed a commit that referenced this issue Dec 9, 2020
[closes #244]

Previously, if the application tried to close the connection before the
handshake completed, uvicorn would log:

    TypeError: An asyncio.Future, a coroutine or an awaitable is required.

These TypeErrors happen in tests/protocols/test_websocket.py. pytest is
hiding them. In my initial pull request, I added `caplog` to
`test_websocket.py` to expose the bug:

    def test_close_connection(protocol_cls, caplog):
        caplog.set_level(logging.ERROR)
        # ...
        assert not [r.message for r in caplog.records]

... but this caused unrelated errors on Windows; so @florimondmanca
suggests leaving the test suite alone, in
#704 (comment)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet