Fails to connect due to tornado.websocket.WebSocketClosedError

[tuxillo]

Hi,

With a very basic setup, that's no oauth, no LDAP, I'm getting the error below. Could it be that there is some sort of timeout? Also, maybe not echo the password in the logs :)

Thanks!

INFO:tornado.access:200 GET /dashboard (192.168.5.103) 4.29ms
INFO:tornado.access:101 GET /kvm (192.168.5.103) 0.72ms
INFO:root:Websocket opened by anonymous
INFO:root:Websocket from anonymous said {"action":"connect","server":"mykvmhost","password":"SECRET","resolution":"1280x960"}
INFO:root:anonymous wants to connect to mykvmhost with res 1280x960
INFO:nojava_ipmi_kvm.kvm:Check if 'http://ipmi.sector.int/' is reachable...
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): ipmi.sector.int:80
DEBUG:urllib3.connectionpool:http://ipmi.sector.int:80 "HEAD / HTTP/1.1" 200 0
INFO:nojava_ipmi_kvm.kvm:The url 'http://ipmi.sector.int/' is reachable.
INFO:nojava_ipmi_kvm.kvm:Starting the Docker container...
INFO:nojava_ipmi_kvm.kvm:Waiting for the Docker container to be up and ready...
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:8801
DEBUG:urllib3.connectionpool:http://localhost:8801 "HEAD / HTTP/1.1" 200 0
INFO:nojava_ipmi_kvm.kvm:Docker container is up and running.

INFO:nojava_ipmi_kvm.kvm:Docker container is up and running.
ERROR:tornado.application:Exception in callback functools.partial(<function WebSocketProtocol._run_callback.<locals>.<lambda> at 0x7f145dc28f70>, <Task finished name='Task-17' coro=<KVMHandler.on_message() done, defined at /home/ipmi/s/nojava-ipmi-kvm-server/kvm_handler.py:49> exception=WebSocketClosedError()>)
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/tornado/ioloop.py", line 741, in _run_callback
    ret = callback()
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 656, in <lambda>
    self.stream.io_loop.add_future(result, lambda f: f.result())
  File "/home/ipmi/s/nojava-ipmi-kvm-server/kvm_handler.py", line 109, in on_message
    sess = self._current_session = await start_kvm_container(
  File "/usr/local/lib/python3.8/dist-packages/nojava_ipmi_kvm/kvm.py", line 384, in start_kvm_container
    log("Docker container is up and running.")
  File "/usr/local/lib/python3.8/dist-packages/nojava_ipmi_kvm/kvm.py", line 136, in log
    additional_logging(msg, *args, **kwargs)
  File "/home/ipmi/s/nojava-ipmi-kvm-server/kvm_handler.py", line 93, in send_log_message
    self.write_message({"action": "log", "message": msg if len(args) == 0 else msg % args})
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 337, in write_message
    raise WebSocketClosedError()
tornado.websocket.WebSocketClosedError
ERROR:tornado.application:Uncaught exception GET /kvm (192.168.5.103)
HTTPServerRequest(protocol='http', host='nojava-ipmi.sector.int:8080', method='GET', uri='/kvm', version='HTTP/1.1', remote_ip='192.168.5.103')
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/tornado/web.py", line 1704, in _execute
    result = await result
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 278, in get
    await self.ws_connection.accept_connection(self)
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 879, in accept_connection
    await self._accept_connection(handler)
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 962, in _accept_connection
    await self._receive_frame_loop()
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 1116, in _receive_frame_loop
    await self._receive_frame()
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 1207, in _receive_frame
    await handled_future
  File "/usr/local/lib/python3.8/dist-packages/tornado/ioloop.py", line 741, in _run_callback
    ret = callback()
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 656, in <lambda>
    self.stream.io_loop.add_future(result, lambda f: f.result())
  File "/home/ipmi/s/nojava-ipmi-kvm-server/kvm_handler.py", line 109, in on_message
    sess = self._current_session = await start_kvm_container(
  File "/usr/local/lib/python3.8/dist-packages/nojava_ipmi_kvm/kvm.py", line 384, in start_kvm_container
    log("Docker container is up and running.")
  File "/usr/local/lib/python3.8/dist-packages/nojava_ipmi_kvm/kvm.py", line 136, in log
    additional_logging(msg, *args, **kwargs)
  File "/home/ipmi/s/nojava-ipmi-kvm-server/kvm_handler.py", line 93, in send_log_message
    self.write_message({"action": "log", "message": msg if len(args) == 0 else msg % args})
  File "/usr/local/lib/python3.8/dist-packages/tornado/websocket.py", line 337, in write_message
    raise WebSocketClosedError()
tornado.websocket.WebSocketClosedError

[Makr91]

I am also having this issue on Ubuntu

Linux automation-01.dc-01.m4kr.net 5.11.0-46-generic #51-Ubuntu SMP Thu Jan 6 22:14:29 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
root@automation-01:/home/homeassistant/docker# docker-compose --version
docker-compose version 1.29.2, build unknown
root@automation-01:/home/homeassistant/docker# docker -v
Docker version 20.10.7, build 20.10.7-0ubuntu5~21.04.2
root@automation-01:/home/homeassistant/docker#

[Prinzhorn]

I'm just passing by from a global GitHub search for tornado.websocket.WebSocketClosedError. This might be caused by a race condition in tornado, which would cause the cleanup code in on_close (self._current_session.kill_process()) to run before _current_session was even initialized

nojava-ipmi-kvm-server/kvm_handler.py

Lines 37 to 47 in b942091

	def open(self):
	self._current_session = None
	self._web_port = 0
	self._current_user = self.get_current_user()
	self._connecting = False
	self._is_closed = False
	if self._current_user is None or not self._current_user["is_admin"]:
	return self.close(code=401, reason="Unauthorized")
	logging.info("Websocket opened by %s", self._current_user["name"])

nojava-ipmi-kvm-server/kvm_handler.py

Lines 168 to 173 in b942091

	def on_close(self):
	logging.info("WS from %s closed", None if self._current_user is None else self._current_user["name"])
	self._is_closed = True
	if self._current_session is not None:
	used_ports.remove(self._web_port)
	self._current_session.kill_process()

tornadoweb/tornado#2958