Not authenticated error. #86

vlebourl · 2020-06-24T12:09:04Z

Describe the bug
For some unknown reason, we get kicked out of the api, causing the following error message:
{"errorCode":"RESOURCE_ACCESS_DENIED","error":"Not authenticated"}

To Reproduce
Don't know yet...

The text was updated successfully, but these errors were encountered:

mariwing · 2020-07-01T19:08:10Z

This happens a lot to me, sometimes already after a restart, sometimes after one or more day. This is the complete error message I get flooded (litterally 100 of these entries):

2020-07-01 21:05:09 ERROR (MainThread) [homeassistant.helpers.entity] Update for cover.markise_hoyre fails
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 272, in async_update_ha_state
await self.async_device_update()
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 466, in async_device_update
self.update # type: ignore
File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
result = self.fn(*self.args, **self.kwargs)
File "/config/custom_components/tahoma/cover.py", line 92, in update
self.controller.get_states([self.tahoma_device])
File "/config/custom_components/tahoma/tahoma_api.py", line 513, in get_states
result = self.send_request(requests.get, BASE_URL + path, headers=header)
File "/config/custom_components/tahoma/tahoma_api.py", line 120, in send_request
self.send_request(method, url, headers, data, timeout, retries - 1)
File "/config/custom_components/tahoma/tahoma_api.py", line 120, in send_request
self.send_request(method, url, headers, data, timeout, retries - 1)
File "/config/custom_components/tahoma/tahoma_api.py", line 120, in send_request
self.send_request(method, url, headers, data, timeout, retries - 1)
File "/config/custom_components/tahoma/tahoma_api.py", line 117, in send_request
+ request.text
Exception: Maximum number of consecutive retries reached. Error is:
{"errorCode":"RESOURCE_ACCESS_DENIED","error":"Not authenticated"}

vlebourl · 2020-07-01T19:30:57Z

Thanks for the report. Unfortunately I haven't found a way to reproduce it consistently to debug it... Still looking!

vlebourl · 2020-07-01T20:41:45Z

Can you try branch fix-86? Download this zip and replace the folder tahoma installed through HACS by the one in the zip, restart HA and let me know if it helps.

mark as logged out when receiving {"errorCode":"RESOURCE_ACCESS_DENIED","error":"Not authenticated"}

Related Github issues: #86

vlebourl · 2020-07-02T08:54:39Z

Can you try branch fix-86? Download this zip and replace the folder tahoma installed through HACS by the one in the zip, restart HA and let me know if it helps.

If you haven't done it yet, it should work now!

vlebourl · 2020-07-02T11:55:39Z

fixed in 1.5alpha2 by #95

Related Github issues: #86

vlebourl · 2020-07-02T13:26:47Z

We manage to get authenticated, but we still don't know why we loose authentication at some point...

rabesocke · 2020-07-02T13:27:02Z

Just moved from the discussion in issue #93

can you edit the file tahoma_api.py and add the following line 157, just before the if not self.login()
_LOGGER.debug("not authenticated: login again.")
Restart HA a try again with debug log setup for the component (see here)

I will test this later and give you feedback.

rabesocke · 2020-07-02T14:46:31Z

I get no log entry when I move the cover (even when I change it to warning or error).

vlebourl · 2020-07-02T14:48:47Z

The log is only supposed to warn if you're not authenticated... Do you still have the delay?

rabesocke · 2020-07-02T14:50:32Z

Yes, the delay is still there (not always, but most of the time)

vlebourl · 2020-07-02T14:51:08Z

I just found something, can you check whether this might change something?
In the Tahoma web interface, go to your account:

Select "My Somfy Account" at the bottom, and check whether you gave access to your box. I have no idea whether this is actually important or not, but we never know.

Related Github issues: #86

vlebourl · 2020-07-02T14:57:15Z

I've added another debug message in branch https://github.com/iMicknl/ha-tahoma/archive/not-authenticated-error.zip
can you try it? Don't forget to activate debug logging.

rabesocke · 2020-07-02T15:12:39Z

I just found something, can you check whether this might change something?
In the Tahoma web interface, go to your account:

Select "My Somfy Account" at the bottom, and check whether you gave access to your box. I have no idea whether this is actually important or not, but we never know.

No change with this configuration

vlebourl · 2020-07-02T15:17:22Z

damn it :(
I just found this in the hidden doc regarding actions sent to the api: "Per-session rate-limit : 50 calls per 24 HOURS period for all operations of the same category (exec)"
Maybe this is the issue?
Not sure though cause I also got this in the tahoma web interface:

rabesocke · 2020-07-02T15:19:24Z

I've added another debug message in branch https://github.com/iMicknl/ha-tahoma/archive/not-authenticated-error.zip
can you try it? Don't forget to activate debug logging.

Still no log entry and still the same situation.

Related Github issues: #86

vlebourl · 2020-07-02T15:26:22Z

I've modified the log. You should get debug messages even if you're still authenticated.
This will flood your logs, but might give us info...
Don't hesitate to revert!

rabesocke · 2020-07-02T15:39:17Z

This is an example of the entries:

2020-07-02 17:37:42 DEBUG (SyncWorker_6) [custom_components.tahoma.tahoma_device] should_wait(WZ West) authenticated: True
2020-07-02 17:37:42 DEBUG (SyncWorker_6) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:42 DEBUG (SyncWorker_6) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:42 DEBUG (SyncWorker_6) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:42 DEBUG (SyncWorker_6) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:42 DEBUG (SyncWorker_6) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:42 DEBUG (SyncWorker_6) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:46 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_device] should_wait(Kind (Süd) Süd) authenticated: True
2020-07-02 17:37:46 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:46 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:46 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:46 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:46 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:46 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:47 DEBUG (SyncWorker_15) [custom_components.tahoma.tahoma_device] should_wait(Büro West) authenticated: True
2020-07-02 17:37:47 DEBUG (SyncWorker_15) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:47 DEBUG (SyncWorker_15) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:47 DEBUG (SyncWorker_15) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:47 DEBUG (SyncWorker_15) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:47 DEBUG (SyncWorker_15) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:47 DEBUG (SyncWorker_15) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:48 DEBUG (SyncWorker_17) [custom_components.tahoma.tahoma_device] should_wait(Bad) authenticated: True
2020-07-02 17:37:48 DEBUG (SyncWorker_17) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:48 DEBUG (SyncWorker_17) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:48 DEBUG (SyncWorker_17) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:48 DEBUG (SyncWorker_17) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:48 DEBUG (SyncWorker_17) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:48 DEBUG (SyncWorker_17) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:48 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_device] should_wait(WZ Süd-West A/M) authenticated: True
2020-07-02 17:37:48 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:49 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:49 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:49 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 17:37:49 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 17:37:49 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] request success
2020-07-02 17:37:49 DEBUG (SyncWorker_10) [custom_components.tahoma.tahoma_device] should_wait(WZ Süd) authenticated: True
2020-07-02 17:37:49 DEBUG (SyncWorker_10) [custom_components.tahoma.tahoma_api] sending request

vlebourl · 2020-07-02T16:13:02Z

These are scheduled update calls. I don't see any delay there. Can you do an action, look for apply_action in the log, and post messages around it?

rabesocke · 2020-07-02T16:24:13Z

Here is the apply_action snippet. The interesting thing is, that I click the button at 18:21:01 in the HA iOS App and in the log it says 18:21:09

2020-07-02 18:21:08 DEBUG (SyncWorker_8) [custom_components.tahoma.tahoma_device] should_wait(WZ West) authenticated: True
2020-07-02 18:21:08 DEBUG (SyncWorker_8) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 18:21:08 DEBUG (SyncWorker_8) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 18:21:08 DEBUG (SyncWorker_8) [custom_components.tahoma.tahoma_api] request success
2020-07-02 18:21:08 DEBUG (SyncWorker_8) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 18:21:08 DEBUG (SyncWorker_8) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 18:21:08 DEBUG (SyncWorker_8) [custom_components.tahoma.tahoma_api] request success
2020-07-02 18:21:09 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_device] apply_action(WZ Süd-Ost) authenticated: True
2020-07-02 18:21:09 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 18:21:09 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 18:21:09 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_api] request success
2020-07-02 18:21:09 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_device] should_wait(WZ Süd-Ost) authenticated: True
2020-07-02 18:21:09 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 18:21:10 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 18:21:10 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_api] request success
2020-07-02 18:21:12 DEBUG (SyncWorker_4) [custom_components.tahoma.tahoma_device] should_wait(Kind (Süd) Süd) authenticated: True

rabesocke · 2020-07-02T16:28:06Z

I test it again and it is reproducible: I clicked the button at 18:24:45 and the cover reacts 10 seconds later. And the same for the stop button - it reacts 10 seconds later after I clicked the button in the HA iOS app.

2020-07-02 18:24:52 DEBUG (SyncWorker_1) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 18:24:52 DEBUG (SyncWorker_1) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 18:24:52 DEBUG (SyncWorker_1) [custom_components.tahoma.tahoma_api] request success
2020-07-02 18:24:53 DEBUG (SyncWorker_9) [custom_components.tahoma.tahoma_device] apply_action(WZ Süd-Ost) authenticated: True
2020-07-02 18:24:53 DEBUG (SyncWorker_9) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 18:24:53 DEBUG (SyncWorker_9) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 18:24:53 DEBUG (SyncWorker_9) [custom_components.tahoma.tahoma_api] request success
2020-07-02 18:24:53 DEBUG (SyncWorker_12) [custom_components.tahoma.tahoma_device] should_wait(WZ Süd-Ost) authenticated: True

2020-07-02 18:25:08 DEBUG (SyncWorker_19) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 18:25:08 DEBUG (SyncWorker_19) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 18:25:08 DEBUG (SyncWorker_19) [custom_components.tahoma.tahoma_api] request success
2020-07-02 18:25:08 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_device] apply_action(WZ Süd-Ost) authenticated: True
2020-07-02 18:25:08 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 18:25:09 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 18:25:09 DEBUG (SyncWorker_5) [custom_components.tahoma.tahoma_api] request success
2020-07-02 18:25:09 DEBUG (SyncWorker_11) [custom_components.tahoma.tahoma_device] should_wait(WZ Süd-Ost) authenticated: True

vlebourl · 2020-07-02T16:30:16Z

Interesting. Are those 8 seconds the typical delay you observe? What command are you using exactly? The apply_action message is sent from the integration, the request messages from the API. It means, once the apply_action is received, no delay is observed

rabesocke · 2020-07-02T16:34:05Z

Since the update to 1.5-alpha2 the delay is normally between 2 and 12 seconds. Most time the delay is 8 till 10 seconds.
Is there any schedule for applying actions?

I use the Button down, up and stop of the entity card:

vlebourl · 2020-07-02T16:39:10Z

I added yet other log messages to time when the actions are received by the cover entity.

rabesocke · 2020-07-02T17:04:32Z

The delay is before the action is received by the cover entity:

Move down clicked at 19:00:45

2020-07-02 19:00:52 DEBUG (SyncWorker_3) [custom_components.tahoma.cover] close_cover(WZ Süd-Ost)
2020-07-02 19:00:52 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_device] apply_action(WZ Süd-Ost) authenticated: True
2020-07-02 19:00:52 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 19:00:53 DEBUG (SyncWorker_3) [custom_components.tahoma.tahoma_api] request sent

Stop clicked at 19:01:00

2020-07-02 19:01:08 DEBUG (SyncWorker_1) [custom_components.tahoma.cover] stop_cover(WZ Süd-Ost)
2020-07-02 19:01:08 DEBUG (SyncWorker_1) [custom_components.tahoma.tahoma_device] apply_action(WZ Süd-Ost) authenticated: True
2020-07-02 19:01:08 DEBUG (SyncWorker_1) [custom_components.tahoma.tahoma_api] sending request
2020-07-02 19:01:09 DEBUG (SyncWorker_1) [custom_components.tahoma.tahoma_api] request sent
2020-07-02 19:01:09 DEBUG (SyncWorker_1) [custom_components.tahoma.tahoma_api] request success

vlebourl · 2020-07-02T17:08:39Z

I'm afraid it's not on our side... This might be related to the frontend, but we can't control what happens before the close_cover our stop_cover log message.

rabesocke · 2020-07-02T17:38:12Z

Ok. It's hard to say what the source is. I updated HA to 0.112 and because of the login issue I had to update tahoma to 1.5-alpha2. Before that I used HA 0.111.4 and tahoma 1.3.

What I don't unterstand: the Zigbee lights are responding immediately without delay.

mariwing · 2020-07-02T19:07:55Z

I just found this in the hidden doc regarding actions sent to the api: "Per-session rate-limit : 50 calls per 24 HOURS period for all operations of the same category (exec)"
Maybe this is the issue?

This comment might be completly idiotic and I might be thinking completely wrong :-) But I have only RTS devices, so none of them report any state at any time. Reading the log (and this is the part where I might be wrong) it seems that the integration is pulling the api for status. This is bound to not give any usable result since there is no state to report. If it is possible to from the device class see that it is an RTS device (or maybe some other way to determine that the device don't report status) you could save on the API call quota by not issuing status update calls for this device groups.

vlebourl · 2020-07-02T19:15:29Z

It's a good idea to not pull on rts devices indeed. But we are thinking of rewriting the whole update process to make it an event based push update instead of a regular poll. This will be quite some work so not for tomorrow... Nevertheless, updates aren't exec calls, so it shouldn't impact the quotas

vlebourl · 2020-07-03T07:03:40Z

I'll close this issue for now.

Related Github issues: #86

vlebourl added the bug Something isn't working label Jun 24, 2020

vlebourl referenced this issue Jul 1, 2020

handle error not authenticated

992e315

mark as logged out when receiving {"errorCode":"RESOURCE_ACCESS_DENIED","error":"Not authenticated"}

vlebourl added a commit that referenced this issue Jul 2, 2020

[fix] Relog in when not authenticated error.

4cdcd23

Related Github issues: #86

vlebourl mentioned this issue Jul 2, 2020

Re-log in the API after a "error":"Not authenticated" #95

Merged

vlebourl closed this as completed Jul 2, 2020

vlebourl mentioned this issue Jul 2, 2020

Remove the lock on apply_action #93

Merged

vlebourl added a commit that referenced this issue Jul 2, 2020

[fix] Change a test in login function

f70c088

Related Github issues: #86

vlebourl reopened this Jul 2, 2020

vlebourl added a commit that referenced this issue Jul 2, 2020

[WIP] Add debug message if not authenticated.

2630c22

Related Github issues: #86

vlebourl added a commit that referenced this issue Jul 2, 2020

[WIP] modified debug message

29dce7f

Related Github issues: #86

vlebourl closed this as completed Jul 3, 2020

vlebourl added a commit that referenced this issue Jul 3, 2020

[fix] Reverted log message

3e0e6b4

Related Github issues: #86

vlebourl added a commit that referenced this issue Jul 3, 2020

[stye] Fixed a few white lines.

25dd442

Related Github issues: #86

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Not authenticated error. #86

Not authenticated error. #86

vlebourl commented Jun 24, 2020

mariwing commented Jul 1, 2020

vlebourl commented Jul 1, 2020

vlebourl commented Jul 1, 2020

vlebourl commented Jul 2, 2020

vlebourl commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020 •

edited

Loading

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

mariwing commented Jul 2, 2020

vlebourl commented Jul 2, 2020

vlebourl commented Jul 3, 2020

Not authenticated error. #86

Not authenticated error. #86

Comments

vlebourl commented Jun 24, 2020

mariwing commented Jul 1, 2020

vlebourl commented Jul 1, 2020

vlebourl commented Jul 1, 2020

vlebourl commented Jul 2, 2020

vlebourl commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020 • edited Loading

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

vlebourl commented Jul 2, 2020

rabesocke commented Jul 2, 2020

mariwing commented Jul 2, 2020

vlebourl commented Jul 2, 2020

vlebourl commented Jul 3, 2020

rabesocke commented Jul 2, 2020 •

edited

Loading