Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Time-out issues with DataUpdateCoordinator #345

Closed
1 task done
Tonylolo opened this issue Jan 14, 2021 · 20 comments · Fixed by #346
Closed
1 task done

Time-out issues with DataUpdateCoordinator #345

Tonylolo opened this issue Jan 14, 2021 · 20 comments · Fixed by #346
Labels
bug Something isn't working no-issue-activity

Comments

@Tonylolo
Copy link

Tonylolo commented Jan 14, 2021 •
edited
Loading

  • I have read the Readme, including the Advanced section regarding debugging.

Describe the bug
it's random, sometimes daily, sometimes 3 times a week ... the controls for my shutters for my tahoma do not work.
In the log I have the message: Timeout fetching TaHoma Event Fetcher data.

After restarting the server, everything works again.

I am using HA on container / Qnap.

To Reproduce
Steps to reproduce the behavior:

Just wait several minutes or hours...and in my log I have:

Timeout fetching TaHoma Event Fetcher data

Expected behavior
A clear and concise description of what you expected to happen.

Screenshots
If applicable, add screenshots to help explain your problem.

Environment (please complete the following information):

  • ha-tahoma version: lastest
  • Home Assistant version: Home Assistant 2020.12.1
  • Platform: [e.g. cover, sensor, binary_sensor]
    roller
    Device: (if your problem is related to a specific device)
    Tahoma
  • Model: [e.g. PositionableScreen, can be gathered from device list in HA]
  • Type: [e.g. io:DimmableLightIOComponent, can be gathered from device page in HA looking at Firmware] /config/devices/dashboard]

Additional context

Add any other context about the problem here.
@Tonylolo Tonylolo added the bug Something isn't working label Jan 14, 2021
@iMicknl iMicknl mentioned this issue Jan 14, 2021
Closed
1 task
@iMicknl iMicknl changed the title Tahoma : Timeout fetching TaHoma Event Fetcher data Time-out issues with DataUpdateCoordinator Jan 14, 2021
@iMicknl
Copy link
Owner

iMicknl commented Jan 14, 2021

Thanks for reporting @Tonylolo. I haven't seen these issues yet. What is your update interval? (Settings -> Integrations).

Do you have debug mode enabled and could you share more parts of your log? I would like to understand more about this behaviour. Normally, controlling your covers is not related to the event fetcher. The event fetcher is able to recover from any timeouts, thus that should not be a big issue.

@Tonylolo
Copy link
Author

My update interval : 30s, I test with 3200 same things.

I don't know how enable debug mode ?

@iMicknl
Copy link
Owner

iMicknl commented Jan 14, 2021

In our readme, we documented how to enable debug logging: https://github.com/iMicknl/ha-tahoma#enable-debug-logging

Could you clarify what the issue is. Is it just the message in the log, or does it also happen when you try to execute a command? (via automations?)

@Tonylolo
Copy link
Author

my log has been cleaned, so as soon as the message, I copy here.

It's just a message in the log, when a command doesn't work I go see. in log and I find the message :...fetcher....

@iMicknl iMicknl linked a pull request Jan 14, 2021 that will close this issue
Catch timeout error in DataUpdateCoordinator #346
Merged
@Tonylolo
Copy link
Author

Tonylolo commented Jan 15, 2021 •
edited by iMicknl
Loading 

EventName.EXECUTION_STATE_CHANGED/04b2b4cc-ac10-3401-7548-14e55edb4b2a (device: None, state: ExecutionState.IN_PROGRESS -> ExecutionState.COMPLETED)
2021-01-15 07:21:38 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 68.960 seconds
2021-01-15 07:22:48 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.996 seconds
2021-01-15 07:25:09 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 07:27:29 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 07:27:30 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 252.052 seconds
2021-01-15 07:33:00 DEBUG (MainThread) [custom_components.tahoma.coordinator]
2021-01-15 07:33:00 ERROR (MainThread) [custom_components.tahoma] Error fetching TaHoma Event Fetcher data:
2021-01-15 07:33:00 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 300.273 seconds
2021-01-15 07:34:29 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 07:37:59 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 07:37:59 INFO (MainThread) [custom_components.tahoma] Fetching TaHoma Event Fetcher data recovered
2021-01-15 07:37:59 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 269.696 seconds
2021-01-15 07:39:09 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.095 seconds
2021-01-15 07:40:19 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.090 seconds
2021-01-15 07:45:49 DEBUG (MainThread) [custom_components.tahoma.coordinator]
2021-01-15 07:45:49 ERROR (MainThread) [custom_components.tahoma] Error fetching TaHoma Event Fetcher data:
2021-01-15 07:45:49 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 300.273 seconds
2021-01-15 07:47:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 07:47:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 07:49:39 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.5s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 07:50:49 INFO (MainThread) [custom_components.tahoma] Fetching TaHoma Event Fetcher data recovered
2021-01-15 07:50:49 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 270.239 seconds
2021-01-15 07:53:09 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 07:53:09 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 07:55:29 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.4s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 07:56:39 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 320.243 seconds
2021-01-15 08:00:09 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 08:01:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 08:03:39 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.3s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 08:04:49 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 460.310 seconds
2021-01-15 08:05:59 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.249 seconds
2021-01-15 08:08:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 08:08:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 08:12:59 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.8s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 08:18:49 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 740.417 seconds
2021-01-15 08:21:09 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 08:21:09 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 08:24:39 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.4s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 08:29:19 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 600.500 seconds
2021-01-15 08:33:59 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 08:35:09 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 08:39:49 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.3s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 08:42:09 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 740.554 seconds
2021-01-15 08:43:19 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.474 seconds
2021-01-15 08:44:29 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.629 seconds
2021-01-15 08:46:49 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 08:46:49 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 08:50:19 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.9s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 08:54:59 ERROR (MainThread) [backoff] Giving up get_devices(...) after 2 tries (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 08:54:59 ERROR (MainThread) [custom_components.tahoma] Unexpected error fetching TaHoma Event Fetcher data: Not authenticated
Traceback (most recent call last):
File "/config/custom_components/tahoma/coordinator.py", line 66, in _async_update_data
events = await self.client.fetch_events()
File "/usr/local/lib/python3.8/site-packages/pyhoma/client.py", line 190, in fetch_events
response = await self.__post(f"events/{self.event_listener_id}/fetch")
File "/usr/local/lib/python3.8/site-packages/pyhoma/client.py", line 294, in __post
await self.check_response(response)
File "/usr/local/lib/python3.8/site-packages/pyhoma/client.py", line 332, in check_response
raise NotAuthenticatedException(message)
pyhoma.exceptions.NotAuthenticatedException: Not authenticated
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 144, in async_refresh
self.data = await self._async_update_data()
File "/config/custom_components/tahoma/coordinator.py", line 77, in _async_update_data
self.devices = await self._get_devices()
File "/config/custom_components/tahoma/coordinator.py", line 141, in _get_devices
return {d.deviceurl: d for d in await self.client.get_devices(refresh=True)}
File "/usr/local/lib/python3.8/site-packages/backoff/_async.py", line 133, in retry
ret = await target(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/pyhoma/client.py", line 106, in get_devices
response = await self.__get("setup/devices")
File "/usr/local/lib/python3.8/site-packages/pyhoma/client.py", line 284, in __get
await self.check_response(response)
File "/usr/local/lib/python3.8/site-packages/pyhoma/client.py", line 332, in check_response
raise NotAuthenticatedException(message)
pyhoma.exceptions.NotAuthenticatedException: Not authenticated
2021-01-15 08:54:59 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 600.579 seconds
2021-01-15 09:00:29 DEBUG (MainThread) [custom_components.tahoma.coordinator]
2021-01-15 09:00:29 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 300.376 seconds
2021-01-15 09:01:59 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 09:04:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 09:06:39 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.5s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 09:08:59 INFO (MainThread) [custom_components.tahoma] Fetching TaHoma Event Fetcher data recovered
2021-01-15 09:08:59 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 480.790 seconds
2021-01-15 09:11:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 09:13:39 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 09:14:49 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 320.803 seconds
2021-01-15 09:15:59 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.732 seconds
2021-01-15 09:18:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 09:18:19 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 09:20:39 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.8s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 09:21:49 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 320.819 seconds
2021-01-15 09:24:09 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 09:25:20 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 09:25:20 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 181.184 seconds
2021-01-15 09:26:29 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 39.801 seconds
2021-01-15 09:28:49 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 09:29:59 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 09:31:09 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 250.877 seconds
2021-01-15 09:32:19 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.819 seconds
2021-01-15 09:34:39 DEBUG (MainThread) [custom_components.tahoma.coordinator] Not authenticated
2021-01-15 09:34:39 DEBUG (MainThread) [custom_components.tahoma.coordinator] Fetching all devices and state via /setup/devices
2021-01-15 09:36:59 INFO (MainThread) [backoff] Backing off get_devices(...) for 0.9s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-01-15 09:38:09 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 320.920 seconds
2021-01-15 09:39:19 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.897 seconds
2021-01-15 09:40:30 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 41.022 seconds

@Tonylolo
Copy link
Author

Hi

I start at:

2021-01-15 07:17:19 ERROR (MainThread) [custom_components.tahoma] Timeout fetching TaHoma Event Fetcher data

Thk

@Tonylolo
Copy link
Author

Logger: custom_components.tahoma
Source: helpers/update_coordinator.py:166
Integration: Somfy TaHoma (documentation, issues)
First occurred: 7:33:00 (2 occurrences)
Last logged: 7:45:49

Error fetching TaHoma Event Fetcher data:

@iMicknl
Copy link
Owner

iMicknl commented Jan 15, 2021

Thanks for sharing your log. I am a bit clue less why you receive so many Not authenticated exceptions in combination with very high response times.

  • Could you update to the latest available version of this integration (via HACS / GitHub)
  • What is your current update interval? (the one you shared the log from)
  • Could it be that you have network issues?
2021-01-15 09:38:09 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 320.920 seconds
2021-01-15 09:39:19 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 40.897 seconds
2021-01-15 09:40:30 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 41.022 seconds

This is very very slow compared to my installation. The events should be fetched in less than a second normally...

2021-01-15 16:20:12 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 0.132 seconds
2021-01-15 16:21:12 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 0.122 seconds
2021-01-15 16:22:12 DEBUG (MainThread) [custom_components.tahoma] Finished fetching TaHoma Event Fetcher data in 0.122 seconds

@Tonylolo
Copy link
Author

I have alreadu update hacs integration
Interval update: 30s

HA is installing on Qnap, via container, on network via ethernet cable, none wireless between qnap and tahoma. Only a tplink router and box.

Time between action on button(ios app of HA) and moving of roller is randomary; fast and some times several seconds...

@iMicknl
Copy link
Owner

iMicknl commented Jan 15, 2021

I don't think we can offer a solution for this issue... We haven't had any user with those issues yet and I don't believe this is part of this integration. The event fetcher is a really simple API endpoint. It should not happen that a request takes 40 seconds, instead of 0.1 second.

Are you able to ping tahomalink.com from your QNAP? I wonder what kind of latency you have.

@Tonylolo
Copy link
Author

Yes i test the ping: 21ms from nas to tahomalink.com

@Tonylolo
Copy link
Author

So about this issue i ll continue to search...

Another issue if you cn jelp me, when i use stop command on a roller with ha, roller doesn't take myposition , there is nothing. But if the rolling moves it's ok it stops.

Thk

@iMicknl
Copy link
Owner

iMicknl commented Jan 16, 2021

Another issue if you cn jelp me, when i use stop command on a roller with ha, roller doesn't take myposition , there is nothing. But if the rolling moves it's ok it stops.

This is currently not mapped to the stop service in Home Assistant. If you would like to utilize my position, you can the following service call. tahoma.set_cover_my_position

@Tonylolo
Copy link
Author

Great !

@Tonylolo
Copy link
Author

Hi,
In order to validate if it is my installation or the integration; I installed the official SOMFY integration (which works on shutters).
As usual, 2-3 days without any problem and then one morning no shutter responds or so under several tens of seconds and I even have an error:
Failed to call the cover / open_cover service. 500 Server error: Internal Server Error for url:
https://api.somfy.com/api/v1/device/9894282d-b0f29..../exec

I use this time to compare the official and it works perfectly! so the error is on your integration.

I will try with nodered for another comparison.

Do you have more idea?

Thank you

@iMicknl iMicknl reopened this Feb 25, 2021
@tetienne
Copy link
Collaborator

@Tonylolo the error you quoted come from the official api integration not from this one.

The official api is known to be flaky as the Somfy server returns often errors like yours. The only thing you can do is to contact their support. Like I already did several times. Sadly they don't give resources to this api.

@Tonylolo
Copy link
Author

Hi

Are you sure because it's appears when i use an entity cover make with tahoma custom integration.

And i always have issue after 1-2days with this integration. Since somfy official is ok...

Sadly i would like use custom that is very good in term of functions!

@Tonylolo
Copy link
Author

Tonylolo commented Mar 1, 2021

hi,

i complete following to issue this night:

2021-03-01 19:06:25 INFO (MainThread) [backoff] Backing off execute_commands(...) for 0.9s (pyhoma.exceptions.NotAuthenticatedException: Not authenticated)
2021-03-01 19:06:26 INFO (MainThread) [backoff] Backing off execute_command(...) for 0.5s (pyhoma.exceptions.TooManyExecutionsException: Server busy, please try again later. (Too many executions))
2021-03-01 19:06:27 INFO (MainThread) [backoff] Backing off execute_command(...) for 0.2s (pyhoma.exceptions.TooManyExecutionsException: Server busy, please try again later. (Too many executions))
2021-03-01 19:06:27 INFO (MainThread) [backoff] Backing off execute_command(...) for 3.1s (pyhoma.exceptions.TooManyExecutionsException: Server busy, please try again later. (Too many executions))
2021-03-01 19:06:30 INFO (MainThread) [backoff] Backing off execute_command(...) for 0.4s (pyhoma.exceptions.TooManyExecutionsException: Server busy, please try again later. (Too many executions))
2021-03-01 19:06:31 INFO (MainThread) [backoff] Backing off execute_command(...) for 2.1s (pyhoma.exceptions.TooManyExecutionsException: Server busy, please try again later. (Too many executions))
2021-03-01 19:06:33 INFO (MainThread) [backoff] Backing off execute_command(...) for 29.0s (pyhoma.exceptions.TooManyExecutionsException: Server busy, please try again later. (Too many executions

After that I test with "official SOMFY" integration and all is ok.

@iMicknl
Copy link
Owner

iMicknl commented Mar 1, 2021

This is a different, not related, issue. (pyhoma.exceptions.TooManyExecutionsException: Server busy, please try again later. (Too many executions)), see #261.

@github-actions
Copy link

github-actions bot commented Apr 1, 2021

'There hasn't been any activity on this issue recently. Is this issue still present?
Please make sure to update to the latest Home Assistant version and version of this integration to see if that solves the issue. Let us know if that works for you by adding a comment 👍.
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.'

@github-actions github-actions bot closed this as completed Apr 7, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working no-issue-activity
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Catch timeout error in DataUpdateCoordinator iMicknl/ha-tahoma
3 participants
@iMicknl @tetienne @Tonylolo