"Daikin Skyport token expired" randomly causing communication loss with thermostat

[flashadams]

Seemingly randomly I noticed my widgest for thermostat were empty. Went into the logs and found "Daikin Skyport token expired" being shown. If I "reload" the integration it resolves it. Below is an excerpt from a message. I have enabled debug logging for any additional messages that show.

Logger: homeassistant.config_entries Source: config_entries.py:402 First occurred: December 19, 2023 at 11:05:21 AM (2 occurrences) Last logged: December 19, 2023 at 3:00:43 PM

Error setting up entry Daikin for daikinskyport Traceback (most recent call last): File "/config/custom_components/daikinskyport/init.py", line 161, in _async_update_data current = await self.hass.async_add_executor_job(self.daikinskyport.update) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/daikinskyport/daikinskyport.py", line 263, in update result = self.get_thermostats() ^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/daikinskyport/daikinskyport.py", line 173, in get_thermostats raise ExpiredTokenError ("Daikin Skyport token expired") custom_components.daikinskyport.daikinskyport.ExpiredTokenError: Daikin Skyport token expired

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/config_entries.py", line 402, in async_setup result = await component.async_setup_entry(hass, self) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/daikinskyport/init.py", line 79, in async_setup_entry await coordinator._async_update_data() File "/config/custom_components/daikinskyport/init.py", line 165, in _async_update_data await self.hass.async_add_executor_job(self.daikinskyport.update) File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/daikinskyport/daikinskyport.py", line 263, in update result = self.get_thermostats() ^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/daikinskyport/daikinskyport.py", line 173, in get_thermostats raise ExpiredTokenError ("Daikin Skyport token expired") custom_components.daikinskyport.daikinskyport.ExpiredTokenError: Daikin Skyport token expired

[apetrycki]

This doesn't look like the debug output. You should see output from:

logger.debug("Error connecting to Daikin Skyport while attempting to get "
                        "thermostat data. Status code: %s Message: %s", request.status_code, request.text)

Try adding this to your configuration.yaml:

  logs:
    custom_components.daikinskyport: debug
    daikinskyport: debug
    daikinskyport.daikin_set_thermostat_schedule: debug
    climate.daikinskyport: debug

[apetrycki]

I'm assuming this has been fixed since it's been 3 weeks with no response

[flashadams]

I was on vacation and waiting for it to happen again. I tried to use the logs in the config you listed earlier. When checking the config in dev tools I do get this warning. "Configuration warnings Integration error: logs - Integration 'logs' not found."

[ufodone]

@apetrycki I am having the same issue. It's fairly infrequent but did happen again today - I suspect potentially related to the maintenance Daikin was doing on their servers this morning.

I had a bit of a look at the code and I have a theory as to what might be happening. When a token expires, the exception handler in _async_update_data calls async_refresh() which refreshes the tokens and then calls async_update_entry which, I believe, effectively reconfigures the integration and is triggering async_setup_entry() to run. That function then creates a new coordinator instance (DaikinSkyportData) and does an update on it - which should work because it will have the new tokens. However, back in the call stack of the original _async_update_data() call, the async_refresh() call is complete and it then schedules another update job to run. But it also still has the old tokens because it is an old/stale instance of DaikinSkyportData (the instance used by the integration is now the new one created in the freshly called async_setup_entry() function. So when this update does eventually run, it will re-trigger another expired token exception but from within the exception handler of _async_update_data.

At this point, the exception is uncaught and I'm guessing the result of that is the integration become unresponsive.

My guess is that after the async_refresh() call in _update_update_data() that it should just exit the function because the async_update_entry() call will already be re-setting up the integration and scheduling new update calls.

I only had custom_components.daikinskyport logging turned on to debug when this happened but I've included it below in case its helpful.

2024-01-09 15:45:23.183 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 15:45:23.184 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: cloudy
2024-01-09 15:45:53.204 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 15:45:53.206 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: cloudy
2024-01-09 15:46:02.365 INFO (MainThread) [custom_components.emporia_vue] Integrating minute data into day sensors
2024-01-09 15:46:23.148 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 15:46:23.149 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: cloudy
2024-01-09 15:46:53.201 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 15:46:53.202 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: cloudy
2024-01-09 15:47:02.364 INFO (MainThread) [custom_components.emporia_vue] Integrating minute data into day sensors
2024-01-09 15:47:23.239 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 15:47:23.240 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: cloudy
2024-01-09 15:47:53.195 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 15:47:53.197 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: cloudy
2024-01-09 15:48:02.364 INFO (MainThread) [custom_components.emporia_vue] Updating day sensors
2024-01-09 15:48:23.225 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport tokens expired
2024-01-09 15:48:23.225 DEBUG (MainThread) [custom_components.daikinskyport] Refreshing Daikin Skyport tokens and updating config entry
2024-01-09 15:48:23.458 DEBUG (MainThread) [custom_components.daikinskyport] Update listener: <homeassistant.config_entries.ConfigEntry object at 0x7f67bbc70400>
2024-01-09 15:48:23.458 DEBUG (MainThread) [custom_components.daikinskyport] Unload Entry: <homeassistant.config_entries.ConfigEntry object at 0x7f67bbc70400>
2024-01-09 15:48:23.468 WARNING (MainThread) [homeassistant.components.template.trigger] Error evaluating 'template' trigger for 'Furnace Override': TypeError: unsupported operand type(s) for -: 'NoneType' and 'NoneType'
2024-01-09 15:48:23.471 WARNING (MainThread) [homeassistant.components.template.trigger] Error evaluating 'template' trigger for 'Furnace Override': TypeError: unsupported operand type(s) for -: 'NoneType' and 'NoneType'
2024-01-09 15:48:23.474 INFO (MainThread) [custom_components.daikinskyport] Daikin Skyport Starting
2024-01-09 15:48:23.474 DEBUG (MainThread) [custom_components.daikinskyport] Using email: done@noru.ca
2024-01-09 15:48:26.593 ERROR (MainThread) [homeassistant.helpers.entity] Update for weather.daikin fails
Traceback (most recent call last):
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 189, in get_thermostat_info
    request.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: https://api.daikinskyport.com/deviceData/3c39610a-2c6e-11ec-82e8-c3e2fb1164ab

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/config/custom_components/daikinskyport/__init__.py", line 161, in _async_update_data
    current = await self.hass.async_add_executor_job(self.daikinskyport.update)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 263, in update
    result = self.get_thermostats()
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 156, in get_thermostats
    thermostat_info = self.get_thermostat_info(thermostat['id'])
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 199, in get_thermostat_info
    raise ExpiredTokenError ("Daikin Skyport token expired")
custom_components.daikinskyport.daikinskyport.ExpiredTokenError: Daikin Skyport token expired

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 698, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 959, in async_device_update
    await self.async_update()
  File "/config/custom_components/daikinskyport/weather.py", line 132, in async_update
    await self.data._async_update_data()
  File "/config/custom_components/daikinskyport/__init__.py", line 165, in _async_update_data
    await self.hass.async_add_executor_job(self.daikinskyport.update)
  File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 263, in update
    result = self.get_thermostats()
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 173, in get_thermostats
    raise ExpiredTokenError ("Daikin Skyport token expired")
custom_components.daikinskyport.daikinskyport.ExpiredTokenError: Daikin Skyport token expired
2024-01-09 15:48:26.614 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport tokens expired
2024-01-09 15:48:26.614 DEBUG (MainThread) [custom_components.daikinskyport] Refreshing Daikin Skyport tokens and updating config entry
2024-01-09 15:48:29.994 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Daikin for daikinskyport
Traceback (most recent call last):
  File "/config/custom_components/daikinskyport/__init__.py", line 161, in _async_update_data
    current = await self.hass.async_add_executor_job(self.daikinskyport.update)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 263, in update
    result = self.get_thermostats()
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 173, in get_thermostats
    raise ExpiredTokenError ("Daikin Skyport token expired")
custom_components.daikinskyport.daikinskyport.ExpiredTokenError: Daikin Skyport token expired

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 402, in async_setup
    result = await component.async_setup_entry(hass, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/__init__.py", line 79, in async_setup_entry
    await coordinator._async_update_data()
  File "/config/custom_components/daikinskyport/__init__.py", line 165, in _async_update_data
    await self.hass.async_add_executor_job(self.daikinskyport.update)
  File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 263, in update
    result = self.get_thermostats()
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 173, in get_thermostats
    raise ExpiredTokenError ("Daikin Skyport token expired")
custom_components.daikinskyport.daikinskyport.ExpiredTokenError: Daikin Skyport token expired

[mikahjc]

I'm also seeing this, but I had to wait for it to happen again after enabling the logging. Though I don't know that my logs are terribly helpful. Mostly weather updates, until suddenly daikinskyport starts reporting "Device is offline." Since it happened to me today as well, I wouldn't be surprised if it is related to Daikin maintenance windows and the integration just doesn't recover until HA is restarted.

2024-01-09 10:36:53.630 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 10:36:53.630 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: snow
2024-01-09 10:37:23.531 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 10:37:23.532 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: snow
2024-01-09 10:37:53.892 WARNING (SyncWorker_20) [daikinskyport] Device is offline.
2024-01-09 10:37:53.897 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 10:37:53.898 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: snow
2024-01-09 10:38:19.788 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: snow
2024-01-09 10:38:23.384 WARNING (SyncWorker_16) [daikinskyport] Device is offline.

<snip 4 repeated instances>

2024-01-09 10:40:23.396 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 10:40:23.397 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: snow
2024-01-09 10:40:57.799 WARNING (SyncWorker_7) [urllib3.connectionpool] Retrying (Retry(total=7, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7fdb92740ed0>: Failed to establish a new connection: [Errno -3] Try again')': /devices
2024-01-09 10:40:59.793 WARNING (MainThread) [homeassistant.helpers.entity] Update of weather.daikin is taking over 10 seconds
2024-01-09 10:41:01.887 WARNING (SyncWorker_7) [daikinskyport] Device is offline.
2024-01-09 10:41:01.889 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 10:41:01.890 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: snow

<snip 3 more instances>

2024-01-09 10:42:40.153 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [140580832610240] Initialized trigger
2024-01-09 10:42:40.334 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [140580832610240] Initialized trigger
2024-01-09 10:42:53.446 WARNING (SyncWorker_20) [daikinskyport] Device is offline.
2024-01-09 10:42:53.451 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 10:42:53.452 DEBUG (MainThread) [custom_components.daikinskyport] Weather icon for weatherTodayIcon: snow

<snip 28 more instances>

2024-01-09 10:57:23.595 WARNING (SyncWorker_20) [daikinskyport] Device is offline.
2024-01-09 10:57:23.600 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 10:57:53.019 DEBUG (SyncWorker_16) [daikinskyport] Error connecting to Daikin Skyport while attempting to get thermostat data. Status code: 401 Message: {"message":"Unauthorized"}
2024-01-09 10:57:53.020 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport tokens expired
2024-01-09 10:57:53.020 DEBUG (MainThread) [custom_components.daikinskyport] Refreshing Daikin Skyport tokens and updating config entry
2024-01-09 10:57:53.441 DEBUG (MainThread) [custom_components.daikinskyport] Update listener: <homeassistant.config_entries.ConfigEntry object at 0x7fdbdeb5c4f0>
2024-01-09 10:57:53.441 DEBUG (MainThread) [custom_components.daikinskyport] Unload Entry: <homeassistant.config_entries.ConfigEntry object at 0x7fdbdeb5c4f0>
2024-01-09 10:57:53.460 INFO (MainThread) [custom_components.daikinskyport] Daikin Skyport Starting
2024-01-09 10:57:53.460 DEBUG (MainThread) [custom_components.daikinskyport] Using email: mikahjc@email.com
2024-01-09 10:57:57.053 WARNING (SyncWorker_15) [daikinskyport] Device is offline.
2024-01-09 10:57:57.057 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully
2024-01-09 10:57:57.058 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.daikinskyport
2024-01-09 10:57:57.058 INFO (MainThread) [homeassistant.components.weather] Setting up weather.daikinskyport
2024-01-09 10:57:57.058 INFO (MainThread) [homeassistant.components.climate] Setting up climate.daikinskyport
2024-01-09 10:57:57.062 WARNING (SyncWorker_2) [daikinskyport] Device is offline.
2024-01-09 10:57:57.068 DEBUG (MainThread) [custom_components.daikinskyport] Daikin Skyport data updated successfully

[ufodone]

FWIW, I tried validating my theory by simulating the situation though some code changes but haven't been successful yet. I'll keep trying. I did notice that the initial trigger exception was a 500 (internal server error) so I'm wondering whether there's a scenario around when that happens which prevents a successful reconnection.

[apetrycki]

@flashadams you need to put the logs: under logger:

logger:
  default: error
  logs:
    custom_components.daikinskyport: debug
    daikinskyport: debug
    climate.daikinskyport: debug

If everyone could add these lines to their config, there would be a lot more debug info. It will show the entire message that comes back on the error. I've been seeing this error as well from time to time, but I have an automation that reloads the integration on failure, so I haven't really noticed it.

[christoftaylor]

It has happened to me three times in the last week or so. Of note, the timestamp on the most recent occurrence aligns with the one in @ufodone's logs, which gives me the impression the hiccup is on Daikin's side and the problem is how the plugin recovers from receiving this '500 server error'.

2024-01-09 15:48:06.617 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Daikin for daikinskyport
  File "/config/custom_components/daikinskyport/daikinskyport.py", line 189, in get_thermostat_info
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: https://api.daikinskyport.com/deviceData/517e930a-725a-11ec-8b44-fbec9e62bac8

@apetrycki, how are you doing this auto reload on failure? Can that just be part of the plugin?

[BeebleZap]

@apetrycki , I would also like to know how to reload the config when there is a failure. At least, until this issue is fixed.

[apetrycki]

Just trigger on the state being unavailable and run the reload_config_entry service

[christoftaylor]

That seems easy enough. Thank you.

My integration restarts every hour. Looks like this in the logs:

2024-01-11 09:20:02.894 INFO (MainThread) [custom_components.daikinskyport] Daikin Skyport Starting
2024-01-11 09:20:07.314 INFO (MainThread) [homeassistant.components.sensor] Setting up daikinskyport.sensor
2024-01-11 09:20:07.314 INFO (MainThread) [homeassistant.components.weather] Setting up daikinskyport.weather
2024-01-11 09:20:07.314 INFO (MainThread) [homeassistant.components.climate] Setting up daikinskyport.climate
2024-01-11 10:20:11.014 INFO (MainThread) [custom_components.daikinskyport] Daikin Skyport Starting
2024-01-11 10:20:15.359 INFO (MainThread) [homeassistant.components.sensor] Setting up daikinskyport.sensor
2024-01-11 10:20:15.360 INFO (MainThread) [homeassistant.components.weather] Setting up daikinskyport.weather
2024-01-11 10:20:15.360 INFO (MainThread) [homeassistant.components.climate] Setting up daikinskyport.climate
2024-01-11 11:20:19.079 INFO (MainThread) [custom_components.daikinskyport] Daikin Skyport Starting
2024-01-11 11:20:23.468 INFO (MainThread) [homeassistant.components.sensor] Setting up daikinskyport.sensor
2024-01-11 11:20:23.468 INFO (MainThread) [homeassistant.components.weather] Setting up daikinskyport.weather
2024-01-11 11:20:23.469 INFO (MainThread) [homeassistant.components.climate] Setting up daikinskyport.climate

This causes the service to momentarily go 'unavailable' every hour. That interrupts the history logs ability to tell me how long the system has been in whatever state. So, depending on how I trigger that automation, it would fire every hour.

[apetrycki]

I use Node Red and have it set to restart if unavailable for over 1min. I haven't used the automation stuff in HA in several years, so not sure if there is an equivalent.

[ufodone]

I use something like this:

trigger:
  - platform: state
    entity_id:
      - climate.daikin
    to: unavailable
    for:
      hours: 0
      minutes: 1
      seconds: 0

which looks like the equivalent of what you're doing in Node Red.

[ufodone]

It turns out my theory was mostly correct but the way I was trying to simulate the error was wrong. In any case, I've been able to simulate the problem and have submitted a PR with a fix to at least allow it to recover on its own.

[apetrycki]

I updated the async listener to not reload the integration. It no longer should go unavailable after a token refresh. The only downside is, if you change the name of your thermostat in the configuration, you'll have to reload the integration manually instead of it doing it automatically. Seemed like an easy fix with a miniscule downside.