Websockets errors after upgrading to stretch

nelbs · October 19, 2017, 7:44am

Hi guys,

Since python 3.4 will be deprecated in 2018 I upgraded my Hassbian installatie from jessie to stretch. The installation was succesfull but now the log shows a lot of repeated warnings and errors related to the websockets package. Beside that there are multiple “timer got out of sync” errors. What does these warnings and errors mean? and what can I do to fix the problem.

Thanks in adcance!

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/protocol.py", line 441, in run
    yield from self.fail_connection(1002)
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/protocol.py", line 650, in fail_connection
    yield from self.close_connection()
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/protocol.py", line 607, in close_connection
    "in the {} state".format(self.state_name))
websockets.exceptions.InvalidState: Cannot close a WebSocket connection in the CONNECTING state
2017-10-19 07:20:26 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:20:35 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:20:37 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:20:46 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:20:48 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:20:56 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:20:58 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:21:06 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:21:08 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:21:12 WARNING (MainThread) [websockets.server] Invalid handshake
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/server.py", line 174, in read_http_request
    path, headers = yield from read_request(self.reader)
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/http.py", line 83, in read_request
    raise ValueError("Unsupported HTTP method: %r" % method)
ValueError: Unsupported HTTP method: b'POST'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/server.py", line 69, in handler
    extra_headers=self.extra_headers)
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/server.py", line 297, in handshake
    path, request_headers = yield from self.read_http_request()
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/server.py", line 176, in read_http_request
    raise InvalidMessage("Malformed HTTP message") from exc
websockets.exceptions.InvalidMessage: Malformed HTTP message
2017-10-19 07:21:17 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-19 07:21:17 ERROR (Recorder) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/protocol.py", line 434, in run
    msg = yield from self.read_message()
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/protocol.py", line 456, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/protocol.py", line 511, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/protocol.py", line 546, in read_frame
    self.reader.readexactly, is_masked, max_size=max_size)
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/framing.py", line 90, in read_frame
    raise WebSocketProtocolError("Reserved bits must be 0")
websockets.exceptions.WebSocketProtocolError: Reserved bits must be 0

During handling of the above exception, another exception occurred:

gpbenton · October 19, 2017, 9:17pm

These are normally the result of the HA process being starved of resources, because something else is using up all the processing.

This could be the result of the websocket errors, or the websocket errors could also be caused by the something else using up resources.

Try running top and see what processes are running, and if any are using all the cpu or memory. Paste the output here if it doesn’t make sense, in case someone can help.

nelbs · October 20, 2017, 10:16am

This makes sense. I runned the top command and everything looks ok. This is obvious since I dont have the out of sync error at the moment. This is because I switch off many components to find out which one is using the websockets package what caused the problem. I think the out of sync error is a result of the websockets errors.

I also think that the components itself are not the problem but the websocket package. Maybe a wrong version or a corrupt installation? Does anyone know which components of homeassistant uses this package?

nelbs · October 20, 2017, 10:53am

After I switched on de device_tracker component the errors came back :(.

top shows that the command "hass’ uses the most resources. sometimes 100 %. Below I pasted the errors and the configuration script of my device_tracker file.

Error log

2017-10-20 10:39:35 WARNING (Thread-12) [homeassistant.components.light.hue] Connected to Hue at 192.168.1.108 but not registered.
2017-10-20 10:39:40 WARNING (MainThread) [homeassistant.setup] Setup of media_player is taking over 10 seconds.
2017-10-20 10:39:40 WARNING (MainThread) [homeassistant.setup] Setup of remote is taking over 10 seconds.
2017-10-20 10:39:40 WARNING (MainThread) [homeassistant.setup] Setup of device_tracker is taking over 10 seconds.
2017-10-20 10:39:42 WARNING (MainThread) [homeassistant.components.media_player] Setup of platform cast is taking over 10 seconds.
2017-10-20 10:39:46 WARNING (MainThread) [homeassistant.components.remote] Setup of platform harmony is taking over 10 seconds.
2017-10-20 10:40:09 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-20 10:40:11 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
2017-10-20 10:40:14 WARNING (MainThread) [websockets.server] Invalid handshake
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/server.py", line 174, in read_http_request
    path, headers = yield from read_request(self.reader)
  File "/srv/homeassistant/lib/python3.5/site-packages/websockets/http.py", line 83, in read_request
    raise ValueError("Unsupported HTTP method: %r" % method)
ValueError: Unsupported HTTP method: b'POST'

The above exception was the direct cause of the following exception:

Device_tracker.yaml

 - platform: bluetooth_tracker
   track_new_devices: no
   conside_home: 180
 - platform: owntracks
   max_gps_accuracy: 500
   waypoints: True
 - platform: nmap_tracker
   hosts:
     - 192.168.1.100
     - 192.168.1.101
     - 192.168.1.102
     - 192.168.1.104
     - 192.168.1.106
     - 192.168.1.107
     - 192.168.1.108
     - 192.168.1.109
     - 192.168.1.110
     - 192.168.1.111
     - 192.168.1.112
     - 192.168.1.113
   home_interval: 10

gpbenton · October 20, 2017, 1:07pm

The only item there that might use websockets is owntracks. It used to be exclusively MQTT based, but I did here that it had added a web interface. Are you using that, or MQTT?

nelbs · October 20, 2017, 1:31pm

You are correct, after turning on each component one by one I found out that mqtt causes the problem. In my previous installation (jessie) I used owntracks with a mosquitto broker. This worked fine.

In my current installation (stretch) I use the embedded broker which does not work…