search

nielsfaber / scheduler-component

Custom component for HA that enables the creation of scheduler entities
GNU General Public License v3.0
685 stars 46 forks source link

Strange execution times #99

Closed ianeva78 closed 3 years ago

ianeva78 commented 3 years ago

Unsure if this is the correct place to put this and can't see anyone else with the issue.

Schedules have been working very well but now they don't execute at the exact time and sometimes they may miss the schedule completely. I have uninstalled and reinstalled and updated to latest version of HA. Logs below. Any help appreciated. TIA

problems, be sure to disable it if you experience issues with Home Assistant 2021-03-04 13:34:10 ERROR (MainThread) [homeassistant.components.calendar] google: Error on device update! Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 360, in _async_add_entity await entity.async_device_update(warning=False) File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 465, in async_device_update await task File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run result = self.fn(*self.args, **self.kwargs) File "/usr/src/homeassistant/homeassistant/components/google/calendar.py", line 103, in update self.data.update() File "/usr/src/homeassistant/homeassistant/util/__init__.py", line 285, in wrapper result = method(*args, **kwargs) File "/usr/src/homeassistant/homeassistant/components/google/calendar.py", line 172, in update result = events.list(**params).execute() File "/usr/local/lib/python3.8/site-packages/oauth2client/_helpers.py", line 133, in positional_wrapper return wrapped(*args, **kwargs) File "/usr/local/lib/python3.8/site-packages/googleapiclient/http.py", line 842, in execute raise HttpError(resp, content, uri=self.uri) googleapiclient.errors.HttpError: <HttpError 404 when requesting https://www.googleapis.com/calendar/v3/calendars/family12892771050008729721%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2021-03-04T13%3A34%3A10.423568%2B00%3A00&alt=json returned "Not Found"> 2021-03-04 13:34:10 WARNING (MainThread) [homeassistant.components.onvif] The date/time on the device (UTC) is '2021-03-04 13:34:16+00:00', which is different from the system '2021-03-04 13:34:10.247731+00:00', this could lead to authentication issues 2021-03-04 13:58:07 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140718262634432] Received invalid command: scheduler 2021-03-04 13:58:07 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140718262634432] Received invalid command: scheduler 2021-03-04 13:58:07 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140718262634432] Received invalid command: scheduler 2021-03-04 13:58:11 WARNING (MainThread) [homeassistant.loader] You are using a custom integration scheduler which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-04 13:58:11 WARNING (MainThread) [homeassistant.loader] No 'version' key in the manifest file for custom integration 'scheduler'. This will not be allowed in a future version of Home Assistant. Please report this to the maintainer of 'scheduler' 2021-03-04 13:58:53 WARNING (MainThread) [homeassistant.components.cloud.google_config] Error reporting state - 5: Requested entity was not found. 2021-03-04 13:59:27 WARNING (MainThread) [homeassistant.components.cloud.google_config] Error reporting state - 5: Requested entity was not found. 2021-03-04 14:00:06 WARNING (MainThread) [homeassistant.components.cloud.google_config] Error reporting state - 5: Requested entity was not found.

System Health

version core-2021.3.0
installation_type Home Assistant OS
dev false
hassio true
docker true
virtualenv false
python_version 3.8.7
os_name Linux
os_version 5.4.99
arch x86_64
timezone GB
Home Assistant Community Store GitHub API | ok -- | -- Github API Calls Remaining | 4855 Installed Version | 1.11.3 Stage | running Available Repositories | 819 Installed Repositories | 24
Home Assistant Cloud logged_in | true -- | -- subscription_expiration | March 25, 2021, 12:00 AM relayer_connected | true remote_enabled | true remote_connected | true alexa_enabled | true google_enabled | true can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok
Hass.io host_os | Home Assistant OS 5.12 -- | -- update_channel | stable supervisor_version | supervisor-2021.03.4 docker_version | 19.03.13 disk_total | 38.7 GB disk_used | 11.6 GB healthy | true supported | true board | ova supervisor_api | ok version_api | ok installed_addons | Samba share (9.3.1), AppDaemon 4 (0.4.4), Visual Studio Code (3.1.0), Terminal & SSH (9.0.2), AdGuard Home (3.0.0), Mosquitto broker (5.1.1), TasmoAdmin (0.14.0), Spotify Connect (0.8.2), Check Home Assistant configuration (3.6.0), WireGuard (0.5.0), TasmoBackup (1.04.10)
Lovelace dashboards | 3 -- | -- resources | 10 views | 14 mode | storage
Spotify api_endpoint_reachable | ok -- | --
KTibow commented 3 years ago

Please format your code and logs.

ianeva78 commented 3 years ago

Sorry, first time I have posted. Hopefully this is now correct.

nielsfaber commented 3 years ago

Hello @ianeva78 ,

I cannot really see any useful information from the logs you are sharing.

Could you please add the following to configuration.yaml and restart your HA:

logger:
  default: warning
  logs:
    custom_components.scheduler: debug

After adding this, you should see a lot more logging info. Please share the logging when you notice the problem occured again.

ianeva78 commented 3 years ago

Hello @nielsfaber,

Timer set for 21:00 and triggered at 21:00:14.

No errors but is 14 seconds away from trigger normal. Sometimes it can be a minute or missed.

Thank you

2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] You are using a custom integration garbage_collection which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] You are using a custom integration hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] You are using a custom integration shelly which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] No 'version' key in the manifest file for custom integration 'shelly'. This will not be allowed in a future version of Home Assistant. Please report this to the maintainer of 'shelly' 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] You are using a custom integration nodered which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] You are using a custom integration sonoff which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] No 'version' key in the manifest file for custom integration 'sonoff'. This will not be allowed in a future version of Home Assistant. Please report this to the maintainer of 'sonoff' 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] You are using a custom integration scheduler which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] No 'version' key in the manifest file for custom integration 'scheduler'. This will not be allowed in a future version of Home Assistant. Please report this to the maintainer of 'scheduler' 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] You are using a custom integration momentary which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] You are using a custom integration localtuya which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-03-05 20:58:56 WARNING (MainThread) [homeassistant.loader] No 'version' key in the manifest file for custom integration 'localtuya'. This will not be allowed in a future version of Home Assistant. Please report this to the maintainer of 'localtuya' 2021-03-05 20:59:33 ERROR (MainThread) [homeassistant.components.calendar] google: Error on device update! Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 360, in _async_add_entity await entity.async_device_update(warning=False) File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 465, in async_device_update await task File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run result = self.fn(*self.args, **self.kwargs) File "/usr/src/homeassistant/homeassistant/components/google/calendar.py", line 103, in update self.data.update() File "/usr/src/homeassistant/homeassistant/util/__init__.py", line 285, in wrapper result = method(*args, **kwargs) File "/usr/src/homeassistant/homeassistant/components/google/calendar.py", line 172, in update result = events.list(**params).execute() File "/usr/local/lib/python3.8/site-packages/oauth2client/_helpers.py", line 133, in positional_wrapper return wrapped(*args, **kwargs) File "/usr/local/lib/python3.8/site-packages/googleapiclient/http.py", line 842, in execute raise HttpError(resp, content, uri=self.uri) googleapiclient.errors.HttpError: <HttpError 404 when requesting https://www.googleapis.com/calendar/v3/calendars/family12892771050008729721%40group.calendar.google.com/events?orderBy=startTime&maxResults=5&singleEvents=true&timeMin=2021-03-05T20%3A59%3A33.588798%2B00%3A00&alt=json returned "Not Found"> 2021-03-05 20:59:44 WARNING (MainThread) [homeassistant.setup] Setup of default_config is taking over 10 seconds. 2021-03-05 21:00:04 DEBUG (MainThread) [custom_components.scheduler] Scheduler coordinator is ready 2021-03-05 21:00:04 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_b2a30d 2021-03-05 21:00:04 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-05T21:18:00+00:00 2021-03-05 21:00:04 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_80b0e7 2021-03-05 21:00:04 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_ab6333 2021-03-05 21:03:57 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_b2a30d 2021-03-05 21:03:57 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-05T21:05:00+00:00 2021-03-05 21:05:07 DEBUG (MainThread) [custom_components.scheduler.switch] timer for switch.schedule_b2a30d is triggered 2021-03-05 21:05:07 DEBUG (MainThread) [custom_components.scheduler.switch] start of executing actions for switch.schedule_b2a30d 2021-03-05 21:05:07 DEBUG (MainThread) [custom_components.scheduler.switch] Executing action input_boolean.turn_off for entity input_boolean.test_switch. 2021-03-05 21:06:21 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_b2a30d 2021-03-05 21:06:21 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-06T21:05:00+00:00 2021-03-05 21:07:36 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_test_switch_schedule 2021-03-05 21:07:36 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-06T21:05:00+00:00 2021-03-05 21:07:36 WARNING (MainThread) [homeassistant.components.cloud.google_config] Error reporting state - 5: Requested entity was not found. 2021-03-05 21:07:54 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_test_switch_schedule 2021-03-05 21:07:54 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-05T21:09:00+00:00 2021-03-05 21:09:14 DEBUG (MainThread) [custom_components.scheduler.switch] timer for switch.schedule_test_switch_schedule is triggered 2021-03-05 21:09:14 DEBUG (MainThread) [custom_components.scheduler.switch] start of executing actions for switch.schedule_test_switch_schedule 2021-03-05 21:09:14 DEBUG (MainThread) [custom_components.scheduler.switch] Executing action input_boolean.turn_on for entity input_boolean.test_switch. 2021-03-05 21:10:21 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_test_switch_schedule 2021-03-05 21:10:21 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-06T21:09:00+00:00 2021-03-05 21:19:21 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_ab6333 2021-03-05 21:19:24 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_ab6333 2021-03-05 21:19:24 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-05T21:25:00+00:00 2021-03-05 21:19:51 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_ab6333 2021-03-05 21:19:51 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-05T21:25:00+00:00 2021-03-05 21:26:03 DEBUG (MainThread) [custom_components.scheduler.switch] timer for switch.schedule_ab6333 is triggered 2021-03-05 21:26:03 DEBUG (MainThread) [custom_components.scheduler.switch] start of executing actions for switch.schedule_ab6333 2021-03-05 21:26:03 DEBUG (MainThread) [custom_components.scheduler.switch] Executing action switch.turn_off for entity switch.fire_lamp. 2021-03-05 21:27:17 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_ab6333 2021-03-05 21:27:17 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-03-06T21:25:00+00:00

System Health

version core-2021.3.1
installation_type Home Assistant OS
dev false
hassio true
docker true
virtualenv false
python_version 3.8.7
os_name Linux
os_version 5.4.99
arch x86_64
timezone GB
Home Assistant Community Store GitHub API | ok -- | -- Github API Calls Remaining | 4519 Installed Version | 1.11.3 Stage | running Available Repositories | 819 Installed Repositories | 24
Home Assistant Cloud logged_in | true -- | -- subscription_expiration | March 25, 2021, 12:00 AM relayer_connected | true remote_enabled | true remote_connected | true alexa_enabled | true google_enabled | true can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok
Hass.io host_os | Home Assistant OS 5.12 -- | -- update_channel | stable supervisor_version | supervisor-2021.03.4 docker_version | 19.03.13 disk_total | 38.7 GB disk_used | 12.5 GB healthy | true supported | true board | ova supervisor_api | ok version_api | ok installed_addons | Samba share (9.3.1), AppDaemon 4 (0.4.4), Visual Studio Code (3.1.0), Terminal & SSH (9.0.2), AdGuard Home (3.0.0), Mosquitto broker (5.1.1), TasmoAdmin (0.14.0), Spotify Connect (0.8.2), Check Home Assistant configuration (3.6.0), WireGuard (0.5.0), TasmoBackup (1.04.10)
Lovelace dashboards | 3 -- | -- resources | 10 views | 14 mode | storage
Spotify api_endpoint_reachable | ok -- | --
crisobal commented 3 years ago

I have the same behaviour. Deviation seems to be depending on the time from setting schedule until trigger. If I set a new schedule which points only a couple of minutes to the future it is normally 10-30 seconds to late, if duration is almost a day then it is more than 2.5 hours late. I am running homeassistant as VM on ESXi 7. Is the Python async event loop made for exact scheduling? A workaround could be to let scheduler component being internally triggered every 1s and the check if some real schedules must be triggered. After spending some minutes in your code I did not see any obvious bug.

Shows restart around 10:17 on 5.4.2021, then fire almost 9 min to late. Then reschedule and fire 2.5 hours to late. If I would let it run it will always fire around 14:00 instead of 11:28.

2021-04-05 10:17:07 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_fd947a
2021-04-05 10:17:07 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-04-05T11:28:00+02:00
2021-04-05 11:36:53 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_fd947a
2021-04-05 11:36:53 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-04-06T11:28:00+02:00
2021-04-06 14:07:13 DEBUG (MainThread) [custom_components.scheduler.switch] Rescheduling timer for switch.schedule_fd947a
2021-04-06 14:07:13 DEBUG (MainThread) [custom_components.scheduler.switch] The next timer is set for 2021-04-07T11:28:00+02:00

My Environment

version core-2021.3.4
installation_type Home Assistant Core
dev false
hassio false
docker false
virtualenv true
python_version 3.8.7
os_name Linux
os_version 4.19.0-16-amd64
arch x86_64
timezone Europe/Zurich
Home Assistant Community Store GitHub API | ok -- | -- Github API Calls Remaining | 4923 Installed Version | 1.11.3 Stage | running Available Repositories | 838 Installed Repositories | 12
Home Assistant Cloud logged_in | false -- | -- can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok
Lovelace dashboards | 1 -- | -- resources | 6 views | 8 mode | storage
ianeva78 commented 3 years ago

I've just updated to the latest version of HA and scheduler is now working perfectly!