ReadTimeoutError

[Fulch]

Home Assistant 0.107.7 Wiser R2.1

Been getting several of these each day lately, so added wiser debug logging and noticed that hub updates seem to happen every 30 seconds now. Did this not used to be controlled by the Scan_Interval parameter, which was suggested to be left at 300 seconds so as not to ask too much of the hub?

Logger: homeassistant.helpers.entity Source: custom_components/wiser/init.py:200 First occurred: 9:14:54 PM (2 occurrences) Last logged: 9:17:59 PM

Update for switch.wiser_comfort_mode fails
Update for switch.wiser_eco_mode fails

Traceback (most recent call last): File "/usr/local/lib/python3.7/site-packages/urllib3/response.py", line 425, in _error_catcher yield File "/usr/local/lib/python3.7/site-packages/urllib3/response.py", line 752, in read_chunked self._update_chunk_length() File "/usr/local/lib/python3.7/site-packages/urllib3/response.py", line 682, in _update_chunk_length line = self._fp.fp.readline() File "/usr/local/lib/python3.7/socket.py", line 589, in readinto return self._sock.recv_into(b) socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/local/lib/python3.7/site-packages/requests/models.py", line 751, in generate for chunk in self.raw.stream(chunk_size, decode_content=True): File "/usr/local/lib/python3.7/site-packages/urllib3/response.py", line 560, in stream for line in self.read_chunked(amt, decode_content=decode_content): File "/usr/local/lib/python3.7/site-packages/urllib3/response.py", line 781, in read_chunked self._original_response.close() File "/usr/local/lib/python3.7/contextlib.py", line 130, in exit self.gen.throw(type, value, traceback) File "/usr/local/lib/python3.7/site-packages/urllib3/response.py", line 430, in _error_catcher raise ReadTimeoutError(self._pool, None, "Read timed out.") urllib3.exceptions.ReadTimeoutError: HTTPConnectionPool(host='192.168.0.211', port=80): Read timed out.

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 279, in async_update_ha_state await self.async_device_update() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 474, in async_device_update await self.async_update() File "/config/custom_components/wiser/switch.py", line 103, in async_update await self.data.async_update() File "/config/custom_components/wiser/init.py", line 200, in async_update result = await self._hass.async_add_executor_job(self.wiserhub.refreshData) File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run result = self.fn(*self.args, self.kwargs) File "/usr/local/lib/python3.7/site-packages/wiserHeatingAPI/wiserHub.py", line 161, in refreshData WISERHUBURL.format(self.hubIP), headers=self.headers, timeout=TIMEOUT File "/usr/local/lib/python3.7/site-packages/requests/api.py", line 76, in get return request('get', url, params=params, kwargs) File "/usr/local/lib/python3.7/site-packages/requests/api.py", line 61, in request return session.request(method=method, url=url, kwargs) File "/usr/local/lib/python3.7/site-packages/requests/sessions.py", line 530, in request resp = self.send(prep, send_kwargs) File "/usr/local/lib/python3.7/site-packages/requests/sessions.py", line 683, in send r.content File "/usr/local/lib/python3.7/site-packages/requests/models.py", line 829, in content self._content = b''.join(self.iter_content(CONTENT_CHUNK_SIZE)) or b'' File "/usr/local/lib/python3.7/site-packages/requests/models.py", line 758, in generate raise ConnectionError(e) requests.exceptions.ConnectionError: HTTPConnectionPool(host='192.168.0.211', port=80): Read timed out.

[msp1974]

This was standardised to 30 seconds and i havent seen many timeouts. If i do see timeouts every so often but i am also seeing others, in particular from Alexa integration.

@Fulch few of questions. Do you have other timeouts showing? Do you have lots of http based integrations configured? How old is your wiser hub?

@asantaga we could put this back into config flow and default a value. Let me know if you want me to do this.

[Fulch]

Hi @msp1974 , thanks for the response. Since posting I found and changed MIN_TIME_BETWEEN_UPDATES to be 120 seconds. In the last 24hrs I've had no timeouts at all, whilst logging at info level the worst response time has been 3 seconds between Update of Wiser Hub data requested and Wiser Hub data updated and that was only one time according to the logs.

The only other timeouts I regularly see are from a TP-Link energy monitoring smart plug but this seems quite commonly reported and is being looked into by the dev's of the integration. Since changing the wiser timing update I've only had 3 TP-Link timeouts in the last 24hrs, whereas 10 to 12 would be more normal.

I believe TP-Link,Hue and Google are the only Http based integrations that I use, I do also have a zigbee hub using deCONZ with various sensors attached which use websockets.

The wiser hub was purchased and installed in Dec 2019, so not that old.

Using the Firefox inspector, it reports 15.1k of data is returned for the /data/domain/ endpoint on my system and most of that is the schedule data ( TRV x 4, roomstat, hotwater and smartplug) this will obviously vary for each system installed. Would reducing the amount of data requested from the hub (Use the V2 API you discovered) have any impact on timeouts though or is this just the nature of the hub?

[msp1974]

I think what is happening is that when the hub is busy doing something (updates to cloud or TRVs etc) it can't handle our api well. I presume, dropping the hub scan interval is meaning it is not coinciding with these moments as much.

I am currently working on being able to set the scan interval again so that people can vary to what suits their environment best.

[Fulch]

I totally agree with your reasoning and your proposed solution. This is still the most stable and well behaved of all the integrations I have tried out on the HA platform!

Have just been playing with HTTPCanary, it pretty much lays bare the entire wiser implementation including another easy way to find your "secret". Using /data/v2/domain/ is now only 8.9k vs 15.1k on v1 api.

[asantaga]

@msp1974 Yeah Im easy.. To be honest I dont see many, if any , timeouts.. but at the same time I just let it be.. but it makes sense to put it back in. From your comment I assume your already working on a PR?.. Later tonight I will be working on #90 and #88 so I can merge it in tonight..

[msp1974]

Yes , think i have done but want to test a little more before i send PR. Will be prob tomorrow.

[asantaga]

@Fulch , can you test out the latest dev branch and see if @msp1974 fixes work for you?

wrt battery values on roomstats ignore them, still trying to figure out the right values.

[Fulch]

Just installed latest dev, will monitor logs and report back. Thanks @msp1974 for all the updates!

[msp1974]

@Fulch any update on this?

[Fulch]

Yes, your rewrite making use of the event loop scheduler and other optimisations produce refresh updates with the precision of a swiss watch! Also no more unhandled exceptions for HA to fill the log with. Still getting timeouts due to the hub not responding and I can't detect any pattern to it but I do accept it's just how the hub behaves. Have had a go at modding the wiserHubAPI to add a retry on a timeout or connection exception and limited to a max of two retries so far it has not failed to get an update but I won't hold my breath! Log below from last 20+ hrs.

2020-04-07 22:22:32 INFO (MainThread) [custom_components.wiser.const] Update of Wiser Hub data requested on 30 seconds interval 2020-04-07 22:22:33 INFO (MainThread) [custom_components.wiser.const] Wiser Hub data updated 2020-04-08 00:11:03 WARNING (SyncWorker_11) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 03:14:04 WARNING (SyncWorker_12) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 03:18:35 WARNING (SyncWorker_8) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 03:31:43 WARNING (Thread-2) [pychromecast.socket_client] [Lounge:8009] Heartbeat timeout, resetting connection 2020-04-08 05:09:35 WARNING (SyncWorker_10) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 05:09:38 WARNING (SyncWorker_10) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 2 2020-04-08 08:38:36 WARNING (SyncWorker_18) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 09:22:03 WARNING (SyncWorker_5) [homeassistant.components.tplink.switch] Could not read state for 192.168.0.142: Communication error 2020-04-08 09:47:37 WARNING (SyncWorker_7) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 11:37:37 WARNING (SyncWorker_17) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 14:43:07 WARNING (SyncWorker_1) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 14:43:11 WARNING (SyncWorker_1) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 2 2020-04-08 15:18:10 WARNING (SyncWorker_3) [homeassistant.components.tplink.switch] Could not read state for 192.168.0.142: Communication error 2020-04-08 16:26:47 WARNING (SyncWorker_17) [homeassistant.components.tplink.switch] Could not read state for 192.168.0.142: Communication error 2020-04-08 17:42:08 WARNING (SyncWorker_9) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 17:42:13 WARNING (SyncWorker_9) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 2

[asantaga]

Nice,

Feel free to log a PR against the base api

On Wed, 8 Apr 2020 at 20:36, Fulch notifications@github.com wrote:

Yes, your rewrite making use of the event loop scheduler and other optimisations produce refresh updates with the precision of a swiss watch! Also no more unhandled exceptions for HA to fill the log with. Still getting timeouts due to the hub not responding and I can't detect any pattern to it but I do accept it's just how the hub behaves. Have had a go at modding the wiserHubAPI to add a retry on a timeout or connection exception and limited to a max of two retries so far it has not failed to get an update but I won't hold my breath! Log below from last 20+ hrs.

2020-04-07 22:22:32 INFO (MainThread) [custom_components.wiser.const] Update of Wiser Hub data requested on 30 seconds interval 2020-04-07 22:22:33 INFO (MainThread) [custom_components.wiser.const] Wiser Hub data updated 2020-04-08 00:11:03 WARNING (SyncWorker_11) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 03:14:04 WARNING (SyncWorker_12) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 03:18:35 WARNING (SyncWorker_8) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 03:31:43 WARNING (Thread-2) [pychromecast.socket_client] [Lounge:8009] Heartbeat timeout, resetting connection 2020-04-08 05:09:35 WARNING (SyncWorker_10) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 05:09:38 WARNING (SyncWorker_10) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 2 2020-04-08 08:38:36 WARNING (SyncWorker_18) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 09:22:03 WARNING (SyncWorker_5) [homeassistant.components.tplink.switch] Could not read state for 192.168.0.142: Communication error 2020-04-08 09:47:37 WARNING (SyncWorker_7) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 11:37:37 WARNING (SyncWorker_17) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 14:43:07 WARNING (SyncWorker_1) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 14:43:11 WARNING (SyncWorker_1) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 2 2020-04-08 15:18:10 WARNING (SyncWorker_3) [homeassistant.components.tplink.switch] Could not read state for 192.168.0.142: Communication error 2020-04-08 16:26:47 WARNING (SyncWorker_17) [homeassistant.components.tplink.switch] Could not read state for 192.168.0.142: Communication error 2020-04-08 17:42:08 WARNING (SyncWorker_9) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 1 2020-04-08 17:42:13 WARNING (SyncWorker_9) [wiserHeatingAPI.wiserHub] Connection timeout retry No. 2

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/asantaga/wiserHomeAssistantPlatform/issues/91#issuecomment-611151644, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAWN2QEBZVCJBPEUBO6GSBTRLTG3BANCNFSM4L4OVKVA .

--

Angelo

[asantaga]

I'll close this issue as the issue can be solved in the wiser-heating-api instead,.. if/when u log a PR

[msp1974]

@Fulch from your logs it seems like you are getting timeout for other devices too. This is my experience. Im wondering if this is a HA issue due to connection pool not having enough available connections and hitting a contention with other integrations. Will research this more when I have time.