WebSocket handshake error

[golles]

Describe the bug I've seen this handshake error 2 (or 3) times in the last couple of weeks. According to #37 this is related to an outage of the supplier.

To Reproduce N/A

Expected behavior Even though there isn't much you can do about the unavailability of the service, I believe the component should be able to recover from such a problem.

Screenshots N/A

Version of the component 0.4.3 (lghorizon>=0.5.12)

Logging

2023-02-07 01:51:42.205 ERROR (Thread-3 (_thread_main)) [lghorizon.models] Caught exception in on_connect: WebSocket handshake error
2023-02-07 01:51:42.209 ERROR (Thread-3 (_thread_main)) [root] Uncaught thread exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3591, in _thread_main
    self.loop_forever(retry_first_connection=True)
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1756, in loop_forever
    rc = self._loop(timeout)
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1164, in _loop
    rc = self.loop_read()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1556, in loop_read
    rc = self._packet_read()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 2439, in _packet_read
    rc = self._packet_handle()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3039, in _packet_handle
    return self._handle_connack()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3138, in _handle_connack
    on_connect(
  File "/usr/local/lib/python3.10/site-packages/lghorizon/models.py", line 314, in _on_mqtt_connect
    self.connect()
  File "/usr/local/lib/python3.10/site-packages/lghorizon/models.py", line 319, in connect
    self._mqtt_client.connect(self._brokerUrl, 443)
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 914, in connect
    return self.reconnect()
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 1080, in reconnect
    sock = WebsocketWrapper(sock, self._host, self._port, self._ssl,
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3713, in __init__
    self._do_handshake(extra_headers)
  File "/usr/local/lib/python3.10/site-packages/paho/mqtt/client.py", line 3797, in _do_handshake
    raise WebsocketConnectionError("WebSocket handshake error")
paho.mqtt.client.WebsocketConnectionError: WebSocket handshake error

Additional context I'm now either reloading the component manually or restarting HA, which fixes the issue.

[mleenaerts]

Some kind of recover mechanism would indeed be very nice, at least it assures automations to keep working.

[Sholofly]

@golles I've added some recovery mechanism. in the latest version with some sliding interval of retry-attempts. Please let me know if you see improvement on this matter.

[golles]

I'm not sure if this is related but got this yesterday:

2023-03-29 18:23:34.536 ERROR (Thread-3 (_thread_main)) [lghorizon.lghorizon_api] Could not handle status message
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 449, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 444, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/local/lib/python3.10/http/client.py", line 1374, in getresponse
    response.begin()
  File "/usr/local/lib/python3.10/http/client.py", line 318, in begin
    version, status, reason = self._read_status()
  File "/usr/local/lib/python3.10/http/client.py", line 287, in _read_status
    raise RemoteDisconnected("Remote end closed connection without"
http.client.RemoteDisconnected: Remote end closed connection without response

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/requests/adapters.py", line 489, in send
    resp = conn.urlopen(
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 787, in urlopen
    retries = retries.increment(
  File "/usr/local/lib/python3.10/site-packages/urllib3/util/retry.py", line 550, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.10/site-packages/urllib3/packages/six.py", line 769, in reraise
    raise value.with_traceback(tb)
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 449, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 444, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/local/lib/python3.10/http/client.py", line 1374, in getresponse
    response.begin()
  File "/usr/local/lib/python3.10/http/client.py", line 318, in begin
    version, status, reason = self._read_status()
  File "/usr/local/lib/python3.10/http/client.py", line 287, in _read_status
    raise RemoteDisconnected("Remote end closed connection without"
urllib3.exceptions.ProtocolError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/lghorizon/lghorizon_api.py", line 298, in _on_mqtt_message
    self._handle_box_update(deviceId, message)
  File "/usr/local/lib/python3.10/site-packages/lghorizon/lghorizon_api.py", line 331, in _handle_box_update
    raw_replay_event = self._do_api_call(f"{self._country_settings['api_url']}/eng/web/linear-service/v2/replayEvent/{eventId}?returnLinearContent=true&language={self._country_settings['language']}")
  File "/usr/local/lib/python3.10/site-packages/backoff/_sync.py", line 105, in retry
    ret = target(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/lghorizon/lghorizon_api.py", line 360, in _do_api_call
    api_response = self._session.get(url)
  File "/usr/local/lib/python3.10/site-packages/requests/sessions.py", line 600, in get
    return self.request("GET", url, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/requests/sessions.py", line 587, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python3.10/site-packages/requests/sessions.py", line 701, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/requests/adapters.py", line 547, in send
    raise ConnectionError(err, request=request)
requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))
2023-03-29 18:23:34.546 WARNING (Thread-3 (_thread_main)) [lghorizon.lghorizon_api] Full message: {'version': '1.3.18', 'type': 'CPE.uiStatus', 'source': '3C36E4-EOSSTB-003926772108', 'messageTimeStamp': 1680107013470, 'status': {'uiStatus': 'mainUI', 'playerState': {'sourceType': 'replay', 'speed': 1, 'lastSpeedChangeTime': 1680105779517, 'source': {'eventId': 'crid:~~2F~~2Fgn.tv~~2F24237772~~2FEP044303940147,imi:cf7dcac4de382211a0887b3dc845ee2c3383828b', 'prePadding': 300000, 'postPadding': 7200000, 'sessionStartTime': 1680106860000, 'sessionEndTime': 1680108900000}, 'relativePosition': 300280}, 'uiState': {}}}

Another thing I noticed is that sometimes fields become null (very likely due to the above):

media_content_type: episode
entity_picture_local: null
play_mode: null
channel: null
title: null
image: null
recording_capacity: null
device_class: tv
friendly_name: Mediabox
supported_features: 154545

[Sholofly]

These are two different issues. The mqtt issue should be partially resolved by a retry mechanism. Does this work for you?

[golles]

I haven't seen any issues recently

[Sholofly]

Ok, thanks for the feedback. I'm closing this right now. Feel free te reopen s issues reappear.