Core: Ecobee Integration breaks after random number of manual restarts of HA

[edif30]

Home Assistant release with the issue: 0.100.x

Last working Home Assistant release (if known): <0.100.x -- I think

Operating environment (Hass.io/Docker/Windows/etc.): Docker

Integration: Ecobee

Description of problem:
Ecobee integration stops working after a manual HA restart and logs a message. The only way to get it working again is to remove the entire ecobee integration from HA... Restart HA... Remove the app from the ecobee developer page. Then add ecobee integration to HA again, add the app to ecobee developer page, and submit in HA.

2019-11-04 10:51:25 ERROR (SyncWorker_7) [pyecobee] Error while refreshing tokens from ecobee: 400: {'error': 'invalid_grant', 'error_description': 'The authorization grant, token or credentials are invalid, expired, revoked, do not match the redirection URI used in the authorization request, or was issued to another client.', 'error_uri': 'https://tools.ietf.org/html/rfc6749#section-5.2'}
2019-11-04 10:51:25 ERROR (MainThread) [homeassistant.components.ecobee] Error updating ecobee tokens

I also get random messages throughout the day such as...

2019-11-01 17:03:33 WARNING (MainThread) [homeassistant.components.ecobee] Ecobee update failed; attempting to refresh expired tokens

This doesn't seem to be an indication after a restart that the integration will break. It's just a random message. There is no rhyme or reason. I manually restart HA for various configuration reasons. Could be the next restart or it could be 10 restarts later. Eventually the ecobee integration fails.

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):
Configuration is done via integrations. No configuration.yaml in HA

Traceback (if applicable): Not Applicable

Additional information:
I do not recall seeing this issue pre 0.100.x

[probot-home-assistant[bot]]

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

[arsaboo]

I experienced the same and discussed this with @marthoc. Here's a summary of what he said:

It is because HASS got shutdown/restarted in the middle of or before the config entry could be updated with a new token. What happens is: we request an update, ecobee tells us our access token expired (it expires every hour) we call to refresh the access token, new access and refresh tokens get updated into the config entry

The resolution right now is to remove the integration and add it. But, he did indicate that the proper way for how that error will need to be handled is, we catch that error on a refresh attempt and then automatically unload the integration and create a notification that it needs to be reauthorized

[edif30]

@arsaboo if the tokens expire every hour what is preventing the component from refreshing the token on its own every 60 min and 1s?

[arsaboo]

The tokens are refreshed automatically. This error only appears when we restart HA during the refresh. I have been using the integration for a while now and restart my HA frequently, but have only encountered this error once.

I agree that it should be handled little more gracefully as it can happen and the dev is aware of it.

[marthoc]

@edif30 - there are two things going on in your issue, one of which is normal:

Ecobee update failed; attempting to refresh expired tokens

That error is not really an error and in a future PR that will get changed to a debug level message; every 3600 seconds (1 hour) the ecobee access token expires, we try to update and fail, and we request a new token. Normal behaviour, and it happens every hour.

However, this error:

2019-11-04 10:51:25 ERROR (SyncWorker_7) [pyecobee] Error while refreshing tokens from ecobee: 400: {'error': 'invalid_grant', 'error_description': 'The authorization grant, token or credentials are invalid, expired, revoked, do not match the redirection URI used in the authorization request, or was issued to another client.', 'error_uri': 'https://tools.ietf.org/html/rfc6749#section-5.2'}
2019-11-04 10:51:25 ERROR (MainThread) [homeassistant.components.ecobee] Error updating ecobee tokens

Indicates that the refresh token is no longer valid, and the only solution is to reauthorize the ecobee integration (i.e. delete it and re add it and go through the process on ecobee.com again).

@arsaboo is correct, this error could happen because we unfortunately happen to restart during the process of updating Home Assistant's config entry with the new token and so on restart we don't have the new token. However, I've also found another "bug" in the underlying python-ecobee-api library related to retrying failed requests that could be causing this issue - the details are in this PR: https://github.com/home-assistant/home-assistant/pull/28296.

Bottom line is that soon, hopefully this issue will be 99% solved.

[edif30]

@marthoc Great thank you. I am happy to test this out locally but looks like the PR has a merge conflict.

[marthoc]

@edif30 the PR has been updated to fix some comments and the merge issue, so if you’d like to test you can! Much appreciated.

[edif30]

@marthoc is a removal and re-add of the integration required after adding in this PR?

EDIT: Just added the PR to my local. Will report any issues. 🤞

[marthoc]

@edif30 I don’t think re-adding the integration should be necessary, but perhaps you can let me know.

[edif30]

PR has been running and no need to do any integration changes. I will keep an eye on things and let you know how this goes. I've already had to restart several times today due to changes in my environment/testing and so far so good.

[edif30]

@marthoc I think it's been long enough to say that I am no longer seeing the random updating tokens error as well as I am no longer losing the integration from the token 1 hour expiration. I am using the PR that you provided. I've restarted and rebuilt multiple times. By now I would have to have removed and re-added the integration. Seems to be working great! I will continue to monitor.

[marthoc]

Thanks for reporting! These changes should get merged into a release soon.

[sstratoti]

Hi @marthoc !

I wanted to check back with you on that PR? I see that you are close!

I've been watching this issue and that PR hoping that it would be approved soon. Very much looking forward to getting this fixed, especially with winter upon us.

Thanks!

[rwarner]

Just a heads up, I integrated your commit into my local Home Assistant integration since it was totally failing out as described here. I'm no longer seeing these issues anymore in the logs. Seems pretty solid on 0.101.3 with those changes in: #28296

[ZetaPhoenix]

I just ran into the logs being full of the expired token messages. @marthoc, do you know when the update was supposed to happen as I still see the messages in 0.103.0.

[marthoc]

@ZetaPhoenix until this PR is merged the “problem” won’t be fixed. Sorry to all that I haven’t had a lot of time to work on this recently. But to be clear, the log messages don’t actually indicate a problem with the component. If all you’re seeing is this error in the logs, but things are still working, then there’s no real problem.

[sstratoti]

Just wanted to clarify, I'm seeing the error with the logs and my ecobee integration hasn't been working since October. Is this an issue with log messages, or with the tokens/integration? If it's just related to log message spam then I may want to do more research.

[john5788]

Just wanted to clarify, I'm seeing the error with the logs and my ecobee integration hasn't been working since October. Is this an issue with log messages, or with the tokens/integration? If it's just related to log message spam then I may want to do more research.

Sounds like a problem with the token refresh. Problem seems to have a fix, just waiting for the PR to merge and a new release of homeassistant. You can merge the changes locally as others have done to fix it for yourself before a new release is made.

[rsnodgrass]

Any update on when the PR will be merged and released?

[rwarner]

Just to add, I had to re-add my ecobee integration the other day as it seemed to have stopped working once again. Haven't seen many problems outside of that one instance, but figured it was worth noting.

Have been holding back upgrading from 103 until this and/or a few Unifi things have been merged. Noticed this wasn't in the latest 104.x releases.

[sstratoti]

I removed and re-added the integration about 2 weeks ago, haven't had any issues since then.

All the sensor names stayed the same when I re-added, so the impact of remove/add was minimal.

[ljmerza]

I do get this error after restarting a few times. I work on custom components so have to restart HA multiple times when working on them and it destroys my ecbobee integration every time. Please fix.

[recklessnl]

I also just got this error, hope the PR will be added soon to fix it.

[stratotally]

So after removing and re-adding the integration it works fine for me. Even with restarts, however - I’m restarting the entire docker container. I’m curious - are you all calling the service restart?

[FuzzyMistborn]

So after removing and re-adding the integration it works fine for me. Even with restarts, however - I’m restarting the entire docker container. I’m curious - are you all calling the service restart?

Shouldn't make a difference for the integration given what the bug is

[MarkHofmann11]

This problem seems to be happening more often and not just after restarting HA. I have added the Ecobee integration 3 times in the past 2 weeks due to the token issue. Two times it broke after a HA restart and one time is broke while running normally. Almost like a response isn't being acknowledged on one side or the other. Delete and re-adding the integration is the only fix that I am aware of once the token issue surfaces.

[zolstarym]

Same problem for me. Here are some logs I get, if it helps
2020-02-13 13:22:58 WARNING (MainThread) [homeassistant.components.ecobee] Ecobee update failed; attempting to refresh expired tokens
2020-02-13 14:23:56 WARNING (MainThread) [homeassistant.components.ecobee] Ecobee update failed; attempting to refresh expired tokens
2020-02-13 15:00:39 WARNING (MainThread) [homeassistant.helpers.entity] Update of climate.thermo is taking over 10 seconds
2020-02-13 15:00:51 ERROR (MainThread) [homeassistant.helpers.entity] Update for climate.thermo fails
Traceback (most recent call last):
File "/home/fidget/home-assistant/lib/python3.8/site-packages/homeassistant/helpers/entity.py", line 279, in async_update_ha_state
await self.async_device_update()
File "/home/fidget/home-assistant/lib/python3.8/site-packages/homeassistant/helpers/entity.py", line 459, in async_device_update
await self.async_update()
File "/home/fidget/home-assistant/lib/python3.8/site-packages/homeassistant/components/ecobee/climate.py", line 289, in async_update
await self.data.update()
File "/home/fidget/home-assistant/lib/python3.8/site-packages/homeassistant/components/ecobee/__init__.py", line 96, in update
await self._hass.async_add_executor_job(self.ecobee.update)
File "/usr/lib/python3.8/concurrent/futures/thread.py", line 57, in run
result = self.fn(self.args, *self.kwargs)
File "/home/fidget/home-assistant/lib/python3.8/site-packages/pyecobee/__init__.py", line 199, in update
self.get_thermostats()
File "/home/fidget/home-assistant/lib/python3.8/site-packages/pyecobee/__init__.py", line 173, in get_thermostats
logger.error(f"Error connecting to ecobee while attempting to get thermostat data: "
File "/home/fidget/home-assistant/lib/python3.8/site-packages/requests/models.py", line 897, in json
return complexjson.loads(self.text, **kwargs)
File "/usr/lib/python3.8/json/__init__.py", line 357, in loads
return _default_decoder.decode(s)
File "/usr/lib/python3.8/json/decoder.py", line 337, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
File "/usr/lib/python3.8/json/decoder.py", line 355, in raw_decode
raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2020-02-13 15:24:53 WARNING (MainThread) [homeassistant.components.ecobee] Ecobee update failed; attempting to refresh expired tokens
2020-02-13 16:25:48 WARNING (MainThread) [homeassistant.components.ecobee] Ecobee update failed; attempting to refresh expired tokens

[rrubin0]

this just happened to me too - was troubleshooting/upgrading something else and, after a Linux update/reboot, I ran into this.

[mcondren]

Just happened to me as well. 3 days into using ecobee integration.
2020-02-16 16:44:24 ERROR (SyncWorker_38) [pyecobee] Error while refreshing tokens from ecobee: 400: {'error': 'invalid_grant', 'error_description': 'The authorization grant, token or credentials are invalid, expired, revoked, do not match the redirection URI used in the authorization request, or was issued to another client.', 'error_uri': 'https://tools.ietf.org/html/rfc6749#section-5.2'} 2020-02-16 16:44:25 ERROR (MainThread) [homeassistant.components.ecobee] Error updating ecobee tokens

[klenya]

The same issue. I have to re-register Ecobee every few days. Frustrating...
The PR with fix #28296 was just canceled due to inactivity

[edif30]

Yea I saw. I find it ridiculous that it was closed. I've seen PRs and Issues open for months. 1 month and this one is closed??? Hrmmm

[ljmerza]

I have this issue every few days as well.

One of the many reasons why I don't contribute to HA directly anymore. I
just maintain my custom components/cards. I've seen stuff like this happen
and other PRs get merged in so quickly that don't even have tests. Makes no
sense.

On Tue, Feb 18, 2020, 11:09 PM edif30 [e-mail] wrote:

Yea I saw. I find it ridiculous that it was closed. I've seen PRs and
Issues open for months. 1 month and this one is closed??? Hrmmm

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/home-assistant/home-assistant/issues/28531?email_source=notifications&email_token=AA7FQBMMUFMUD7ILFGFMFWTRDSWJPA5CNFSM4JIV45MKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEMGI5SQ#issuecomment-588025546,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AA7FQBM7CNTEC4Q73AN6KELRDSWJPANCNFSM4JIV45MA
.

[marthoc]

Again all, sorry for the delay. This isn't on the HASS dev team, it's on me. I haven't had the time needed to push PR #28296 over the line. But, I think I can push a much narrower PR to fix the bug itself in the meantime. I've got the code written and will test tonight before opening a PR. Hopefully the devs can merge it while the refactor moves forward in parallel.

[rwarner]

Thanks for the update @marthoc much appreciated. Looking forward to seeing this resolved.

[marthoc]

Just for greater transparency regarding the issue raised in this thread, I'll explain why the ecobee integration keeps breaking for all of you.

Before config entries, ecobee authentication tokens were stored in a file called ecobee.conf that was stored in the Home Assistant config directory. On HA startup, the ecobee component would read the tokens from this file and use them to authenticate. The python library took care of retrieving the tokens from ecobee, storing them in the file, and (importantly) refreshing them and updating ecobee.conf with the new tokens if the old tokens became stale. If HA was shut down, on the next startup, ecobee.conf would contain the most recent tokens as the python library had been updating that file each time the tokens were refreshed.

Moving ecobee to using config entries meant that the tokens would now be stored in the entry itself, rather than in ecobee.conf. From a logic perspective, this meant that HA itself would now need to be in charge of refreshing the tokens and updating the config entry with any refreshed tokens. Easy enough.

However, the python library still contained logic as though it was responsible for refreshing tokens. On a failed API access attempt (because of connectivity issues or otherwise), the library would (without being prompted by the logic in HA) retry the failed call but also (and the origin of the bug) attempt to refresh the authentication tokens. If this succeeded, HA would go on using the correct tokens for the time being, but, when those tokens became stale (as they do every 3600 seconds/1 hour) the attempt by HA to refresh them would fail as the tokens in the config entry had been invalidated by the issuing of new tokens to the request made by the python library, and HA was presenting those stale tokens on the refresh request.

This explains why this issue is not cropping up for everyone - if you have no connectivity issues to ecobee (i.e. calls to the API don't fail), then the library would never independently refresh your tokens and this error would not happen.

I had previously refactored the underlying python library to fix this issue. The broader ecobee refactor was undertaken not only to clean up the component, but also to allow the component to refresh failed calls. For the time being, I think that bumping the library to the newest version (and fixing a few minor aspects of the HA refresh logic) should at least stop the error that is cropping up in this issue.

[theoretick]

@marthoc thank you for your effort and the great explanation! Much appreciated!

[recklessnl]

@marthoc Please keep us posted on the new PR! Would be a relief to not having to deal with the ecobee issue again. Thanks for staying on top of it.

[marthoc]

PR has been submitted: #32008. I was not experiencing this bug, but the integration appears to continue to work correctly with the changes to fix the bug in place.

[marthoc]

I don’t like to keep posting in closed issues but can anyone confirm that upgrading to 106 has solved this problem?

[rwarner]

Thanks again for getting this integrated. I have not yet upgraded to 106, but now that this, as well as a few Unifi bugs, have been integrated I will certainly do so soon and will report back.

[pashdown]

It still happens on my 106.

[yang3535]

I just had it happen on my 106.1

[marthoc]

Alright we should reopen this issue. Can someone turn debug logging on for both the integration and pyecobee and then post the logs when the error happens? Seeing the whole transaction in debug logging should help me pin down where the keys are getting out of sync.

[FidgetyRat]

I can confirm that this happens on my system as well on 0.106.2. I'm always afraid to restart out of the hassle of re-integrating.

[marthoc]

@pashdown @yang3535 @FidgetyRat Since you have all confirmed that this is still happening for you, can you please help me debug? If you could turn on debug logging for the integration and for pyecobee, then send me your .log after the error happens, it would help me greatly to figure out what happens to cause the tokens to become invalid.

[pashdown]

Welp, I've turned on the logging and killed and restarted HA several times, which used to always cause the problem. It isn't happening anymore for me. If it does, I'll try and capture some logs for you.

[rrubin0]

I’ve only seen this after numerous restarts on any version. I’m on 106.6
and do still see errors in log occasionally but only experienced a
de-integration once ever.

On Fri, Mar 13, 2020 at 3:31 PM pashdown [e-mail] wrote:

Welp, I've turned on the logging and killed and restarted HA several
times, which used to always cause the problem. It isn't happening anymore
for me. If it does, I'll try and capture some logs for you.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/home-assistant/core/issues/28531#issuecomment-598957282,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AFCPURE6OLORTGSN3GGOFCLRHKX3LANCNFSM4JIV45MA
.

[FidgetyRat]

I got it today when restarting to add another integration. Full reintegration required. I’ll try to get some logs from a debug setup as I’m rebooting it a lot for testing of my own work. I’ll add ecobee to that system.

[ljmerza]

I develop custom integrations and have to restart HA frequently and this happens to me A LOT. Something I've been dealing with for months and I don't see why this is not acknowledged and fixed by now.

  File "/usr/local/lib/python3.7/site-packages/pyecobee/__init__.py", line 522, in _request
    "ecobee tokens invalid; re-authentication required"
pyecobee.errors.InvalidTokenError: ecobee tokens invalid; re-authentication required

[marthoc]

@ljmerza Am I not here acknowledging it and trying to fix it? If you develop your own custom components you will know that tracking down bugs can be difficult if not impossible without being able to recreate the problem or get logs from users who are experiencing the problem. Since you are seeing the exact problem (the InvalidTokenError is raised), and you seem to know your way around HA, I would appreciate it very much if you could enable debug logging of the integration and pyecobee and send me the .log file the next time this happens.

[marthoc]

@balloob Could you please reopen this issue for visibility of the problem? Thanks!

[balloob]

@ijmerza your attitude is misplaced. Feel free to contribute to core instead of building custom stuff.

[ljmerza]

@balloob yet you closed this issue without even being involved and without it even being fixed. Your attitude is misplaced to just close this issue when you had no business to.

@marthoc you already have two people provide logs. My logs are no different than theirs.

[marthoc]

@ljmerza This issue was closed because I opened a PR that I thought addressed the issue. It was closed automatically when that PR was merged. You need to check your attitude.

Also, what everyone is posting is not logs. That’s the error itself, which tells me nothing about what caused the error. The debug logs will have a lot of information about the specific call that provoked the error and the calls leading up to it. I’ve actually added a lot of debug output to pyecobee since I started contributing to it, which is precisely so that when an issue arises, I have all the information I need to diagnose.

[balloob]

Going to lock this issue.

People that have this issue, feel free to open a new issue if you can reproduce it after running the Home Assistant version with the bugfix.