Google Calendar `calendar` entity delayed in changing state #101431

bachya · 2023-10-05T00:18:34Z

The problem

I have a Google Calendar that I use for a guest entry automation. The associated calendar entity in HASS is consistently late in changing state; as an example, here's an event that is scheduled from 4:35pm to 5:05pm:

State changes are 5-6 minutes behind:

Additionally, these state changes do not appear to trigger a simple automation:

alias: New automation
description: ""
trigger:
  - platform: calendar
    event: start
    offset: "-0:0:0"
    entity_id: calendar.guest_entry
condition: []
action:
  - service: persistent_notification.create
    data:
      message: "{{ trigger.calendar_event.summary }}"
      title: New event
mode: single

In this scenario, even with late state changes, no persistent notifications are created:

What version of Home Assistant Core has the issue?

core-2023.10.0

What was the last working version of Home Assistant Core?

N/A

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Google Calendar

Link to integration documentation on our website

https://www.home-assistant.io/integrations/google/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Unfortunately, debug-level logging doesn't show much:

2023-10-04 15:41:03.078 DEBUG (SyncWorker_0) [homeassistant.components.google] Error reading calendar configuration: [Errno 2] No such file or directory: '/config/google_calendars.yaml'
2023-10-04 15:41:03.677 DEBUG (SyncWorker_4) [homeassistant.components.google] Error reading calendar configuration: [Errno 2] No such file or directory: '/config/google_calendars.yaml'
2023-10-04 15:41:03.878 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.196 seconds (success: True)
2023-10-04 15:41:03.911 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.229 seconds (success: True)
2023-10-04 15:41:03.924 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.241 seconds (success: True)
2023-10-04 15:41:03.928 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.246 seconds (success: True)
2023-10-04 15:41:03.974 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.293 seconds (success: True)
2023-10-04 15:41:03.993 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.311 seconds (success: True)
2023-10-04 15:41:03.999 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.317 seconds (success: True)
2023-10-04 15:41:21.001 DEBUG (SyncWorker_5) [homeassistant.components.google] Error reading calendar configuration: [Errno 2] No such file or directory: '/config/google_calendars.yaml'
2023-10-04 15:41:21.614 DEBUG (SyncWorker_8) [homeassistant.components.google] Error reading calendar configuration: [Errno 2] No such file or directory: '/config/google_calendars.yaml'
2023-10-04 15:41:21.800 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.181 seconds (success: True)
2023-10-04 15:41:21.828 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.209 seconds (success: True)
2023-10-04 15:41:21.836 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.217 seconds (success: True)
2023-10-04 15:41:21.844 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.224 seconds (success: True)
2023-10-04 15:41:21.895 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.276 seconds (success: True)
2023-10-04 15:41:21.930 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.311 seconds (success: True)
2023-10-04 15:41:22.177 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.558 seconds (success: True)
2023-10-04 15:56:22.013 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.197 seconds (success: True)
2023-10-04 15:56:22.109 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.180 seconds (success: True)
2023-10-04 15:56:22.193 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.155 seconds (success: True)
2023-10-04 15:56:22.302 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.152 seconds (success: True)
2023-10-04 15:56:22.363 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.239 seconds (success: True)
2023-10-04 15:56:22.395 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.168 seconds (success: True)
2023-10-04 15:56:22.553 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.579 seconds (success: True)
2023-10-04 16:11:22.020 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.205 seconds (success: True)
2023-10-04 16:11:22.091 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.163 seconds (success: True)
2023-10-04 16:11:22.192 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.141 seconds (success: True)
2023-10-04 16:11:22.316 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.167 seconds (success: True)
2023-10-04 16:11:22.332 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.208 seconds (success: True)
2023-10-04 16:11:22.389 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.162 seconds (success: True)
2023-10-04 16:11:22.537 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.564 seconds (success: True)
2023-10-04 16:26:22.070 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.255 seconds (success: True)
2023-10-04 16:26:22.102 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.173 seconds (success: True)
2023-10-04 16:26:22.157 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.170 seconds (success: True)
2023-10-04 16:26:22.206 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.232 seconds (success: True)
2023-10-04 16:26:22.375 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.250 seconds (success: True)
2023-10-04 16:26:22.380 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.151 seconds (success: True)
2023-10-04 16:26:22.404 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.179 seconds (success: True)
2023-10-04 16:41:22.144 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.328 seconds (success: True)
2023-10-04 16:41:22.177 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.191 seconds (success: True)
2023-10-04 16:41:22.244 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.272 seconds (success: True)
2023-10-04 16:41:22.275 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.347 seconds (success: True)
2023-10-04 16:41:22.373 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.191 seconds (success: True)
2023-10-04 16:41:22.417 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.237 seconds (success: True)
2023-10-04 16:41:22.434 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.172 seconds (success: True)
2023-10-04 16:56:22.036 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.220 seconds (success: True)
2023-10-04 16:56:22.087 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.158 seconds (success: True)
2023-10-04 16:56:22.207 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.221 seconds (success: True)
2023-10-04 16:56:22.328 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.179 seconds (success: True)
2023-10-04 16:56:22.336 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.211 seconds (success: True)
2023-10-04 16:56:22.352 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.126 seconds (success: True)
2023-10-04 16:56:25.359 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 3.385 seconds (success: True)
2023-10-04 17:11:22.061 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.244 seconds (success: True)
2023-10-04 17:11:22.089 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.161 seconds (success: True)
2023-10-04 17:11:22.142 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.155 seconds (success: True)
2023-10-04 17:11:22.270 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.120 seconds (success: True)
2023-10-04 17:11:22.323 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.199 seconds (success: True)
2023-10-04 17:11:22.408 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.182 seconds (success: True)
2023-10-04 17:11:25.527 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.554 seconds (success: True)
2023-10-04 17:26:22.050 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.233 seconds (success: True)
2023-10-04 17:26:22.093 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.165 seconds (success: True)
2023-10-04 17:26:22.149 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.164 seconds (success: True)
2023-10-04 17:26:22.269 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.117 seconds (success: True)
2023-10-04 17:26:22.332 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.207 seconds (success: True)
2023-10-04 17:26:22.370 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.143 seconds (success: True)
2023-10-04 17:26:25.217 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.242 seconds (success: True)
2023-10-04 17:41:22.146 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.330 seconds (success: True)
2023-10-04 17:41:22.176 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.248 seconds (success: True)
2023-10-04 17:41:22.184 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.198 seconds (success: True)
2023-10-04 17:41:22.310 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.121 seconds (success: True)
2023-10-04 17:41:22.396 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.168 seconds (success: True)
2023-10-04 17:41:22.402 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.214 seconds (success: True)
2023-10-04 17:41:25.450 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.477 seconds (success: True)
2023-10-04 17:56:22.081 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.265 seconds (success: True)
2023-10-04 17:56:22.111 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.183 seconds (success: True)
2023-10-04 17:56:22.156 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.171 seconds (success: True)
2023-10-04 17:56:22.302 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.140 seconds (success: True)
2023-10-04 17:56:22.349 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.122 seconds (success: True)
2023-10-04 17:56:22.361 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.235 seconds (success: True)
2023-10-04 17:56:25.191 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.218 seconds (success: True)
2023-10-04 18:11:22.010 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.194 seconds (success: True)
2023-10-04 18:11:22.080 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.151 seconds (success: True)
2023-10-04 18:11:22.165 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.129 seconds (success: True)
2023-10-04 18:11:22.299 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.149 seconds (success: True)
2023-10-04 18:11:22.336 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.212 seconds (success: True)
2023-10-04 18:11:22.361 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.134 seconds (success: True)
2023-10-04 18:11:25.190 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.217 seconds (success: True)

Additional information

No response

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

home-assistant · 2023-10-05T00:18:38Z

Hey there @allenporter, mind taking a look at this issue as it has been labeled with an integration (google) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of google can trigger bot actions by commenting:

@home-assistant close Closes the issue.
@home-assistant rename Awesome new title Renames the issue.
@home-assistant reopen Reopen the issue.
@home-assistant unassign google Removes the current integration label and assignees on the issue, add the integration domain after the command.

_{^{(message by CodeOwnersMention)}}

google documentation
google source
_{^{(message by IssueLinks)}}

allenporter · 2023-10-05T03:51:55Z

@bachya TY for the report -- appreciate the detail here. Can you turn up debug for homeassistant.components.calendar as well? I've added new logging there about when alarms are schedule.

allenporter · 2023-10-05T03:59:44Z

I may be seeing this on one of my dev instances as well... Will also try to get debug data myself.

bachya · 2023-10-05T15:19:41Z

Ran another test today with an 8-8:30am event today:

Once again, the calendar entity state changes were delayed:

Interestingly, this time, the simple automation ran, apparently at the correct time?

DEBUG-level logs for homeassistant.components.calendar and homeassistant.components.google:

2023-10-05 07:39:55.775 DEBUG (SyncWorker_0) [homeassistant.components.google] Error reading calendar configuration: [Errno 2] No such file or directory: '/config/google_calendars.yaml'
2023-10-05 07:39:57.425 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.ridwell (2023-10-13 00:00:00-06:00, 2023-10-14 00:00:00-06:00)
2023-10-05 07:39:57.524 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.recollect_waste (2023-10-10 00:00:00-06:00, 2023-10-11 00:00:00-06:00)
2023-10-05 07:39:57.525 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.recollect_waste (2023-10-10 00:00:00-06:00, 2023-10-11 00:00:00-06:00)
2023-10-05 07:39:58.960 DEBUG (SyncWorker_2) [homeassistant.components.google] Error reading calendar configuration: [Errno 2] No such file or directory: '/config/google_calendars.yaml'
2023-10-05 07:39:59.548 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.467 seconds (success: True)
2023-10-05 07:39:59.570 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.birthdays (2023-10-05 00:00:00-06:00, 2023-10-06 00:00:00-06:00)
2023-10-05 07:39:59.571 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.490 seconds (success: True)
2023-10-05 07:39:59.759 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.678 seconds (success: True)
2023-10-05 07:39:59.763 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.peanut_pad_dates (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-05 07:39:59.774 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.693 seconds (success: True)
2023-10-05 07:39:59.780 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.8673_e_55th_dates (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-05 07:39:59.822 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.741 seconds (success: True)
2023-10-05 07:39:59.850 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.bachya1208_gmail_com (2023-10-05 16:30:00-06:00, 2023-10-05 17:30:00-06:00)
2023-10-05 07:39:59.853 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.772 seconds (success: True)
2023-10-05 07:39:59.854 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.guest_entry (2023-10-05 08:00:00-06:00, 2023-10-05 08:30:00-06:00)
2023-10-05 07:39:59.856 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.775 seconds (success: True)
2023-10-05 07:39:59.857 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-05 07:42:00.497 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 07:42:00.497811-06:00, 2023-10-05 07:57:00.497811-06:00) found 0 eligble of 0 active
2023-10-05 07:42:27.076 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 07:42:27.076091-06:00, 2023-10-05 07:57:27.076091-06:00) found 0 eligble of 0 active
2023-10-05 07:50:53.263 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 07:50:53.263523-06:00, 2023-10-05 08:05:53.263523-06:00) found 1 eligble of 1 active
2023-10-05 07:50:53.264 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scheduled next event trigger for 2023-10-05 08:00:00-06:00
2023-10-05 07:54:59.348 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.244 seconds (success: True)
2023-10-05 07:54:59.351 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.peanut_pad_dates (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-05 07:54:59.370 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.268 seconds (success: True)
2023-10-05 07:54:59.456 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.477 seconds (success: True)
2023-10-05 07:54:59.473 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.birthdays (2023-10-05 00:00:00-06:00, 2023-10-06 00:00:00-06:00)
2023-10-05 07:55:00.072 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.128 seconds (success: True)
2023-10-05 07:55:00.073 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.guest_entry (2023-10-05 08:00:00-06:00, 2023-10-05 08:30:00-06:00)
2023-10-05 07:55:00.238 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.161 seconds (success: True)
2023-10-05 07:55:00.265 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.bachya1208_gmail_com (2023-10-05 16:30:00-06:00, 2023-10-05 17:30:00-06:00)
2023-10-05 07:55:00.296 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.151 seconds (success: True)
2023-10-05 07:55:00.299 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.8673_e_55th_dates (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-05 07:55:00.402 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.238 seconds (success: True)
2023-10-05 07:55:00.403 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-05 07:57:00.821 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-05 07:57:00.797750-06:00
2023-10-05 07:57:00.822 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 07:57:00.497811-06:00, 2023-10-05 08:12:00.797750-06:00) found 1 eligble of 1 active
2023-10-05 07:57:00.822 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scheduled next event trigger for 2023-10-05 08:00:00-06:00
2023-10-05 08:00:00.001 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Calendar event @ 2023-10-05 08:00:00-06:00
2023-10-05 08:00:00.001 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Dispatching event: CalendarEvent(start=datetime.datetime(2023, 10, 5, 8, 0, tzinfo=zoneinfo.ZoneInfo(key='America/Denver')), end=datetime.datetime(2023, 10, 5, 8, 30, tzinfo=zoneinfo.ZoneInfo(key='America/Denver')), summary='New Test', description=None, location=None, uid='706347A4-84BD-4B39-A1A1-98055C9CC798', recurrence_id=None, rrule=None)
2023-10-05 08:09:59.261 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.155 seconds (success: True)
2023-10-05 08:09:59.265 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.peanut_pad_dates (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-05 08:09:59.277 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.179 seconds (success: True)
2023-10-05 08:09:59.552 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.572 seconds (success: True)
2023-10-05 08:09:59.570 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.birthdays (2023-10-05 00:00:00-06:00, 2023-10-06 00:00:00-06:00)
2023-10-05 08:10:00.060 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.115 seconds (success: True)
2023-10-05 08:10:00.061 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.guest_entry (2023-10-05 08:00:00-06:00, 2023-10-05 08:30:00-06:00)
2023-10-05 08:10:00.271 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.194 seconds (success: True)
2023-10-05 08:10:00.298 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.bachya1208_gmail_com (2023-10-05 16:30:00-06:00, 2023-10-05 17:30:00-06:00)
2023-10-05 08:10:00.311 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.167 seconds (success: True)
2023-10-05 08:10:00.315 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.8673_e_55th_dates (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-05 08:10:00.421 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.257 seconds (success: True)
2023-10-05 08:10:00.422 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-05 08:12:00.798 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-05 08:12:00.798236-06:00
2023-10-05 08:12:00.798 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 08:12:00.797750-06:00, 2023-10-05 08:27:00.798236-06:00) found 0 eligble of 1 active
2023-10-05 08:18:21.531 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 08:18:21.531000-06:00, 2023-10-05 08:33:21.531000-06:00) found 0 eligble of 1 active
2023-10-05 08:24:59.282 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.302 seconds (success: True)
2023-10-05 08:24:59.300 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.birthdays (2023-10-05 00:00:00-06:00, 2023-10-06 00:00:00-06:00)
2023-10-05 08:24:59.302 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.203 seconds (success: True)
2023-10-05 08:24:59.316 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.210 seconds (success: True)
2023-10-05 08:24:59.319 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.peanut_pad_dates (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-05 08:25:00.102 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.157 seconds (success: True)
2023-10-05 08:25:00.102 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.guest_entry (2023-10-05 08:00:00-06:00, 2023-10-05 08:30:00-06:00)
2023-10-05 08:25:00.289 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.212 seconds (success: True)
2023-10-05 08:25:00.314 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.bachya1208_gmail_com (2023-10-05 16:30:00-06:00, 2023-10-05 17:30:00-06:00)
2023-10-05 08:25:00.325 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.181 seconds (success: True)
2023-10-05 08:25:00.329 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.8673_e_55th_dates (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-05 08:25:00.356 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.192 seconds (success: True)
2023-10-05 08:25:00.357 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-05 08:27:00.799 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-05 08:27:00.799301-06:00
2023-10-05 08:27:00.799 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 08:27:00.798236-06:00, 2023-10-05 08:42:00.799301-06:00) found 0 eligble of 1 active
2023-10-05 08:39:57.108 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.ridwell (2023-10-13 00:00:00-06:00, 2023-10-14 00:00:00-06:00)
2023-10-05 08:39:59.287 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.307 seconds (success: True)
2023-10-05 08:39:59.305 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.birthdays (2023-10-05 00:00:00-06:00, 2023-10-06 00:00:00-06:00)
2023-10-05 08:39:59.307 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.207 seconds (success: True)
2023-10-05 08:39:59.310 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.207 seconds (success: True)
2023-10-05 08:39:59.314 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.peanut_pad_dates (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-05 08:40:00.111 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.167 seconds (success: True)
2023-10-05 08:40:00.633 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.557 seconds (success: True)
2023-10-05 08:40:00.659 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.bachya1208_gmail_com (2023-10-05 16:30:00-06:00, 2023-10-05 17:30:00-06:00)
2023-10-05 08:40:00.670 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.527 seconds (success: True)
2023-10-05 08:40:00.674 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.8673_e_55th_dates (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-05 08:40:00.676 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.512 seconds (success: True)
2023-10-05 08:40:00.678 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-05 08:42:00.799 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-05 08:42:00.799809-06:00
2023-10-05 08:42:00.800 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 08:42:00.799301-06:00, 2023-10-05 08:57:00.799809-06:00) found 0 eligble of 0 active
2023-10-05 08:46:30.153 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 08:46:30.153350-06:00, 2023-10-05 09:01:30.153350-06:00) found 0 eligble of 0 active
2023-10-05 08:54:59.313 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.209 seconds (success: True)
2023-10-05 08:54:59.316 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.peanut_pad_dates (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-05 08:54:59.330 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.231 seconds (success: True)
2023-10-05 08:54:59.593 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.613 seconds (success: True)
2023-10-05 08:54:59.610 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.birthdays (2023-10-05 00:00:00-06:00, 2023-10-06 00:00:00-06:00)
2023-10-05 08:55:00.054 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.110 seconds (success: True)
2023-10-05 08:55:00.278 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.201 seconds (success: True)
2023-10-05 08:55:00.303 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.bachya1208_gmail_com (2023-10-05 16:30:00-06:00, 2023-10-05 17:30:00-06:00)
2023-10-05 08:55:00.312 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.168 seconds (success: True)
2023-10-05 08:55:00.316 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.8673_e_55th_dates (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-05 08:55:00.384 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.220 seconds (success: True)
2023-10-05 08:55:00.385 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-05 08:57:00.800 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-05 08:57:00.800436-06:00
2023-10-05 08:57:00.800 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 08:57:00.799809-06:00, 2023-10-05 09:12:00.800436-06:00) found 0 eligble of 0 active
2023-10-05 09:09:59.259 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Packages data in 0.161 seconds (success: True)
2023-10-05 09:09:59.289 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Peanut Pad Dates data in 0.185 seconds (success: True)
2023-10-05 09:09:59.292 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.peanut_pad_dates (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-05 09:09:59.482 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Birthdays data in 0.502 seconds (success: True)
2023-10-05 09:09:59.500 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.birthdays (2023-10-05 00:00:00-06:00, 2023-10-06 00:00:00-06:00)
2023-10-05 09:10:00.111 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Guest Entry data in 0.167 seconds (success: True)
2023-10-05 09:10:00.271 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED data in 0.195 seconds (success: True)
2023-10-05 09:10:00.295 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.bachya1208_gmail_com (2023-10-05 16:30:00-06:00, 2023-10-05 17:30:00-06:00)
2023-10-05 09:10:00.324 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching REDACTED Dates data in 0.180 seconds (success: True)
2023-10-05 09:10:00.328 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.8673_e_55th_dates (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-05 09:10:00.380 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Colorado Buffaloes data in 0.216 seconds (success: True)
2023-10-05 09:10:00.382 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-05 09:12:00.801 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-05 09:12:00.801581-06:00
2023-10-05 09:12:00.802 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 09:12:00.800436-06:00, 2023-10-05 09:27:00.801581-06:00) found 0 eligble of 0 active
2023-10-05 09:12:08.473 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-05 09:12:08.473595-06:00, 2023-10-05 09:27:08.473595-06:00) found 0 eligble of 0 active

allenporter · 2023-10-05T15:40:37Z

The interesting part is

[homeassistant.components.calendar] Scheduled 1 updates for calendar.guest_entry (2023-10-05 08:00:00-06:00, 2023-10-05 08:30:00-06:00)

So it's definitely scheduling the alarms at the right times but either it's not called or it's not detecting the state correctly when it is called. It's then fixed on the next fetch.

bachya · 2023-10-05T16:28:05Z

Would there be any race condition based on when the next event occurs? This quasi-successful run was for an event more than 30 minutes away, but I think the initial test was 5-10 minutes away... Not sure if that matters.

allenporter · 2023-10-06T03:34:20Z

The way I expect this to work is:

async_write_ha_state runs
cancel any previous alarms
Pull the active or upcoming event from the entity. If its already over, there is nothing left to do. The state should already have been update.
Schedule alarms based on the next or upcoming event start or end
Alarm fires, logging Running %s update. This calls _async_write_ha_state to evaluate and update state

So the alarms can be cancelled. We never see the Running update log which either means the alarm is dropped or it got cancelled up a subsequent async_write_ha_state run and was not rescheduled.

allenporter · 2023-10-06T04:50:35Z

Ah so the issue is the update function calls _async_write_ha_state but it does not reschedule itself again. So it works the first time, and doesn't work after that. I can send a fix.

bachya · 2023-10-07T16:42:40Z

Unfortunately, this is still occurring with 2023.10.1. Scheduled a new test event this morning:

...and state changes were once again delayed:

DEBUG-level logs for homeassistant.components.calendar around this time:

2023-10-07 09:42:02.553 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-07 09:42:02.553316-06:00
2023-10-07 09:42:02.553 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-07 09:42:02.552257-06:00, 2023-10-07 09:57:02.553316-06:00) found 1 eligble of 1 active
2023-10-07 09:42:02.553 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scheduled next event trigger for 2023-10-07 09:45:00-06:00
2023-10-07 09:45:00.000 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Calendar event @ 2023-10-07 09:45:00-06:00
2023-10-07 09:45:00.000 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Dispatching event: CalendarEvent(start=datetime.datetime(2023, 10, 7, 9, 45, tzinfo=zoneinfo.ZoneInfo(key='America/Denver')), end=datetime.datetime(2023, 10, 7, 10, 0, tzinfo=zoneinfo.ZoneInfo(key='America/Denver')), summary='Test', description=None, location=None, uid='B74B6380-EDAF-4F10-B1E7-80096A7E0679', recurrence_id=None, rrule=None)
2023-10-07 09:54:55.872 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.guest_entry (2023-10-07 09:45:00-06:00, 2023-10-07 10:00:00-06:00)
2023-10-07 09:54:55.940 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_1 (2023-10-08 10:30:00-06:00, 2023-10-08 11:30:00-06:00)
2023-10-07 09:54:55.948 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_2 (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-07 09:54:55.953 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-07 09:54:56.824 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_3 (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-07 09:54:58.956 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.birthdays (2023-10-11 00:00:00-06:00, 2023-10-12 00:00:00-06:00)
2023-10-07 09:57:02.554 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-07 09:57:02.554194-06:00
2023-10-07 09:57:02.554 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-07 09:57:02.553316-06:00, 2023-10-07 10:12:02.554194-06:00) found 0 eligble of 1 active
2023-10-07 10:09:55.758 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_1 (2023-10-08 10:30:00-06:00, 2023-10-08 11:30:00-06:00)
2023-10-07 10:09:55.862 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-07 10:09:55.910 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_2 (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-07 10:09:56.812 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_3 (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-07 10:09:59.027 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.birthdays (2023-10-11 00:00:00-06:00, 2023-10-12 00:00:00-06:00)
2023-10-07 10:12:02.554 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-07 10:12:02.554675-06:00
2023-10-07 10:12:02.555 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-07 10:12:02.554194-06:00, 2023-10-07 10:27:02.554675-06:00) found 0 eligble of 0 active
2023-10-07 10:24:41.688 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.ridwell (2023-10-13 00:00:00-06:00, 2023-10-14 00:00:00-06:00)
2023-10-07 10:24:55.733 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_1 (2023-10-08 10:30:00-06:00, 2023-10-08 11:30:00-06:00)
2023-10-07 10:24:55.907 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_2 (2024-06-07 00:00:00-06:00, 2024-06-08 00:00:00-06:00)
2023-10-07 10:24:55.928 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.colorado_buffaloes (2023-10-07 16:30:00-06:00, 2023-10-07 19:30:00-06:00)
2023-10-07 10:24:56.855 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.redacted_3 (2023-10-18 10:00:00-06:00, 2023-10-18 13:00:00-06:00)
2023-10-07 10:24:59.018 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 2 updates for calendar.birthdays (2023-10-11 00:00:00-06:00, 2023-10-12 00:00:00-06:00)
2023-10-07 10:27:02.555 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Refresh events @ 2023-10-07 10:27:02.555628-06:00
2023-10-07 10:27:02.555 DEBUG (MainThread) [homeassistant.components.calendar.trigger] Scan events @ [2023-10-07 10:27:02.554675-06:00, 2023-10-07 10:42:02.555628-06:00) found 0 eligble of 0 active

It does appear that the automation trigger issue has been addressed:

allenporter · 2023-10-08T00:10:46Z

FWIW nothing changed here for automation triggers. Maybe the only thing i want to mention, just in case, is that the integration only refreshes data from the server every 15 minutes so if you change something on the server side it needs to be updated/refreshed before it will fire.

I can see in your example:

2023-10-07 09:54:55.872 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.guest_entry (2023-10-07 09:45:00-06:00, 2023-10-07 10:00:00-06:00)

But then the alarm at 2023-10-07 10:00:00-06:00 never fires.

If you capture this again it would be also helpful to have homeassistant.components.google debug logs since it may show when the update coordinator is refreshing.

I'll keep looking on my own test instance for this...

allenporter · 2023-10-08T02:48:11Z

I'm not sure what to do besides add more logging. I can see this happening where it triggers a few minutes behind on my test docker instance, but in my local developer build instance it always runs fine. I'm adding some debugging like what I have locally.

bachya · 2023-10-08T17:53:32Z

FWIW nothing changed here for automation triggers. Maybe the only thing i want to mention, just in case, is that the integration only refreshes data from the server every 15 minutes so if you change something on the server side it needs to be updated/refreshed before it will fire.

Ah, good reminder—it's entirely possible that in some circumstances, I created an event that was 2-3 minutes away...

allenporter · 2023-10-15T20:27:49Z

I have seen this happening in a development environment and with the added extra debugging it seems like it's still just not firing the alarms at all when it should. The alarm at

2023-10-15 11:53:46.249 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Public Recurrence Test data in 0.277 seconds (success: True)
2023-10-15 11:53:46.253 DEBUG (MainThread) [homeassistant.components.calendar] Clearing calendar.public_recurrence_test alarms (2)
2023-10-15 11:53:46.255 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.public_recurrence_test (2023-10-15 11:30:00-07:00, 2023-10-15 12:00:00-07:00)
2023-10-15 12:08:46.352 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Public Recurrence Test data in 0.381 seconds (success: True)
2023-10-15 12:08:46.356 DEBUG (MainThread) [homeassistant.components.calendar] Clearing calendar.public_recurrence_test alarms (2)
2023-10-15 12:08:46.359 DEBUG (MainThread) [homeassistant.components.calendar] Scheduled 1 updates for calendar.public_recurrence_test (2023-10-15 12:00:00-07:00, 2023-10-15 12:30:00-07:00)

So it scheduled an alarm for 2023-10-15 12:00:00-07:00 which never ran.

From the diagnostics, the timezones look all fine:

  "data": {
    "now": "2023-10-15T13:12:36.770097-07:00",
    "timezone": "America/Los_Angeles",
    "system_timezone": "PDT",

allenporter · 2023-10-15T22:27:34Z

Found the issue while talking over with bdraco, its because there is a shared mutable list class var so the alarms for calendars are clobbering each other. I wasn't able to reproduce locally since i only had one local calendar.

home-assistant bot added the integration: google label Oct 5, 2023

home-assistant bot assigned allenporter Oct 5, 2023

allenporter mentioned this issue Oct 6, 2023

Fix bug in calendar state where alarms due to alarms not scheduled #101510

Merged

20 tasks

frenck closed this as completed in #101510 Oct 6, 2023

bachya reopened this Oct 7, 2023

bachya changed the title ~~Google Calendar calendar entity (a) delayed in changing state and (b) fails as trigger~~ Google Calendar calendar entity delayed in changing state Oct 7, 2023

allenporter mentioned this issue Oct 8, 2023

Add additional calendar state alarm debugging #101631

Merged

20 tasks

allenporter mentioned this issue Oct 15, 2023

Fix bug in calendar state transitions #102083

Merged

20 tasks

allenporter closed this as completed in #102083 Oct 15, 2023

github-actions bot locked and limited conversation to collaborators Nov 15, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Google Calendar `calendar` entity delayed in changing state #101431

Google Calendar `calendar` entity delayed in changing state #101431

bachya commented Oct 5, 2023 •

edited

Loading

home-assistant bot commented Oct 5, 2023

allenporter commented Oct 5, 2023

allenporter commented Oct 5, 2023

bachya commented Oct 5, 2023

allenporter commented Oct 5, 2023 •

edited

Loading

bachya commented Oct 5, 2023

allenporter commented Oct 6, 2023

allenporter commented Oct 6, 2023

bachya commented Oct 7, 2023 •

edited

Loading

allenporter commented Oct 8, 2023

allenporter commented Oct 8, 2023

bachya commented Oct 8, 2023

allenporter commented Oct 15, 2023

allenporter commented Oct 15, 2023

Google Calendar calendar entity delayed in changing state #101431

Google Calendar calendar entity delayed in changing state #101431

Comments

bachya commented Oct 5, 2023 • edited Loading

The problem

What version of Home Assistant Core has the issue?

What was the last working version of Home Assistant Core?

What type of installation are you running?

Integration causing the issue

Link to integration documentation on our website

Diagnostics information

Example YAML snippet

Anything in the logs that might be useful for us?

Additional information

home-assistant bot commented Oct 5, 2023

allenporter commented Oct 5, 2023

allenporter commented Oct 5, 2023

bachya commented Oct 5, 2023

allenporter commented Oct 5, 2023 • edited Loading

bachya commented Oct 5, 2023

allenporter commented Oct 6, 2023

allenporter commented Oct 6, 2023

bachya commented Oct 7, 2023 • edited Loading

allenporter commented Oct 8, 2023

allenporter commented Oct 8, 2023

bachya commented Oct 8, 2023

allenporter commented Oct 15, 2023

allenporter commented Oct 15, 2023

Google Calendar `calendar` entity delayed in changing state #101431

Google Calendar `calendar` entity delayed in changing state #101431

bachya commented Oct 5, 2023 •

edited

Loading

allenporter commented Oct 5, 2023 •

edited

Loading

bachya commented Oct 7, 2023 •

edited

Loading