core: Google Calendar no longer changing state at start of events

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:

Screenshot 2023-09-18 at 9 51 34 PM

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

About this issue

Original URL
State: closed
Created 9 months ago
Reactions: 1
Comments: 28 (9 by maintainers)

Most upvoted comments

@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 https://github.com/home-assistant/core/pull/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.

allenporter on Sep 23, 2023