search

tuya / tuya-iot-python-sdk

Tuya IoT Python SDK for Tuya Open API.
MIT License
117 stars 47 forks source link

tuya_iot getting error "Failed to establish a new connection" #56

Closed ZephireNZ closed 2 years ago

ZephireNZ commented 2 years ago

I am getting a error where the API intermittently will fail to connect.

From what I can tell, the error causes the Tuya integration in Home Assistant to stop tracking device state. I have two devices, a light and a heat pump, and both are "frozen" in time after the error occurs. A reboot will usually fix the issue (presumably at the time of the reboot, the API is responsive again).

I can see multiple issues on Home Assistant Core which seem could be related: https://github.com/home-assistant/core/issues/63957 https://github.com/home-assistant/core/issues/64077 https://github.com/home-assistant/core/issues/65099 https://github.com/home-assistant/core/issues/65524 https://github.com/home-assistant/core/issues/65634 https://github.com/home-assistant/core/issues/65758

I think one solution would be to use exponential backoff to retry the API. Based on the log below, it's looks to be trying a few times and then stops tracking state entirely.

Here's the most recent log from today, that shows the issue. Home Assistant shows no state change from 16:06 onwards.

2022-02-06 16:04:55 DEBUG (Thread-33) [tuya_iot] _on_log: Received PUBLISH (d0, q0, r0, m0), 'cloud/token/in/d249680c232bf1a26ec786b86fecbf0f', ...  (348 bytes)
2022-02-06 16:04:55 DEBUG (Thread-33) [tuya_iot] payload-> b'{"data":"dRgRVE73G2xRptoTBwYRK0o5qn+tmZWI+0Sadjg7p+jmFAPNqPDoQMSoWxiI7X62X0mAVEdXxSIK1ooNccSsMob3dCy5cx7t4SBdBSBhhpF+R/sAVw93LMPxvio06DqsgHu7nYUK4jOJ6ACEvb3roOoUgyKzMTLn80277aitytz2h0zqqUpBtojYaS1HUOApEfMiOiqJadn4K+tC3U4OboBuuSa2u1ZhLDtrFocRlGtjAWlupFrG58u/tvjGzn5z","protocol":4,"pv":"2.0","sign":"3d4f08833ce8be059c2a88b564dcb365","t":1644116694}'
2022-02-06 16:04:55 DEBUG (Thread-33) [tuya_iot] on_message: {'data': {'dataId': '3eeb7ae6-930c-4e3d-ac1c-399df3f0ba23', 'devId': '078443178caab57ec4c8', 'productKey': 'gylvqvz3p94i3zdn', 'status': [{'3': 24, 'code': 'temp_current', 't': '1644116694', 'value': 24}]}, 'protocol': 4, 'pv': '2.0', 'sign': '3d4f08833ce8be059c2a88b564dcb365', 't': 1644116694}
2022-02-06 16:04:55 DEBUG (Thread-33) [tuya_iot] mq receive-> {'data': {'dataId': '3eeb7ae6-930c-4e3d-ac1c-399df3f0ba23', 'devId': '078443178caab57ec4c8', 'productKey': 'gylvqvz3p94i3zdn', 'status': [{'3': 24, 'code': 'temp_current', 't': '1644116694', 'value': 24}]}, 'protocol': 4, 'pv': '2.0', 'sign': '3d4f08833ce8be059c2a88b564dcb365', 't': 1644116694}
2022-02-06 16:04:55 DEBUG (Thread-33) [tuya_iot] mq _on_device_report-> [{'3': 24, 'code': 'temp_current', 't': '1644116694', 'value': 24}]
2022-02-06 16:04:55 DEBUG (Thread-33) [homeassistant.components.tuya] Received update for device 078443178caab57ec4c8: {'switch': True, 'temp_set': 24, 'temp_current': 24, 'mode': 'cold', 'anion': False, 'temp_set_f': 61, 'temp_current_f': 32}
2022-02-06 16:05:18 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:05:18 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:05:44 DEBUG (Thread-33) [tuya_iot] _on_log: Received PUBLISH (d0, q0, r0, m0), 'cloud/token/in/d249680c232bf1a26ec786b86fecbf0f', ...  (348 bytes)
2022-02-06 16:05:45 DEBUG (Thread-33) [tuya_iot] payload-> b'{"data":"iHsj7kaTxdR5zYikRVh0oQoBrIUDK6SZ59En0NdecuUV0bpkMJU/e8e97NrJZwaKX0mAVEdXxSIK1ooNccSsMob3dCy5cx7t4SBdBSBhhpF+R/sAVw93LMPxvio06DqsgHu7nYUK4jOJ6ACEvb3roOoUgyKzMTLn80277aitytyHLFff/vzp/sSHFYMNyxN/EfMiOiqJadn4K+tC3U4Obp+vMnCJhNITPzBgDfMAFmWXG93EDTzim9Aa7i73r2/y","protocol":4,"pv":"2.0","sign":"a414390bb2befd85584774524097bf2e","t":1644116743}'
2022-02-06 16:05:45 DEBUG (Thread-33) [tuya_iot] on_message: {'data': {'dataId': '218f257e-4c72-4f29-9410-387f5a60522d', 'devId': '078443178caab57ec4c8', 'productKey': 'gylvqvz3p94i3zdn', 'status': [{'3': 23, 'code': 'temp_current', 't': '1644116743', 'value': 23}]}, 'protocol': 4, 'pv': '2.0', 'sign': 'a414390bb2befd85584774524097bf2e', 't': 1644116743}
2022-02-06 16:05:45 DEBUG (Thread-33) [tuya_iot] mq receive-> {'data': {'dataId': '218f257e-4c72-4f29-9410-387f5a60522d', 'devId': '078443178caab57ec4c8', 'productKey': 'gylvqvz3p94i3zdn', 'status': [{'3': 23, 'code': 'temp_current', 't': '1644116743', 'value': 23}]}, 'protocol': 4, 'pv': '2.0', 'sign': 'a414390bb2befd85584774524097bf2e', 't': 1644116743}
2022-02-06 16:05:45 DEBUG (Thread-33) [tuya_iot] mq _on_device_report-> [{'3': 23, 'code': 'temp_current', 't': '1644116743', 'value': 23}]
2022-02-06 16:05:45 DEBUG (Thread-33) [homeassistant.components.tuya] Received update for device 078443178caab57ec4c8: {'switch': True, 'temp_set': 24, 'temp_current': 23, 'mode': 'cold', 'anion': False, 'temp_set_f': 61, 'temp_current_f': 32}
2022-02-06 16:05:46 DEBUG (Thread-33) [tuya_iot] _on_log: Received PUBLISH (d0, q0, r0, m0), 'cloud/token/in/d249680c232bf1a26ec786b86fecbf0f', ...  (348 bytes)
2022-02-06 16:05:46 DEBUG (Thread-33) [tuya_iot] payload-> b'{"data":"o0YNq9wgHukb77DoDinU4AuUfzTPUFHg+IryeGIOWKzNIAVp5B5j/Wgkgx/szz6WX0mAVEdXxSIK1ooNccSsMob3dCy5cx7t4SBdBSBhhpF+R/sAVw93LMPxvio06DqsgHu7nYUK4jOJ6ACEvb3roOoUgyKzMTLn80277aitytz2h0zqqUpBtojYaS1HUOApEfMiOiqJadn4K+tC3U4ObhBhjV4btFSnXJlvbvKV+bZjAWlupFrG58u/tvjGzn5z","protocol":4,"pv":"2.0","sign":"d93f9d396e76ae4d939f60f0a14e30f6","t":1644116745}'
2022-02-06 16:05:46 DEBUG (Thread-33) [tuya_iot] on_message: {'data': {'dataId': 'f0aba7ce-3878-4dca-80f2-20b6303ed5bf', 'devId': '078443178caab57ec4c8', 'productKey': 'gylvqvz3p94i3zdn', 'status': [{'3': 24, 'code': 'temp_current', 't': '1644116745', 'value': 24}]}, 'protocol': 4, 'pv': '2.0', 'sign': 'd93f9d396e76ae4d939f60f0a14e30f6', 't': 1644116745}
2022-02-06 16:05:46 DEBUG (Thread-33) [tuya_iot] mq receive-> {'data': {'dataId': 'f0aba7ce-3878-4dca-80f2-20b6303ed5bf', 'devId': '078443178caab57ec4c8', 'productKey': 'gylvqvz3p94i3zdn', 'status': [{'3': 24, 'code': 'temp_current', 't': '1644116745', 'value': 24}]}, 'protocol': 4, 'pv': '2.0', 'sign': 'd93f9d396e76ae4d939f60f0a14e30f6', 't': 1644116745}
2022-02-06 16:05:46 DEBUG (Thread-33) [tuya_iot] mq _on_device_report-> [{'3': 24, 'code': 'temp_current', 't': '1644116745', 'value': 24}]
2022-02-06 16:05:46 DEBUG (Thread-33) [homeassistant.components.tuya] Received update for device 078443178caab57ec4c8: {'switch': True, 'temp_set': 24, 'temp_current': 24, 'mode': 'cold', 'anion': False, 'temp_set_f': 61, 'temp_current_f': 32}
2022-02-06 16:06:18 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:06:18 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:06:20 DEBUG (Thread-33) [tuya_iot] _on_log: Received PUBLISH (d0, q0, r0, m0), 'cloud/token/in/d249680c232bf1a26ec786b86fecbf0f', ...  (348 bytes)
2022-02-06 16:06:20 DEBUG (Thread-33) [tuya_iot] payload-> b'{"data":"gNFDOxLjZG3IJDxyG7mnzvfXpvkcj4kgIu1URZfC1e7Kt0mYlvr9LJd2Hc4Iab5nX0mAVEdXxSIK1ooNccSsMob3dCy5cx7t4SBdBSBhhpF+R/sAVw93LMPxvio06DqsgHu7nYUK4jOJ6ACEvb3roOoUgyKzMTLn80277aitytwwWOckLP1BaMf9gswE6vdBEfMiOiqJadn4K+tC3U4ObnNMQ2jHyxHDRK/NKMWvv4PlWZzn4sTjqROwVZy3mgVT","protocol":4,"pv":"2.0","sign":"c454868db621f241b62807100c47deb7","t":1644116779}'
2022-02-06 16:06:20 DEBUG (Thread-33) [tuya_iot] on_message: {'data': {'dataId': '1d448d81-3136-400b-8b8d-5bc35ebcf9ae', 'devId': '078443178caab57ec4c8', 'productKey': 'gylvqvz3p94i3zdn', 'status': [{'3': 25, 'code': 'temp_current', 't': '1644116779', 'value': 25}]}, 'protocol': 4, 'pv': '2.0', 'sign': 'c454868db621f241b62807100c47deb7', 't': 1644116779}
2022-02-06 16:06:20 DEBUG (Thread-33) [tuya_iot] mq receive-> {'data': {'dataId': '1d448d81-3136-400b-8b8d-5bc35ebcf9ae', 'devId': '078443178caab57ec4c8', 'productKey': 'gylvqvz3p94i3zdn', 'status': [{'3': 25, 'code': 'temp_current', 't': '1644116779', 'value': 25}]}, 'protocol': 4, 'pv': '2.0', 'sign': 'c454868db621f241b62807100c47deb7', 't': 1644116779}
2022-02-06 16:06:20 DEBUG (Thread-33) [tuya_iot] mq _on_device_report-> [{'3': 25, 'code': 'temp_current', 't': '1644116779', 'value': 25}]
2022-02-06 16:06:20 DEBUG (Thread-33) [homeassistant.components.tuya] Received update for device 078443178caab57ec4c8: {'switch': True, 'temp_set': 24, 'temp_current': 25, 'mode': 'cold', 'anion': False, 'temp_set_f': 61, 'temp_current_f': 32}
2022-02-06 16:06:25 DEBUG (Thread-18) [tuya_iot] Request: method = GET,                 url = https://openapi.tuyaus.com/v1.0/token/506c665c72bdc06091c264dac8ec4100,                params = None,                body = None,                t = 1644116785539
2022-02-06 16:06:30 ERROR (Thread-18) [root] Uncaught thread exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 174, in _new_conn
    conn = connection.create_connection(
  File "/usr/local/lib/python3.9/site-packages/urllib3/util/connection.py", line 72, in create_connection
    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
  File "/usr/local/lib/python3.9/socket.py", line 954, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -3] Try again

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 386, in _make_request
    self._validate_conn(conn)
  File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 1040, in _validate_conn
    conn.connect()
  File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 358, in connect
    conn = self._new_conn()
  File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 186, in _new_conn
    raise NewConnectionError(
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPSConnection object at 0x7f0c25d07460>: Failed to establish a new connection: [Errno -3] Try again

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/requests/adapters.py", line 440, in send
    resp = conn.urlopen(
  File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 785, in urlopen
    retries = retries.increment(
  File "/usr/local/lib/python3.9/site-packages/urllib3/util/retry.py", line 592, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='openapi.tuyaus.com', port=443): Max retries exceeded with url: /v1.0/token/506c665c72bdc06091c264dac8ec4100 (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f0c25d07460>: Failed to establish a new connection: [Errno -3] Try again'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/threading.py", line 973, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.9/site-packages/tuya_iot/openmq.py", line 158, in run
    self.__run_mqtt()
  File "/usr/local/lib/python3.9/site-packages/tuya_iot/openmq.py", line 164, in __run_mqtt
    mq_config = self._get_mqtt_config()
  File "/usr/local/lib/python3.9/site-packages/tuya_iot/openmq.py", line 62, in _get_mqtt_config
    response = self.api.post(
  File "/usr/local/lib/python3.9/site-packages/tuya_iot/openapi.py", line 316, in post
    return self.__request("POST", path, None, body)
  File "/usr/local/lib/python3.9/site-packages/tuya_iot/openapi.py", line 238, in __request
    self.__refresh_access_token_if_need(path)
  File "/usr/local/lib/python3.9/site-packages/tuya_iot/openapi.py", line 164, in __refresh_access_token_if_need
    response = self.get(
  File "/usr/local/lib/python3.9/site-packages/tuya_iot/openapi.py", line 302, in get
    return self.__request("GET", path, params, None)
  File "/usr/local/lib/python3.9/site-packages/tuya_iot/openapi.py", line 266, in __request
    response = self.session.request(
  File "/usr/local/lib/python3.9/site-packages/requests/sessions.py", line 529, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python3.9/site-packages/requests/sessions.py", line 645, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/requests/adapters.py", line 519, in send
    raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='openapi.tuyaus.com', port=443): Max retries exceeded with url: /v1.0/token/506c665c72bdc06091c264dac8ec4100 (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f0c25d07460>: Failed to establish a new connection: [Errno -3] Try again'))
2022-02-06 16:07:19 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:07:19 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:08:19 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:08:19 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:09:19 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:09:19 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:10:19 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:10:19 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:11:19 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:11:20 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:12:20 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:12:20 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:13:20 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:13:20 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:14:20 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:14:20 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:15:20 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:15:21 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:16:21 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:16:21 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:17:21 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:17:21 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:18:21 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:18:21 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:19:21 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:19:21 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:20:21 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:20:22 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:21:22 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:21:22 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
2022-02-06 16:22:22 DEBUG (Thread-33) [tuya_iot] _on_log: Sending PINGREQ
2022-02-06 16:22:22 DEBUG (Thread-33) [tuya_iot] _on_log: Received PINGRESP
ZephireNZ commented 2 years ago

Just dug into the code to see if I can figure out a way to prevent this from happening.

Aside from resolving the actual Tuya server issues, the code can be updated to be more resilient.

In this case, it's the MQTT client that is failing to re-connect after 2 hours.

In openmq the client is recreated. Normally this is fine. However in the call to self._get_mqtt_config() the API server fails to connect, and the error that is throw ripples all the way up to the run() loop. This loop doesn't handle the error, and so the MQTT server eventually expires and the loop is no longer replacing it.

I think this loop should have a try/except added so that it can handle any errors thrown, and continue trying to refresh the MQTT server until it is successful. Given that it's an API server, probably best to have exponential backoff so as to not hammer the server with requests when it is down.

cvroque commented 2 years ago

Amazing work, here's hoping your PR gets accepted soon.

Here's another related issue: https://github.com/home-assistant/core/issues/63052

cvroque commented 2 years ago

@zlinoliver Hello, will we get a new release with this fix soon?

Michi55555 commented 2 years ago

Same issue on my side since months. I hope there will be a new release soon. Thanks.