search

iMicknl / ha-tahoma

Custom component for Home Assistant to interact with smart devices via Somfy TaHoma or other OverKiz based API's.
MIT License
156 stars 30 forks source link

Stops working, with 'Error fetching device events data: Too many requests, try again later.' #504

Closed callifo closed 3 years ago

callifo commented 3 years ago

Did you read the instructions?

The problem

Within the last few weeks started to notice these populating the log files whenever a cover is controlled,

2021-08-04 07:43:55 ERROR (MainThread) [custom_components.tahoma] Error fetching device events data: Too many requests, try again later.

Eventually blind control completely stopped. After disabling it for 3 days, control has temporarily returned. Even when I could not control the blind, the integration still starts fine with no errors on start, and all blinds are discovered fine.

The speed of control can sometimes be a bit patchy. I've sometimes sent the up or down command, and then nothing has happened. Then 2-3 minutes later the blind activates.

As this blind does not report state, the Update Interval is set to 2 weeks.

What version of this integration (ha-tahoma) has the issue?

2.5.1

What version of Home Assistant Core has the issue?

2021.7.4

Which gateway / hub do you use?

Connexoon Rts Australia hub

Device model

UpDownScreen

Device type

rts:BlindRTSComponent

Additional information

No response

Relevant log output

2021-08-04 23:17:14 INFO (MainThread) [backoff] Backing off execute_commands(...) for 0.2s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-08-04 23:17:15 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_REGISTERED/116b1641-0a32-0482-7f81-993e22afa6a8 (device: None, state: None -> None)
2021-08-04 23:17:15 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116b1641-0a32-0482-7f81-993e22afa6a8 (device: None, state: ExecutionState.INITIALIZED -> ExecutionState.NOT_TRANSMITTED)
2021-08-04 23:17:15 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_STARTED/None (device: None, state: None -> None)
2021-08-04 23:17:15 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116b1641-0a32-0482-7f81-993e22afa6a8 (device: None, state: ExecutionState.NOT_TRANSMITTED -> ExecutionState.TRANSMITTED)
2021-08-04 23:17:15 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_ENDED/None (device: None, state: None -> None)
2021-08-04 23:17:15 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.087 seconds
2021-08-04 23:17:16 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.081 seconds
2021-08-04 23:17:17 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:17:18 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116b1641-0a32-0482-7f81-993e22afa6a8 (device: None, state: ExecutionState.TRANSMITTED -> ExecutionState.IN_PROGRESS)
2021-08-04 23:17:18 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:17:19 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:20 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.089 seconds
2021-08-04 23:17:21 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_STARTED/None (device: None, state: None -> None)
2021-08-04 23:17:21 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.277 seconds
2021-08-04 23:17:22 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_ENDED/None (device: None, state: None -> None)
2021-08-04 23:17:22 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:17:23 DEBUG (MainThread) [custom_components.tahoma.coordinator] CommandExecutionStateChangedEvent/116b1641-0a32-0482-7f81-993e22afa6a8 (device: rts://0407-4147-2775/16763048, state: None -> ExecutionState.FAILED)
2021-08-04 23:17:23 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116b1641-0a32-0482-7f81-993e22afa6a8 (device: None, state: ExecutionState.IN_PROGRESS -> ExecutionState.FAILED)
2021-08-04 23:17:23 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.086 seconds
2021-08-04 23:17:24 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_REGISTERED/116b38b3-0a32-0482-7f81-993e40ce7dcf (device: None, state: None -> None)
2021-08-04 23:17:24 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116b38b3-0a32-0482-7f81-993e40ce7dcf (device: None, state: ExecutionState.INITIALIZED -> ExecutionState.NOT_TRANSMITTED)
2021-08-04 23:17:24 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_STARTED/None (device: None, state: None -> None)
2021-08-04 23:17:24 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116b38b3-0a32-0482-7f81-993e40ce7dcf (device: None, state: ExecutionState.NOT_TRANSMITTED -> ExecutionState.TRANSMITTED)
2021-08-04 23:17:24 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_ENDED/None (device: None, state: None -> None)
2021-08-04 23:17:24 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.088 seconds
2021-08-04 23:17:25 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:26 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116b38b3-0a32-0482-7f81-993e40ce7dcf (device: None, state: ExecutionState.TRANSMITTED -> ExecutionState.IN_PROGRESS)
2021-08-04 23:17:26 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:27 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.088 seconds
2021-08-04 23:17:28 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:17:29 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:30 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:17:31 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:17:32 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.091 seconds
2021-08-04 23:17:33 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.101 seconds
2021-08-04 23:17:34 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:17:35 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.116 seconds
2021-08-04 23:17:36 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:17:37 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:17:38 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.098 seconds
2021-08-04 23:17:39 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:17:40 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:17:41 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:42 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:43 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:17:44 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:45 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.090 seconds
2021-08-04 23:17:46 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.085 seconds
2021-08-04 23:17:47 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.085 seconds
2021-08-04 23:17:48 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:17:49 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:50 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:51 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:52 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:17:53 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:17:54 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:17:55 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.081 seconds
2021-08-04 23:17:56 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:17:57 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116b38b3-0a32-0482-7f81-993e40ce7dcf (device: None, state: ExecutionState.IN_PROGRESS -> ExecutionState.COMPLETED)
2021-08-04 23:17:57 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:18:17 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_REGISTERED/116c0534-0a32-0482-7f81-993e6d32faf0 (device: None, state: None -> None)
2021-08-04 23:18:17 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c0534-0a32-0482-7f81-993e6d32faf0 (device: None, state: ExecutionState.INITIALIZED -> ExecutionState.NOT_TRANSMITTED)
2021-08-04 23:18:17 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_STARTED/None (device: None, state: None -> None)
2021-08-04 23:18:17 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c0534-0a32-0482-7f81-993e6d32faf0 (device: None, state: ExecutionState.NOT_TRANSMITTED -> ExecutionState.TRANSMITTED)
2021-08-04 23:18:17 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_ENDED/None (device: None, state: None -> None)
2021-08-04 23:18:17 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.086 seconds
2021-08-04 23:18:18 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c0534-0a32-0482-7f81-993e6d32faf0 (device: None, state: ExecutionState.TRANSMITTED -> ExecutionState.IN_PROGRESS)
2021-08-04 23:18:19 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:18:20 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:18:21 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:18:22 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.110 seconds
2021-08-04 23:18:23 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:24 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:18:25 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:18:26 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:18:27 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.096 seconds
2021-08-04 23:18:27 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_REGISTERED/116c2d7d-0a32-0482-7f81-993e0fbfe854 (device: None, state: None -> None)
2021-08-04 23:18:27 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c2d7d-0a32-0482-7f81-993e0fbfe854 (device: None, state: ExecutionState.INITIALIZED -> ExecutionState.QUEUED_SERVER_SIDE)
2021-08-04 23:18:27 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.085 seconds
2021-08-04 23:18:28 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:18:29 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:30 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:31 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:32 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:33 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.102 seconds
2021-08-04 23:18:34 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.117 seconds
2021-08-04 23:18:35 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.100 seconds
2021-08-04 23:18:36 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:18:36 ERROR (MainThread) [custom_components.tahoma] Error fetching device events data: Too many requests, try again later.
2021-08-04 23:18:36 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.087 seconds
2021-08-04 23:18:37 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_REGISTERED/116c515c-0a32-0482-7f81-993e5930f1c4 (device: None, state: None -> None)
2021-08-04 23:18:37 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c515c-0a32-0482-7f81-993e5930f1c4 (device: None, state: ExecutionState.INITIALIZED -> ExecutionState.QUEUED_SERVER_SIDE)
2021-08-04 23:18:37 INFO (MainThread) [custom_components.tahoma] Fetching device events data recovered
2021-08-04 23:18:37 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.088 seconds
2021-08-04 23:18:38 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.089 seconds
2021-08-04 23:18:39 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:40 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.090 seconds
2021-08-04 23:18:41 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.085 seconds
2021-08-04 23:18:42 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:43 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:44 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:45 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:46 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:47 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.088 seconds
2021-08-04 23:18:48 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:49 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c0534-0a32-0482-7f81-993e6d32faf0 (device: None, state: ExecutionState.IN_PROGRESS -> ExecutionState.COMPLETED)
2021-08-04 23:18:49 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c2d7d-0a32-0482-7f81-993e0fbfe854 (device: None, state: ExecutionState.QUEUED_SERVER_SIDE -> ExecutionState.NOT_TRANSMITTED)
2021-08-04 23:18:49 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_STARTED/None (device: None, state: None -> None)
2021-08-04 23:18:49 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c2d7d-0a32-0482-7f81-993e0fbfe854 (device: None, state: ExecutionState.NOT_TRANSMITTED -> ExecutionState.TRANSMITTED)
2021-08-04 23:18:49 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.GATEWAY_SYNCHRONIZATION_ENDED/None (device: None, state: None -> None)
2021-08-04 23:18:49 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.087 seconds
2021-08-04 23:18:50 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.103 seconds
2021-08-04 23:18:51 DEBUG (MainThread) [custom_components.tahoma.coordinator] EventName.EXECUTION_STATE_CHANGED/116c2d7d-0a32-0482-7f81-993e0fbfe854 (device: None, state: ExecutionState.TRANSMITTED -> ExecutionState.IN_PROGRESS)
2021-08-04 23:18:51 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.084 seconds
2021-08-04 23:18:52 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:53 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:54 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.090 seconds
2021-08-04 23:18:55 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:56 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:18:57 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.082 seconds
2021-08-04 23:18:58 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
2021-08-04 23:18:59 DEBUG (MainThread) [custom_components.tahoma] Finished fetching device events data in 0.083 seconds
iMicknl commented 3 years ago

Related issues: https://github.com/iMicknl/ha-tahoma/issues/300 & https://github.com/iMicknl/ha-tahoma/issues/369.

@tetienne / @vlebourl what should we do? I would say that the DataUpdateCoordinator still makes sense, but that we would need to tackle two things:

  1. If a user only has RTS devices, set the default polling interval to a high value. (1 day?)
  2. Don't fetch state updates every second from the event listener, after an execution has been scheduled for a RTS device.
callifo commented 3 years ago

Think I got banned again, but its different this time. Previously it'd still connect (e.g. integration would correctly setup) but nothing would happen when I send commands to the blinds. Now it can't seem to login so stays as integration starting up permanently

2021-08-16 08:39:19 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: tahoma
2021-08-16 08:40:13 WARNING (MainThread) [homeassistant.config_entries] Config entry 'x@x.com' for tahoma integration not ready yet: Failed to connect; Retrying in background
antoineguilbert commented 3 years ago

Hello,

I've the same problem :

Do you have an idea to fix it ?

rvrignaud commented 3 years ago

Same problem here. Only stateless devices integrated with Tahoma. This sadly makes this integration extremely unreliable for me :(. Is there any way we can help without contributing code directly?

Thank you

tetienne commented 3 years ago

@rvrignaud Can you try to update the polling interval to 3600 seconds (1 hour) within the configuration of this integration and if you have still the issue? image

tetienne commented 3 years ago

@antoineguilbert How many devices have you? What’s confused me is we only perform one request every 30 seconds whatever the number of the devices you own. When this issue occurred for you?

iMicknl commented 3 years ago

@tetienne looking at the log, we perform a request every second due to the execution of a command. However, this should not be an issue since he has just IO equipment...