core: Platform time and time_pattern triggered automations are executed twice

The problem

Any automation that is triggered with a hardcoded time trigger or time_pattern is executed twice. The automation triggers at the right time and one second before the right time. As a result, reports of duplicate automations appear in the log.

This happens when an automation is triggered with

- platform: time

or

- platform: time_trigger

Automations that are time triggered but use this:

  - platform: template
    value_template: >-
      {{ state_attr('input_datetime.waste_notification', 'timestamp') | timestamp_custom('%H:%M', false) == states('sensor.time') }}

do not have this problem.

Environment

  • Home Assistant Core release with the issue: 0.114.0
  • Last working Home Assistant Core release (if known): 0.113.x
  • Operating environment (OS/Container/Supervised/Core): HassOS 4.12 in VMware ESXi 7
  • Integration causing this issue: Automation
  • Link to integration documentation on our website: https://www.home-assistant.io/integrations/automation/

Problem-relevant configuration.yaml

- id: update_otgw_hourly_with_outside_temp_from_weather_integration_for_otc
  alias: 'Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC' # OTC is Outside Temperature Control
  trigger:
    platform: time_pattern
    minutes: "/15"
  mode: single
  action:
    service: opentherm_gw.set_outside_temperature
    data_template:
      gateway_id: otgw
      temperature: >-
        {{ state_attr( 'weather.thuis', 'temperature') }}

and

 - id: enable_pump_at_1_00
   alias: 'Schakel pomp vloerverwarming in om 1:00'
   trigger:
   - platform: time
     at: "01:00:00"
   condition: []
   action:
     - service: light.turn_on # Plug is presented as a light, not as a switch
       entity_id: light.stekker_vloerverwarming # Plug is used to enable the floor heating pump
     - delay:
         hours: 1
     - service: light.turn_off # Plug is presented as a light, not as a switch
       entity_id: light.stekker_vloerverwarming # Plug is used to disable the floor heating pump

Traceback/Error logs

2020-08-18 06:15:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running
2020-08-18 06:30:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running
2020-08-18 06:45:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running
2020-08-18 07:00:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running
2020-08-18 07:15:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running
2020-08-18 07:45:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running
2020-08-18 08:00:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running
2020-08-18 08:15:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running
2020-08-18 08:30:00 WARNING (MainThread) [homeassistant.components.automation.update_otgw_elk_kwartier_met_buitentemperatuur_van_accuweather_of_met_no_voor_otc] Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC: Already running

Additional information

Two fragments from the logbook.

First one is an automation that uses time_pattern

8:45:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
8:44:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
8:30:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
8:29:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
8:15:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
8:14:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
8:00:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
7:59:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
7:45:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
7:44:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
7:30:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
7:15:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
7:14:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
7:00:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
6:59:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
6:45:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
6:44:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
6:30:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
6:29:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
6:15:00 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered
6:14:59 Update OTGW elk kwartier met buitentemperatuur van AccuWeather of MET.no voor OTC has been triggered

Second one is from an automation that uses a hardcoded timestamp as a trigger

1:00:00 - Schakel pomp vloerverwarming in om 1:00 has been triggered
0:59:59 - Schakel pomp vloerverwarming in om 1:00 has been triggered

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Comments: 43 (37 by maintainers)

Most upvoted comments

As a side note, the automation integration is updating its last_triggered attribute directly instead of using the script helper’s last_triggered attribute (like the script integration does.) This is causing two problems: 1) there are two state change events when an automation is triggered instead of just one, and 2) the last_triggered attribute is getting updated, even if the actions don’t actually run (e.g., “Already running”.) I knew this was an issue before but I didn’t change it because I wasn’t sure if people were potentially counting on the automation’s last_triggered attribute updating when a trigger fires (and the conditions are met), even if the actions don’t end up running (due to the mode limitation.) Maybe this should be changed after all.

Just an FYI … I went ahead and did this in #39323.

+1
pnbruckner on Aug 27, 2020

Just an FYI, when we relied on time changed events for our pattern listeners, we had a precision of 1 second. Anything more precise is a bonus but not a requirement

+1
balloob on Aug 27, 2020

Do you mean like this?

diff --git a/homeassistant/helpers/event.py b/homeassistant/helpers/event.py
index ba0b07a207..334ad3c676 100644
--- a/homeassistant/helpers/event.py
+++ b/homeassistant/helpers/event.py
@@ -996,14 +996,15 @@ def async_track_utc_time_change(
 
         calculate_next(now + timedelta(seconds=1))
 
+        now = time.time()
         cancel_callback = hass.loop.call_at(
-            hass.loop.time() + next_time.timestamp() - time.time(),
+            hass.loop.time() + next_time.timestamp() - now,
             pattern_time_change_listener,
         )
 
+    now = time.time()
     cancel_callback = hass.loop.call_at(
-        hass.loop.time() + next_time.timestamp() - time.time(),
-        pattern_time_change_listener,
+        hass.loop.time() + next_time.timestamp() - now, pattern_time_change_listener,
     )
 
     @callback

@mvandek could you try that?

+1
balloob on Aug 26, 2020
Read more comments on GitHub
← core: Platform support not supported openhome - Volumio / Openhome integration
core: Platform TOD is not updating properly on sunset →