search

tl-its-umich-edu / remote-office-hours-queue

Virtual queuing tool supporting Zoom video conferencing and/or in person meetings.
https://officehours.it.umich.edu/
Apache License 2.0
12 stars 28 forks source link

Frequent websockets.exceptions.ConnectionClosedError: code = 1006 in production logs #348

Open jonespm opened 2 years ago

jonespm commented 2 years ago

On a typical day it looks like this type of error comes up frequently, about 50 times it seems on a typical day.

It looks like the only line we might be able to catch and suppress this is 

  File "/usr/src/app/officehours_api/consumers.py", line 63, in connect
    self.send_json({

I'm not sure if it's causing any user facing error but it makes reading the logs difficult. Perhaps newer versions are better? It's also possible it's related to an Openshift proxy read timeout?

[2021-12-02 14:41:22 -0500] [17] [ERROR] Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/websockets/protocol.py", line 827, in transfer_data
    message = await self.read_message()
  File "/usr/local/lib/python3.8/site-packages/websockets/protocol.py", line 895, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/usr/local/lib/python3.8/site-packages/websockets/protocol.py", line 971, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/usr/local/lib/python3.8/site-packages/websockets/protocol.py", line 1047, in read_frame
    frame = await Frame.read(
  File "/usr/local/lib/python3.8/site-packages/websockets/framing.py", line 105, in read
    data = await reader(2)
  File "/usr/local/lib/python3.8/asyncio/streams.py", line 721, in readexactly
    raise exceptions.IncompleteReadError(incomplete, n)
asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 2 expected bytes

The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 154, in run_asgi
    result = await self.app(self.scope, self.asgi_receive, self.asgi_send)
  File "/usr/local/lib/python3.8/site-packages/uvicorn/middleware/proxy_headers.py", line 45, in __call__
    return await self.app(scope, receive, send)
  File "/usr/local/lib/python3.8/site-packages/uvicorn/middleware/asgi2.py", line 7, in __call__
    await instance(receive, send)
  File "/usr/local/lib/python3.8/site-packages/channels/sessions.py", line 183, in __call__
    return await self.inner(receive, self.send)
  File "/usr/local/lib/python3.8/site-packages/channels/middleware.py", line 41, in coroutine_call
    await inner_instance(receive, send)
  File "/usr/local/lib/python3.8/site-packages/channels/consumer.py", line 58, in __call__
    await await_many_dispatch(
  File "/usr/local/lib/python3.8/site-packages/channels/utils.py", line 51, in await_many_dispatch
    await dispatch(result)
  File "/usr/local/lib/python3.8/site-packages/asgiref/sync.py", line 444, in __call__
    ret = await asyncio.wait_for(future, timeout=None)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 455, in wait_for
    return await fut
  File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.8/site-packages/channels/db.py", line 14, in thread_handler
    return super().thread_handler(loop, *args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/asgiref/sync.py", line 486, in thread_handler
    return func(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/channels/consumer.py", line 105, in dispatch
    handler(message)
  File "/usr/local/lib/python3.8/site-packages/channels/generic/websocket.py", line 39, in websocket_connect
    self.connect()
  File "/usr/src/app/officehours_api/consumers.py", line 63, in connect
    self.send_json({
  File "/usr/local/lib/python3.8/site-packages/channels/generic/websocket.py", line 139, in send_json
    super().send(text_data=self.encode_json(content), close=close)
  File "/usr/local/lib/python3.8/site-packages/channels/generic/websocket.py", line 75, in send
    super().send({"type": "websocket.send", "text": text_data})
  File "/usr/local/lib/python3.8/site-packages/channels/consumer.py", line 113, in send
    self.base_send(message)
  File "/usr/local/lib/python3.8/site-packages/asgiref/sync.py", line 223, in __call__
    return call_result.result()
  File "/usr/local/lib/python3.8/concurrent/futures/_base.py", line 437, in result
    return self.__get_result()
  File "/usr/local/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result
    raise self._exception
  File "/usr/local/lib/python3.8/site-packages/asgiref/sync.py", line 292, in main_wrap
    result = await self.awaitable(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/channels/sessions.py", line 236, in send
    return await self.real_send(message)
  File "/usr/local/lib/python3.8/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 215, in asgi_send
    await self.send(data)
  File "/usr/local/lib/python3.8/site-packages/websockets/protocol.py", line 555, in send
    await self.ensure_open()
  File "/usr/local/lib/python3.8/site-packages/websockets/protocol.py", line 803, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: code = 1006 (connection closed abnormally [internal]), no reason
jonespm commented 2 years ago

This seems like it might be relevant: https://stackoverflow.com/a/47521829/3708872

I don't exactly know the code for this but I've seen websocket has a default ping_interval of 20s and unless this is disabled (to be None) it can cause these issues if uncaught and having a conflict with a proxy.

The default timeout for Openshift is 30 seconds which might be causing this issue with the different timeouts. https://docs.redhat.com/en/documentation/red_hat_process_automation_manager/7.1/html/managing_and_monitoring_process_server/configuring-openshift-connection-timeout-proc