Google Calendar no longer changing state at start of events

[joewesch]

The problem

I have a few automations that use the Google Calendar integration as triggers. Recently I upgraded from 2023.8.4 to 2023.9.2 and now the state of my events are staying as off despite the time being correct for them to be on.

For example, I have an event every evening from 9:00pm-9:05pm to run the script to turn on the A/C in my bedroom. I watched my clock tick over and the event stayed in the off state. I then reloaded the integration at about 9:03pm and the state finally changed to on. You can see the events from the past 2 nights in this screenshot of the logbook:

I set these up a long time ago, so I thought maybe I would need to update the auth or something, so I did that next. I deleted the integration completely and went through the setup again to make sure it could auth correctly. I then watched the exact same thing happen to another one of my calendar triggers for my hue lights that was supposed to trigger at 9:40pm. I turned on debug logging for the integration and restarted it shortly after 9:40 and will share the logs below. You can see in the log output that after I reloaded the integration the automation finally kicked off and in the UI the state was finally set to on.

What version of Home Assistant Core has the issue?

core-2023.9.2

What was the last working version of Home Assistant Core?

core-2023.8.4

What type of installation are you running?

Home Assistant Container

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?

2023-09-18 21:40:36.737 INFO (MainThread) [homeassistant.components.calendar] Setting up calendar.google
2023-09-18 21:40:38.150 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Daily Holidays data in 0.703 seconds (success: True)
2023-09-18 21:40:38.592 WARNING (MainThread) [homeassistant.helpers.entity] Updating state for calendar.daily_holidays (<class 'homeassistant.components.google.calendar.GoogleCalendarEntity'>) took 0.442 seconds. Please create a bug report at https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+google%22
2023-09-18 21:40:38.655 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Driveway Lights data in 1.208 seconds (success: True)
2023-09-18 21:40:38.670 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Hue lights data in 1.223 seconds (success: True)
2023-09-18 21:40:38.714 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Bedroom AC data in 1.268 seconds (success: True)
2023-09-18 21:40:38.731 INFO (MainThread) [homeassistant.components.automation.google_calendar_sunset] Downstairs Sunset: Running automation actions
2023-09-18 21:40:38.731 INFO (MainThread) [homeassistant.components.automation.google_calendar_sunset] Downstairs Sunset: Executing step call service
2023-09-18 21:40:38.736 INFO (MainThread) [homeassistant.components.script.sunset] Sunset: Running script sequence
2023-09-18 21:40:38.736 INFO (MainThread) [homeassistant.components.script.sunset] Sunset: Executing step call service
2023-09-18 21:40:39.353 INFO (MainThread) [homeassistant.components.automation.google_calendar_sunset] Downstairs Sunset: Executing step call service
2023-09-18 21:40:39.355 INFO (MainThread) [homeassistant.components.script.sunset_blooms] Sunset Blooms: Running script sequence
2023-09-18 21:40:39.355 INFO (MainThread) [homeassistant.components.script.sunset_blooms] Sunset Blooms: Test condition state: True
2023-09-18 21:40:39.355 INFO (MainThread) [homeassistant.components.script.sunset_blooms] Sunset Blooms: Executing step call service
2023-09-18 21:40:39.475 INFO (MainThread) [homeassistant.components.script.sunset_blooms] Sunset Blooms: Executing step call service
2023-09-18 21:40:39.598 INFO (MainThread) [homeassistant.components.automation.google_calendar_sunset] Downstairs Sunset: Executing step call service
2023-09-18 21:40:39.600 INFO (MainThread) [homeassistant.components.script.sunset_couch] Sunset Couch: Running script sequence
2023-09-18 21:40:39.600 INFO (MainThread) [homeassistant.components.script.sunset_couch] Sunset Couch: Test condition state: False
2023-09-18 21:40:39.601 INFO (MainThread) [homeassistant.components.automation.google_calendar_sunset] Downstairs Sunset: Executing step call service

Additional information

No response

[home-assistant]

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]

@joewesch thank you for the report. Would you be look up the calendar state in Developer Tools? I'm interested in looking at the start/end time for the events.

[joewesch]

Hello Allen, I actually took a screenshot of all of my calendars at 9:02pm after it had failed to change state. Here it is:

[joewesch]

As an additional update, I also realized finally that there was a Calendar trigger and I have changed all of my automations to use that instead of State triggers. As I said, I created these automations a long time ago so I was unaware of the new triggers and they have been working just fine with the state changes up until now. We can keep this issue open if you'd like if the change to the state was unintentional and should still be corrected.

[allenporter]

Yeah, the state should still work so this looks like a bug. (My impression is the screenshot you have is for the calendar state and not the automation state, so it should keep working.) There was a change related to this logic in #98037 meant to fix a variety of other calendar issues, so definitely i want to understand this more. I have a google calendar with a single event like this and am not seeing this same issue.

Would you also be able to capture the state when the calendar is off some time before it goes on?

I notice that the calendar is going unavailable for some periods. I wonder if something is not recovering properly during that time... Do you know what the unavailable part is about?

[joewesch]

Yes, I did see that PR while researching to see if this was a known issue. Do you know when that will be released? I can surely test it.

Here is a screenshot of their current state:

Yes, I noticed the unavailable states as well and I originally chalked it up to some kind of issue with the sync. I don't know what would have caused it, though, and the only indication in the logs is that warning about the state taking a whopping 0.442 seconds lol.

Updating state for calendar.daily_holidays (<class 'homeassistant.components.google.calendar.GoogleCalendarEntity'>) took 0.442 seconds. Please create a bug report at https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue+label%3A%22integration%3A+google%22

[joewesch]

Another thing I tried was deleting the repeating event and recreating it thinking that I had hit the limit of 730 occurrences, but there was no change.

[allenporter]

My impression is that PR is in 2023.9.X -- its the only major calendar change.

I noticed before you were capturing the logs with debug on which is really helpful. Would you be able to keep that running for longer and we can see what it looks like after 24 hours? I worry otherwise I may need to add additional logging or diagnostics in able to track this down.

I appreciate all the attempts to diagnose the problem, but this definitely just looks like a home assistant bug in calendar so no need to attempt to do any more things like deleting events, deleting the integration, reloading, etc.

[joewesch]

Thanks for the info and assist. I'll turn debug logging back on and report back tomorrow.

[joewesch]

So, the debug logs don't seem to be much help. They just repeat the same messages every 15 minutes as expected:

2023-09-19 19:25:38.397 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Driveway Lights data in 0.247 seconds (success: True)
2023-09-19 19:25:38.586 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Hue lights data in 0.443 seconds (success: True)
2023-09-19 19:26:03.965 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Daily Holidays data in 0.820 seconds (success: True)
2023-09-19 19:26:04.629 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Bedroom AC data in 0.141 seconds (success: True)
2023-09-19 19:40:38.522 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Hue lights data in 0.379 seconds (success: True)
2023-09-19 19:40:38.562 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Driveway Lights data in 0.411 seconds (success: True)
2023-09-19 19:41:03.866 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Daily Holidays data in 0.722 seconds (success: True)
2023-09-19 19:41:04.538 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Bedroom AC data in 0.165 seconds (success: True)
2023-09-19 19:55:38.402 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Driveway Lights data in 0.252 seconds (success: True)
2023-09-19 19:55:38.445 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Hue lights data in 0.303 seconds (success: True)
2023-09-19 19:56:03.883 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Daily Holidays data in 0.740 seconds (success: True)
2023-09-19 19:56:04.509 DEBUG (MainThread) [homeassistant.components.google.calendar] Finished fetching Bedroom AC data in 0.119 seconds (success: True)
...

The entities also stopped showing as unavailable so I guess I'll need to keep the debug logging on until I notice it happen again.

As for the state of the entities, they are still not all consistent.

For the first entity that controls my bedroom A/C the state changes exactly on time with the event start and end:

The entity that controls my lights however is either slightly behind (38 seconds late) or just not there at all. Over the last 24 hours there were 3 events - 9:40pm, 6:00am and 6:30am - and it only changed state for 1 of them:

Here are the 2 events on my calendar that it didn't change state for this morning:

Despite the lack of state change, those automations still triggered correctly since I changed them to the Calendar trigger rather than the State trigger.

[allenporter]

Ok so the one that was broken before is now working, and the other ones saw an issue? (But didn't go unavailable)

The fact that the data looks succeeded is actually helpful for understanding what is and isn't working, thank you.

[allenporter]

Are these all dedicated calendars in Google calendars or using the .yaml file for search? The implementation of these is a little different.

[joewesch]

Ok so the one that was broken before is now working, and the other ones saw an issue? (But didn't go unavailable)

Correct.

I'm not sure what you mean by "using the .yaml file for search", but these are separate dedicated google calendars:

Inside my automations I then have a condition that verifies that the message is a match to either stop or continue:

condition: template
value_template: "{{is_state_attr('calendar.hue_lights', 'message', 'sunrise_downstairs') }}"

[Wireheadbe]

I have a similar thing.. I have, as example, an automation to close the covers at 18:30 (the event covers from 18:30 until 19:00 - so 30 minutes). These always triggered on time, at the start. Now, they trigger seemingly randomly. Eg. at 18:43.

Very strange!

[joewesch]

The Bedroom A/C calendar is back to not reporting any state changes despite having 2 events in the last 24 hours.

[benganellison]

I have something similar that stoped working on latest update, but with attribute offset_reached which is reached at the time of the event and not at the time of the offset

I have a sunrise automation in node-red that is triggered with an offset to the calendar event. But to me it sounds like this is the same issue. The question is if this really is related to calendar or to general attribute templating

for reference my template sensor config:

sensor:
  - platform: template
    sensors:
      wakeup_start_time_masterbedroom_calendar:
        value_template: "{{ is_state_attr('calendar.belysning_masterbedroom', 'offset_reached', true) }}"

and calendar config

  - device_id: belysning_masterbedroom
    ignore_availability: true
    name: Belysningskalender sovrum
    search: "Föräldrar"

[Wireheadbe]

This morning, my automations seemed to trigger when they should trigger. Maybe this was something at Google instead?

[allenporter]

@joewesch Aside: be careful with your example since its using a calendar trigger, but reading the event entity state. Check out https://www.home-assistant.io/integrations/calendar/#automation-recipes for examples of using trigger data instead of reading the calendar entity state. This is not related to the issue described here, but I am just mentioning it as a tangential issue for the automation you're using to be more technically correct -- it would only matter in practice if there are multiple events at the same time. It sounds like it would coincidentally workaround the bug we're seeing here, however, but still want to fix the main issue here.

Back to the issue at hand here, my current thought is I may need to add additional logging to uncover what is happening in your case related to #98037

Others: If you are reporting an issue here, it would be helpful to focus on the calendar entity state transitions on/off and relevant debug logs (any downstream automation/template aspects of this are higher level, so we need to ignore those and go deeper into the entity state in the developer tools as some of the discussions above). Thanks!

I'll consider some additional debug logging.

[ctml91]

Same issue here. The state changes exact 13 minutes and 39 seconds after the original calendar start time. See attached screenshots of states before and after. You can also see in the before screenshot the last time it triggered was 7:43:39 pm for a 7:30 pm calendar event.

[thiagopbarnabe]

I was having the same "bug". All my automations based on calendar sometimes stop working.

I was trying to understand why then after reboot home assistant I found this on my log.
2023-11-16 14:55:17.575 ERROR (MainThread) [homeassistant.components.automation.nova_automacao_teste] Got error 'Entity does not exist calendar.thiagopbarnabe_gmail_com or is not a calendar entity' when setting up triggers for Nova Automação teste

Then I disabled the automation and enable it again. After I did this it started to working again.
I don't know if this was caused by this integration been more slow to start or if Home assistant Core changed how automations are created and started.

[allenporter]

@thiagopbarnabe Can you please file a separate issue report? Seems like a valid issue to track, though its not on topic here.

I believe the original issue being discussed here has been resovled by the same issue tackled in #101431 being fixed. @joewesch can you confirm if things look better after 2023.11?

[benganellison]

I'm running 10.5 and it still isn't working

[allenporter]

@benganellison correct, 2023.11.X includes the fix i referenced

[joewesch]

Thanks for the update, Allen. I am not at home currently, so I will set a reminder to upgrade and test in a couple weeks. I will provide an update afterward.

[benganellison]

Will update as soon as I get home and test 😁

[benganellison]

still doesn't work, offset should had been reached now

Offset Reached: {{state_attr('calendar.belysning_masterbedroom', 'offset_reached')}}

gives

Offset Reached: False

fiddeling with the calendar (refreshing it in the gui) forced a re-check it looks like and now it is reached

[allenporter]

Can we tackle offset reached issue in a separate issue report?

This is only supported in yaml given event triggers, and isn't the main topic here I believe, and so I don't want to lose track of that.

[joewesch]

Hello Allen, I was finally able to confirm that the state is changing on time now with the event start/stop in v2023.11.3. I will go ahead and close this issue as solved. Thanks for your help!