Core: Viessmann integration failes sometimes

[rappenze]

Home Assistant release with the issue:
0.100.2

Last working Home Assistant release (if known):
The previous custom component from @oischinger didn't have the problem.

Operating environment (Hass.io/Docker/Windows/etc.):
hassbian on raspberry pi 3b

Integration:
vicare

Description of problem:
After some time, the vicare integration stops working. A restart solves the problem. I'm unsure what the problem is, but it could be that some missing exception handling when the server is down is the cvause of the problem. Interesting could also be the fact that restart of home assistant is not possible from UI after the vicare integration stops working. The process is then blocked and either reboot of the raspberry pi is needed or I have to manually kill the home assistant process(es) from the command line.

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

vicare:
  username: ***
  password: ***

Traceback (if applicable):

2019-10-18 01:04:52 ERROR (MainThread) [homeassistant.helpers.entity] Update for water_heater.vicare_water fails
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/connectionpool.py", line 603, in urlopen
    chunked=chunked)
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/connectionpool.py", line 387, in _make_request
    six.raise_from(e, None)
  File "<string>", line 2, in raise_from
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/connectionpool.py", line 383, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/local/lib/python3.7/http/client.py", line 1321, in getresponse
    response.begin()
  File "/usr/local/lib/python3.7/http/client.py", line 296, in begin
    version, status, reason = self._read_status()
  File "/usr/local/lib/python3.7/http/client.py", line 265, 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 "/srv/homeassistant/lib/python3.7/site-packages/requests/adapters.py", line 449, in send
    timeout=timeout
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/connectionpool.py", line 641, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/util/retry.py", line 368, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/packages/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/connectionpool.py", line 603, in urlopen
    chunked=chunked)
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/connectionpool.py", line 387, in _make_request
    six.raise_from(e, None)
  File "<string>", line 2, in raise_from
  File "/srv/homeassistant/lib/python3.7/site-packages/urllib3/connectionpool.py", line 383, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/local/lib/python3.7/http/client.py", line 1321, in getresponse
    response.begin()
  File "/usr/local/lib/python3.7/http/client.py", line 296, in begin
    version, status, reason = self._read_status()
  File "/usr/local/lib/python3.7/http/client.py", line 265, 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 "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity.py", line 268, in async_update_ha_state
    await self.async_device_update()
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity.py", line 448, in async_device_update
    await self.hass.async_add_executor_job(self.update)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/vicare/water_heater.py", line 68, in update
    current_temperature = self._api.getDomesticHotWaterStorageTemperature()
  File "/srv/homeassistant/lib/python3.7/site-packages/PyViCare/PyViCareDevice.py", line 220, in getDomesticHotWaterStorageTemperature
    return self.service.getProperty("heating.dhw.sensors.temperature.hotWaterStorage")["properties"]["value"]["value"]
  File "/srv/homeassistant/lib/python3.7/site-packages/PyViCare/PyViCareService.py", line 231, in getProperty
    j=self.__get(url)
  File "/srv/homeassistant/lib/python3.7/site-packages/PyViCare/PyViCareService.py", line 164, in __get
    r=self.oauth.get(url).json()
  File "/srv/homeassistant/lib/python3.7/site-packages/requests/sessions.py", line 546, in get
    return self.request('GET', url, **kwargs)
  File "/srv/homeassistant/lib/python3.7/site-packages/requests_oauthlib/oauth2_session.py", line 425, in request
    headers=headers, data=data, **kwargs)
  File "/srv/homeassistant/lib/python3.7/site-packages/requests/sessions.py", line 533, in request
    resp = self.send(prep, **send_kwargs)
  File "/srv/homeassistant/lib/python3.7/site-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
  File "/srv/homeassistant/lib/python3.7/site-packages/requests/adapters.py", line 498, in send
    raise ConnectionError(err, request=request)
requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))

Additional information:
vicare_log.txt

[probot-home-assistant[bot]]

Hey there @oischinger, mind taking a look at this issue as its been labeled with a integration (vicare) you are listed as a codeowner for? Thanks!

[oischinger]

Seems to be an issue on the server side when handling the request. Maybe we could just catch the exception and go ahead instead of breaking the whole integration.

[rappenze]

I'm not sure if exception handling is enough. As the exception is logged properly it looks for me like home assistant is handling this exception. For me it looks like one of the underlying library (requests and requests-oauth2) is not thread safe. As I understand correctly home assistant is doing polling in multiple threads and it looks like something is messed up when calls or token refresh are made simultaneously.

[oischinger]

Yeah,
I just looked at some other integrations using rest apis and they also seem to perform some catching of exceptions.
I modified the code in my local HA instance but I never run into the issue.
Does this happen a lot on your HA installation?
Would you mind testing a potential fix?

[rappenze]

Error occured normally around 48h after starting HA. If you provide me the fix I can test it.

[oischinger]

I have uploaded a potential fix to the github repo:
https://github.com/oischinger/ha_vicare/tree/master/vicare

It tries to catch a some exceptions in the climate component (note that I did not add this exception handling to the water heater so far.

[crazyfx1]

I just "installed" your branch and will test the stability.
Unfortunately my last PR #27604 which fixed the heating mode is missing in your branch so it's kind of a mixed bag for me ;)

[oischinger]

@crazyfx1
Right. Let me fix that later today. I don't ever change the temperature so I didn't notice.

[oischinger]

@crazyfx1 I synced the master branch with your heating mode / set temperature bugfix

[rappenze]

I tried your code, but the import statements are missing.

Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity.py", line 268, in async_update_ha_state
    await self.async_device_update()
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity.py", line 448, in async_device_update
    await self.hass.async_add_executor_job(self.update)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/homeassistant/.homeassistant/custom_components/vicare/climate.py", line 139, in update
    except requests.exceptions.ConnectionError:
NameError: name 'requests' is not defined

So I added the imports and restarted home assistant. I will keep you up to date with tst results.

[crazyfx1]

I think we need the exception handling in the water heater aswell to test the stability. Seems like this error kills both entities.

2019-10-30 22:43:32 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 275, in async_update_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 316, in _async_write_ha_state
    attr.update(self.state_attributes or {})
  File "/usr/src/homeassistant/homeassistant/components/water_heater/__init__.py", line 167, in state_attributes
    self.precision,
  File "/usr/src/homeassistant/homeassistant/helpers/temperature.py", line 23, in display_temp
    raise TypeError(f"Temperature is not a number: {temperature}")
TypeError: Temperature is not a number: error
2019-10-30 22:52:27 WARNING (MainThread) [homeassistant.helpers.entity] Update of water_heater.vicare_water is taking over 10 seconds

[oischinger]

That was fast.
But in this case we could also just check for "error" return values from PyVicare

[oischinger]

The interesting thing is:
Tonight I had the same issue at the very same time:

Log Details (ERROR)
Wed Oct 30 2019 22:43:40 GMT+0100 (Mitteleuropäische Normalzeit)
Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 273, in async_update_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 314, in _async_write_ha_state
    attr.update(self.state_attributes or {})
  File "/usr/src/homeassistant/homeassistant/components/water_heater/__init__.py", line 167, in state_attributes
    self.precision,
  File "/usr/src/homeassistant/homeassistant/helpers/temperature.py", line 23, in display_temp
    raise TypeError(f"Temperature is not a number: {temperature}")
TypeError: Temperature is not a number: error

It seems the Viessmann server might be the cause.

[oischinger]

OK here's another commit that fixes the imports and avoids the "error" temperature value:
https://github.com/oischinger/ha_vicare/commit/38af017444475130b141dd846c5fc51f8b94a492

[oischinger]

I believe it worked at least in one situation.
I got the log
Unable to retrieve data from ViCare server
And the data is still updated.

Would be good to have some more feedback from you before I create a PR.

[rappenze]

Tested with just error handling and it didn't fix the problem for me. It looks like there are two issues on my installation.

1. Missing exception handling
2. Invalid attributes requested for heat pumps

I changed the two things and now it works stable since 3 days. So additionally to add exception handling we should fix the called API's for heat pumps. The following calls needs to be removed for heat pumps (at least for my case): RoomTemperature, MonthSinceLastService, LastServiceDate

So the behaviour with this two changes is that i do not get anymore timeout messages for vicare in the log, and even when there are exceptions logged with "Unable to retrieve data...", the data was still updated and I was able to restart home assistant through the frontend. So it really looks like this fixes all the problems.

I have seen that there is already a PR for adding heating type, so after merging it we can continue with fixing that. Or you can add the fixes in existing PR https://github.com/home-assistant/home-assistant/pull/27296?

[crazyfx1]

There are no specific API calls for heatpumps or different kinds of heating. There is one call to get all data and from the ViCare API and the PyViCare library just returns values from the JSON result.
If the value does not exist in the JSON result, the string "error" is returned.

The component from @oischinger also already covers the case when the room temperature returns "error".

TLDR: I don't see an improvement by removing those 3 attributes. I also have a heat pump (vitocal 200) and the room temperature is working. The service attributes are on "error" aswell but I thought it's because my heating is new and I never had a service so far.

[rappenze]

You're right that there is one API call returning all values, but the PyViCare library reads all values separately directly from the server in separate calls.

For sure one option would be to create a new library which uses the global API call which returns all values to avoid such problems. Then we need a complete rewrite of the library and the home assistant integration.

[crazyfx1]

You are right, I didn’t expect that because it’s really bad. I thought it’s using a cached result internally.

[oischinger]

Yeah, currently we're not playing nicely with the Viessmann servers but I guess that's something we could address as a change to the PyVicare API. It probably wasn't intended to pull so many values constantly.

I would like to have that heat pump support PR merged first and then as a sperate PR the exception fixes.

[rappenze]

Unfortunately even with the exception handling and removing API's not usable for heat pumps the same failure occured again.

I do not see any patterns why it is failing.

2019-11-03 17:05:04 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for vicare which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant.
2019-11-03 17:05:04 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for neeo which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant.
2019-11-03 17:09:16 WARNING (SyncWorker_0) [ViCare] Token expired, renewing
2019-11-03 17:09:16 WARNING (SyncWorker_1) [ViCare] Token expired, renewing
2019-11-03 17:18:25 ERROR (SyncWorker_19) [custom_components.vicare.climate] Unable to retrieve data from vicare server
2019-11-03 17:25:21 WARNING (SyncWorker_3) [DenonAVR] Not able to match sound mode: 'Dolby Audio - Dolby Digital', returning raw sound mode.
2019-11-03 17:50:57 ERROR (SyncWorker_9) [custom_components.vicare.water_heater] Unable to retrieve water data from vicare server
2019-11-03 18:09:16 WARNING (SyncWorker_12) [ViCare] Token expired, renewing
2019-11-03 19:10:13 WARNING (SyncWorker_11) [ViCare] Token expired, renewing
2019-11-03 20:07:09 ERROR (SyncWorker_3) [custom_components.vicare.climate] Unable to retrieve data from vicare server
2019-11-03 20:10:13 WARNING (SyncWorker_6) [ViCare] Token expired, renewing
2019-11-03 20:15:17 ERROR (SyncWorker_19) [custom_components.vicare.climate] Unable to retrieve data from vicare server
2019-11-03 21:11:11 WARNING (SyncWorker_13) [ViCare] Token expired, renewing
2019-11-03 21:11:11 WARNING (SyncWorker_18) [ViCare] Token expired, renewing
2019-11-03 21:47:47 ERROR (SyncWorker_10) [custom_components.vicare.water_heater] Unable to retrieve water data from vicare server
2019-11-03 22:11:11 WARNING (SyncWorker_9) [ViCare] Token expired, renewing
2019-11-03 22:28:26 ERROR (SyncWorker_7) [custom_components.vicare.water_heater] Unable to retrieve water data from vicare server
2019-11-03 23:12:09 WARNING (SyncWorker_10) [ViCare] Token expired, renewing
2019-11-03 23:12:09 WARNING (SyncWorker_18) [ViCare] Token expired, renewing
2019-11-03 23:30:29 ERROR (SyncWorker_7) [DenonAVR] No connection to /goform/AppCommand.xml end point on host 192.168.1.126
2019-11-03 23:30:29 ERROR (SyncWorker_7) [DenonAVR] Update failed.
2019-11-03 23:47:43 ERROR (SyncWorker_12) [custom_components.vicare.water_heater] Unable to retrieve water data from vicare server
2019-11-04 00:05:42 ERROR (SyncWorker_12) [homeassistant.components.netatmo.sensor] No max_temp data found for Aussen
2019-11-04 00:05:42 ERROR (SyncWorker_1) [homeassistant.components.netatmo.sensor] No min_temp data found for Innen
2019-11-04 00:05:42 ERROR (SyncWorker_13) [homeassistant.components.netatmo.sensor] No min_temp data found for Aussen
2019-11-04 00:05:42 ERROR (SyncWorker_16) [homeassistant.components.netatmo.sensor] No max_temp data found for Innen
2019-11-04 00:13:08 WARNING (SyncWorker_19) [ViCare] Token expired, renewing
2019-11-04 00:13:08 WARNING (SyncWorker_10) [ViCare] Token expired, renewing
2019-11-04 01:13:08 WARNING (SyncWorker_1) [ViCare] Token expired, renewing
2019-11-04 02:14:05 WARNING (SyncWorker_17) [ViCare] Token expired, renewing
2019-11-04 03:14:05 WARNING (SyncWorker_18) [ViCare] Token expired, renewing
2019-11-04 03:27:17 ERROR (SyncWorker_14) [custom_components.vicare.water_heater] Unable to retrieve water data from vicare server
2019-11-04 04:15:04 WARNING (SyncWorker_1) [ViCare] Token expired, renewing
2019-11-04 04:15:04 WARNING (SyncWorker_0) [ViCare] Token expired, renewing
2019-11-04 04:19:08 ERROR (SyncWorker_0) [custom_components.vicare.climate] Unable to retrieve data from vicare server
2019-11-04 04:28:17 ERROR (SyncWorker_0) [custom_components.vicare.water_heater] Unable to retrieve water data from vicare server
2019-11-04 05:15:04 WARNING (SyncWorker_0) [ViCare] Token expired, renewing
2019-11-04 05:39:27 ERROR (SyncWorker_8) [custom_components.vicare.water_heater] Unable to retrieve water data from vicare server
2019-11-04 06:16:02 WARNING (SyncWorker_17) [ViCare] Token expired, renewing
2019-11-04 07:16:02 WARNING (SyncWorker_17) [ViCare] Token expired, renewing
2019-11-04 08:17:00 WARNING (SyncWorker_17) [ViCare] Token expired, renewing
2019-11-04 09:17:00 WARNING (SyncWorker_9) [ViCare] Token expired, renewing
2019-11-04 10:17:00 WARNING (SyncWorker_19) [ViCare] Token expired, renewing
2019-11-04 11:17:56 WARNING (SyncWorker_9) [ViCare] Token expired, renewing
2019-11-04 12:17:56 WARNING (SyncWorker_17) [ViCare] Token expired, renewing
2019-11-04 13:15:53 ERROR (SyncWorker_18) [custom_components.vicare.climate] Unable to decode data from vicare server
2019-11-04 13:18:52 WARNING (SyncWorker_8) [ViCare] Token expired, renewing
2019-11-04 13:36:09 ERROR (SyncWorker_0) [custom_components.vicare.water_heater] Unable to decode water data from vicare server
2019-11-04 14:18:53 WARNING (SyncWorker_7) [ViCare] Token expired, renewing
2019-11-04 14:20:04 WARNING (MainThread) [homeassistant.helpers.entity] Update of climate.vicare_heating is taking over 10 seconds
2019-11-04 15:19:50 WARNING (SyncWorker_2) [ViCare] Token expired, renewing
2019-11-04 16:19:51 WARNING (SyncWorker_12) [ViCare] Token expired, renewing
2019-11-04 17:20:48 WARNING (SyncWorker_5) [ViCare] Token expired, renewing
2019-11-04 18:21:43 WARNING (SyncWorker_2) [ViCare] Token expired, renewing
2019-11-04 19:21:44 WARNING (SyncWorker_7) [ViCare] Token expired, renewing
2019-11-04 20:21:44 WARNING (SyncWorker_0) [ViCare] Token expired, renewing
2019-11-04 21:22:39 WARNING (SyncWorker_4) [ViCare] Token expired, renewing
2019-11-04 22:21:46 WARNING (MainThread) [homeassistant.helpers.entity] Update of water_heater.vicare_water is taking over 10 seconds
2019-11-04 22:22:39 WARNING (SyncWorker_5) [ViCare] Token expired, renewing
2019-11-04 23:03:27 WARNING (MainThread) [homeassistant.helpers.entity] Update of climate.vicare_heating is taking over 10 seconds
2019-11-04 23:16:39 WARNING (MainThread) [homeassistant.helpers.entity] Update of water_heater.vicare_water is taking over 10 seconds
2019-11-04 23:16:40 WARNING (MainThread) [homeassistant.helpers.entity] Update of climate.vicare_heating is taking over 10 seconds
2019-11-04 23:17:30 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:17:31 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:18:31 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:18:32 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:19:32 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:19:33 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:20:33 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:20:34 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:21:34 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:21:35 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:22:35 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:22:36 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:23:36 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:23:37 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:24:37 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:24:38 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:25:38 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:25:39 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:26:39 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:26:40 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:27:40 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00
2019-11-04 23:27:41 WARNING (MainThread) [homeassistant.components.climate] Updating vicare climate took longer than the scheduled update interval 0:01:00
2019-11-04 23:28:41 WARNING (MainThread) [homeassistant.components.water_heater] Updating vicare water_heater took longer than the scheduled update interval 0:01:00

[rappenze]

All problems are fixed for me since version 0.103.0. Many thanks to all involved.