Integration data does not update, also integration often hangs when trying an integration reload

Question

Integration data does not update, also integration often hangs when trying an integration reload

Closed this issue 6 months ago · 9 comments

20ashdale commented 6 months ago

Version of the custom_component

Version 0.2.1

Installation method (hacs / manual)

HACS

Installation method of hass (venv, docker, hassio,...)

Configuration

Integration has no changes from a fresh install other than entering user name and password 
(default 45 second update time).

HA core: 2024.2.4

Describe the bug

Integration loads fine and shows expected data, but after a period of time (can be minutes, can be hours) the data then fails to update even though vehicle data has changed and can be viewed on the VW APP.

Forcing an integration reload will update the data values, but setting an automation to regularly reload (say every 24 hours)  will often result in the integration hanging at the initialization stage.

Debug log

No log of fail to update data


Log of initialization failure when trying a manual reload:

Logger: homeassistant.config_entries
Source: config_entries.py:444
First occurred: 9:19:18 AM (1 occurrences)
Last logged: 9:19:18 AM

Error setting up entry Volkswagen We Connect ID for volkswagen_we_connect_id
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 444, in async_setup
    result = await component.async_setup_entry(hass, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/volkswagen_we_connect_id/__init__.py", line 58, in async_setup_entry
    await hass.async_add_executor_job(update, _we_connect)
asyncio.exceptions.CancelledError

Answer 1 · 2024-03-01T14:24:54.000Z

I have version 0.2.1 installed for about a week (on a RPI4, HomeAssistant 2024.2.3, Hass OS 12.0 , and I have not seen the integration stop updating values. But I still see some of the "old" problems reported in other issues:

Groups of 8 "unsupported status: 1018" events occur regularly
Seleveral "deprecated constants" are reported during initialisation: "LENGTH_KILOMETERS", "SPEED_KILOMETERS_PER_HOUR", TIME_DAYS", "TIME_MINUTES", TEMP_CELSIUS", "SOURCE_TYPE_GPS" - although none of these appear the the integration files. Could they deprecated constants come from an underlying VW interface module that is not updated??

Answer 2 · 2024-03-01T14:52:03.000Z

    await hass.async_add_executor_job(update, _we_connect)
asyncio.exceptions.CancelledError

This CancelledError in the debug logs suggests that the weconnect library was interrupted by the integration reload, while waiting for a response from the VW / Cariad cloud API. The cancellation is expected behaviour, although it would have been nicer to catch the exception and log a more friendly error message instead of a stack trace.

I might suggest increasing the 45-second update interval (which is now configurable) to see if it makes a difference. Consider that the VW / Cariad cloud API may at times take longer than 45 seconds to reply to a query. I am using 300 seconds (5 minutes), but if that’s too much, try perhaps 90 seconds.

Answer 3 · 2024-03-01T15:08:06.000Z

Also, try restarting Home Assistant instead of simply reloading the integration. Despite best-intention efforts, I don’t know that ‘reload’ reliably releases all system resources acquired by the integration, including resources acquired by dependencies like the weconnect Python library. I don’t trust ‘reload’ for any of the several custom integrations in my Home Assistant instance, because unlike “visible features,” it is not something that attracts much developer care. Preventing, investigating and fixing “lingering system resources” on integration reload is basically a “thankless job,” on top of being unpaid! 🙂

Answer 4 · 2024-03-01T18:29:47.000Z

I saw similar issues with the default of 45 seconds. I've increased it to 120 seconds and this seems to have improved it. I did notice an issue once when doing some restarts (that will trigger a refresh) and making a bunch of calls (start/stop charging, changing the charging speed, ...).

I think the default of 45 seconds is too low for the rate limit that the API currently enforces.

Answer 5 · 2024-03-01T19:47:03.000Z

Thanks all for the comments.
I have been having issues with lack of data updates for a while and was hoping that 0.2.1 would have resolved these.
I have seen the update issue with 120second update time, but will try with 300 (300 still didn’t work with 0.2.0).

I was hoping not to have to regularly re-start HA to get this working as I use the data to set when to charge the car and to a predetermined SoC level (which works fine with MyBMW and my i3s).

Part of the problem is that there is no way to know the updates have stopped other than keep checking the VW APP, a time stamp entity from WE connect would allow setting up a warning when the data updates stop.

Answer 6 · 2024-03-06T09:12:52.000Z

After changing the poll time to 300 seconds I was still seeing update failures, so I have done a little more digging into the issue.

I have noticed that on every successful poll the following WARNINGs would be generated :

2024-03-05 22:47:13.587 WARNING (SyncWorker_37) [weconnect] /vehicles/WVGZZZE28PE082628/domains/automation/climatisationTimer/timers/1/recurringTimer: Unknown attribute targetTime with value 06:30
2024-03-05 22:47:13.592 WARNING (SyncWorker_37) [weconnect] /vehicles/WVGZZZE28PE082628/domains/automation/climatisationTimer/timers/1/recurringTimer: Unknown attribute repetitionDays with value ['tuesday']
2024-03-05 22:47:13.594 WARNING (SyncWorker_37) [weconnect] /vehicles/WVGZZZE28PE082628/domains/automation/climatisationTimer/timers/2/singleTimer: Unknown attribute targetDateTime with value 2024-03-01T08:50:00Z
2024-03-05 22:47:13.595 WARNING (SyncWorker_37) [weconnect] /vehicles/WVGZZZE28PE082628/domains/automation/chargingProfiles: Unknown attribute nextChargingTimer with value {'id': 0, 'targetSOCreachable': 'invalid'}
2024-03-05 22:47:13.614 WARNING (SyncWorker_37) [weconnect] /vehicles/WVGZZZE28PE082628/domains/chargingProfiles/chargingProfilesStatus: Unknown attribute nextChargingTimer with value {'id': 0, 'targetSOCreachable': 'invalid'}
2024-03-05 22:47:13.618 WARNING (SyncWorker_37) [weconnect] /vehicles/WVGZZZE28PE082628/domains/climatisationTimers/climatisationTimersStatus/timers/1/recurringTimer: Unknown attribute targetTime with value 06:30
2024-03-05 22:47:13.618 WARNING (SyncWorker_37) [weconnect] /vehicles/WVGZZZE28PE082628/domains/climatisationTimers/climatisationTimersStatus/timers/1/recurringTimer: Unknown attribute repetitionDays with value ['tuesday']
2024-03-05 22:47:13.619 WARNING (SyncWorker_37) [weconnect] /vehicles/WVGZZZE28PE082628/domains/climatisationTimers/climatisationTimersStatus/timers/2/singleTimer: Unknown attribute targetDateTime with value 2024-03-01T08:50:00Z
2024-03-05 22:47:13.630 WARNING (MainThread) [homeassistant.components.automation.create_notifications_for_service_errors] Create notifications for 'service' errors (We Connect ID): Already running
2024-03-05 22:47:13.633 WARNING (MainThread) [homeassistant.components.automation.create_notifications_for_service_errors] Create notifications for 'service' errors (We Connect ID): Already running
2024-03-05 22:47:13.636 WARNING (MainThread) [homeassistant.components.automation.create_notifications_for_service_errors] Create notifications for 'service' errors (We Connect ID): Already running
2024-03-05 22:47:13.638 WARNING (MainThread) [homeassistant.components.automation.create_notifications_for_service_errors] Create notifications for 'service' errors (We Connect ID): Already running
2024-03-05 22:47:13.642 WARNING (MainThread) [homeassistant.components.automation.create_notifications_for_service_errors] Create notifications for 'service' errors (We Connect ID): Already running
2024-03-05 22:47:13.643 WARNING (MainThread) [homeassistant.components.automation.create_notifications_for_service_errors] Create notifications for 'service' errors (We Connect ID): Already running
2024-03-05 22:47:13.654 WARNING (MainThread) [homeassistant.components.automation.create_notifications_for_service_errors] Create notifications for 'service' errors (We Connect ID): Already running

So, I set up an automation to increment a counter and send an email every time the above warning was issued thinking that when the counter stopped that would be when any useful error messages would be generated and the email would give a time stamp to look through the logs for.
Sure enough, after 65 updates (at 300 second intervals) the counter stopped.

Looking at the log this is the ERROR generated.
Not sure if this gives anyone a clue as to what is failing ?????

2024-03-05 23:02:18.545 WARNING (SyncWorker_9) [weconnect] /vehicles/WVGZZZE28PE082628: Vehicle data for WVGZZZE28PE082628 is empty, this can happen when there are too many requests
2024-03-05 23:02:23.967 WARNING (SyncWorker_31) [homeassistant.components.smtp.notify] SMTPServerDisconnected sending mail: retrying connection
2024-03-05 23:02:23.972 ERROR (MainThread) [homeassistant.components.automation.create_notifications_for_service_errors] Create notifications for 'service' errors (We Connect ID): Error executing script. Unexpected error for call_service at pos 2: please run connect() first
Traceback (most recent call last):
File "/usr/local/lib/python3.12/smtplib.py", line 398, in getreply
line = self.file.readline(_MAXLINE + 1)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/socket.py", line 707, in readinto
return self._sock.recv_into(b)
^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/ssl.py", line 1253, in recv_into
return self.read(nbytes, buffer)
^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/ssl.py", line 1105, in read
return self._sslobj.read(len, buffer)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Answer 7 · 2024-03-11T14:22:11.000Z

I have the same issue, even the reload of the integration hangs on start... However, full HA restart generally works well...

Answer 8 · 2024-03-18T10:47:26.000Z

Just to tidy up this issue ticket for anyone else who searches for the same problem.

I have updated to version 0.2.2 and this has both eliminated the warnings that were generated every time a car data update occurred (in my case every 300 seconds) but more importantly the updates are not not stopping after a random period.

I have had the version 0.2.2 installed for 5 days now and the updates (300 second intervals) are now OK and I also do not get any error/warning messages in the logs.

Answer 9 · 2024-03-18T22:05:47.000Z

I have updated to version 0.2.2 and [...]

@mitch-dc, on this note, I gather that both versions 0.2.1 and 0.2.2 are still marked “pre-release”:
https://github.com/mitch-dc/volkswagen_we_connect_id/releases

Not sure if it is intentional. While they are pre-release, HACS (custom repositories) won’t offer them to users unless users toggle the “show beta versions” button.