Triggering off input_datetime triggering minutes late

chris8 · June 1, 2022, 8:23pm

Hi everyone,

For the past couple years I have been using an automation to turn on/off my coffee maker in the morning. The on/off times are set via input_datetime helpers. This worked great, triggering exactly at the specified time, up until April 9, 2022, when the triggers started to drift.

Here is my automation:

alias: Coffee Maker Scheduled
description: ''
trigger:
  - platform: time
    at: input_datetime.coffee_start_time
    id: StartCoffee
  - platform: time
    at: input_datetime.coffee_stop_time
    id: StopCoffee
condition:
  - condition: state
    entity_id: input_boolean.coffee_use_schedule
    state: 'on'
action:
  - choose:
      - conditions:
          - condition: trigger
            id: StartCoffee
          - condition: state
            entity_id: input_boolean.away_mode
            state: 'off'
        sequence:
          - service: switch.turn_on
            target:
              entity_id: switch.coffee_maker
            data: {}
      - conditions:
          - condition: trigger
            id: StopCoffee
        sequence:
          - service: switch.turn_off
            target:
              entity_id: switch.coffee_maker
            data: {}
    default: []
mode: single

The start time has been ‘6:00am’ and the end time has been ‘12:00pm’ essentially forever. The automation turns on the coffee maker in the morning, and then most mornings we will manually turn it off when the coffee is gone, or else if we haven’t turned it off by noon it will automatically turn off.

Here are the start/top times:

April 7: 6:00:00am - 11:00:20am
(up until this point, the trigger times have been exact)

April 8: 6:00am - 6:20pm
(it missed the stop trigger and we manually turned it off at 6:20pm… it appears Home Assistant was down for a while this day. I don’t remember what had happened, but I’m assuming I performed a Home Assistant update)

April 09: 06:01:07am - 12:00:25pm

April 10: 06:01:55am - 10:59:35am

April 11: 06:03:30am - 10:07:29am

April 12: 06:04:42am - 09:23:44am

April 13: 06:01:17am - 10:47:15am

April 14: 06:04:43am - 10:43:09am

. . . .

April 23: 06:02:30am - 12:00:03pm

April 24: 06:03:37am - 12:04:43pm

April 25: 06:01:43am - 12:02:54pm

…

June 01: 06:16:37am - 12:10:04pm

Ever since April 8th the trigger times have been drifting farther and farther away. If I had to guess, I would say this started happening when I updated to 2022.4, but I do not know for sure that I updated that day. The timeline would fit, though.

Has anyone seen this before? Any ideas on how to make my automations trigger at the correct time?

Thanks!

tom_l · June 1, 2022, 8:35pm

What is your system time?

Are your DNS settings correct (Settings > System > Network)?

If not you will not be able to reach the NTP service to keep your clock in sync.

chris8 · June 1, 2022, 8:45pm

Thanks for the super quick response!

System time is right. I’m running Home Assistant via the docker container:

> ntpdate -q pool.ntp.org && docker exec home-assistant date && docker exec mariadb date && date
server 66.220.9.122, stratum 1, offset 4.748737, delay 0.08263
server 129.250.35.250, stratum 2, offset 4.749684, delay 0.04179
server 45.55.58.103, stratum 2, offset 4.751274, delay 0.06126
server 50.18.44.198, stratum 2, offset 4.751562, delay 0.07721
 1 Jun 15:43:51 ntpdate[3288014]: step time server 66.220.9.122 offset 4.748737 sec

Wed Jun  1 15:43:52 CDT 2022 (HomeAssistant)

Wed Jun  1 20:43:52 UTC 2022 (MariaDb)

Wed 01 Jun 2022 03:43:52 PM CDT (Host)

I’d think even if the time was wrong that the Home Assistant log would show the ‘correct’ trigger time, but that the time would not be accurate. The logs show that it triggers it at odd times:

2022-06-01 06:16:36 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Running automation actions
2022-06-01 06:16:36 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 1: Running automation actions
2022-06-01 06:16:36 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 1: Executing step call service

chris8 · June 1, 2022, 9:10pm

I just tried creating a new automation with a scheduled start time, and it started exactly on time.

I tried changing my coffee start time to trigger ‘a minute from now’ and it started exactly on time.

I tried changing the coffee start/stop time to trigger ‘a couple minutes from now’ and to end a few minutes after that. It started and ended exactly on time.

So I guess I need to wait until tomorrow at 6:00 am to see what time it is going to start. I have previously tried changing the end time to 11:59am (instead of noon) and it didn’t help, but maybe tomorrow will be different

My logs are full of

2022-06-01 06:15:53 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-01 06:16:03 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-01 06:16:13 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-01 06:16:23 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-01 06:16:33 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-01 06:16:36 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Running automation actions
2022-06-01 06:16:36 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 1: Running automation actions
2022-06-01 06:16:36 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 1: Executing step call service
2022-06-01 06:16:43 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05

I don’t think this is the issue, as there seems to be plenty of time between the ping warnings for other things to occur, I’ve been using the ping sensor much longer than I’ve been having issues, and when the automation does occur it is not immediately after a ping timeout.

However, if the trigger time is off tomorrow I’ll try increasing the ping interval to see if that helps.

chris8 · June 2, 2022, 5:06pm

So today the coffee maker did not turn on at 6:00am. My partner wanted her coffee, so she manually switch on the coffee at 6:05:25am. The automation then triggered at 6:05:43:

2022-06-02 06:05:27 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-02 06:05:37 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-02 06:05:43 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Running automation actions
2022-06-02 06:05:43 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 1: Running automation actions
2022-06-02 06:05:43 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 1: Executing step call service
2022-06-02 06:05:47 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05

I don’t know if it is just a coincidence or not that the automation triggered so close to the manual trigger. I would think they would be completely unrelated, as the trigger itself should have no connection to the result of the automation action.

The noon shutoff was 5m43s late… the exact same offset as the start:

2022-06-02 12:05:32 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-02 12:05:42 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-02 12:05:43 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Running automation actions
2022-06-02 12:05:43 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 2: Running automation actions
2022-06-02 12:05:43 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 2: Executing step call service
2022-06-02 12:05:52 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05
2022-06-02 12:06:02 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating ping binary_sensor took longer than the scheduled update interval 0:00:05

I’m increasing the ‘ping’ interval and turning on ‘debug’ logging. We’ll see what happens tomorrow.

chris8 · June 2, 2022, 6:55pm

Set start time to 1:00PM, end time to 1:20PM.

Started right on time, but ended 1:25:27pm, 5m27s late.

Interestingly, in the DEBUG level Home-Assistant log there was not a single event from 1:16 to 1:22:

2022-06-02 13:16:35 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.15.67 data in 0.148 seconds (success: True)
2022-06-02 13:22:05 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('172.25.0.1', 54780): b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nST: upnp:rootdevice\r\nMX: 5\r\n\r\n'

So absolutely nothing happened at 1:20, when it was supposed to trigger. 5 minutes later it finally decided to trigger:

2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.15.64 data in 0.020 seconds (success: True)
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.15.54 data in 0.022 seconds (success: True)
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Automation triggered by time set in input_datetime.coffee_stop_time
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=Coffee Maker Scheduled, entity_id=automation.coffee_maker_scheduled, source=time set in input_datetime.coffee_stop_time>
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.coffee_maker_scheduled, old_state=<state automation.coffee_maker_scheduled=on; last_triggered=2022-06-02T13:00:00.004469-05:00, mode=single, current=0, id=1646408179088, friendly_name=Coffee Maker Scheduled @ 2022-06-02T12:09:50.868094-05:00>, new_state=<state automation.coffee_maker_scheduled=on; last_triggered=2022-06-02T13:25:27.394558-05:00, mode=single, current=1, id=1646408179088, friendly_name=Coffee Maker Scheduled @ 2022-06-02T12:09:50.868094-05:00>>
2022-06-02 13:25:27 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Running automation actions
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140581399855312] Sending {"id":74,"type":"event","event":{"event_type":"automation_triggered","data":{"name":"Coffee Maker Scheduled","entity_id":"automation.coffee_maker_scheduled","source":"time set in input_datetime.coffee_stop_time"},"origin":"LOCAL","time_fired":"2022-06-02T18:25:27.394367+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}}}
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140581399855312] Sending {"id":74,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"automation.coffee_maker_scheduled","old_state":{"entity_id":"automation.coffee_maker_scheduled","state":"on","attributes":{"last_triggered":"2022-06-02T18:00:00.004469+00:00","mode":"single","current":0,"id":"1646408179088","friendly_name":"Coffee Maker Scheduled"},"last_changed":"2022-06-02T17:09:50.868094+00:00","last_updated":"2022-06-02T18:00:00.058347+00:00","context":{"id":"018125930103f0b56a2312b4d1c67048","parent_id":null,"user_id":null}},"new_state":{"entity_id":"automation.coffee_maker_scheduled","state":"on","attributes":{"last_triggered":"2022-06-02T18:25:27.394558+00:00","mode":"single","current":1,"id":"1646408179088","friendly_name":"Coffee Maker Scheduled"},"last_changed":"2022-06-02T17:09:50.868094+00:00","last_updated":"2022-06-02T18:25:27.394636+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-06-02T18:25:27.394636+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}}}
2022-06-02 13:25:27 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 2: Running automation actions
2022-06-02 13:25:27 INFO (MainThread) [homeassistant.components.automation.coffee_maker_scheduled] Coffee Maker Scheduled: Choose at step 1: choice 2: Executing step call service
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=switch, service=turn_off, service_data=entity_id=['switch.coffee_maker']>
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140581399855312] Sending {"id":74,"type":"event","event":{"event_type":"call_service","data":{"domain":"switch","service":"turn_off","service_data":{"entity_id":["switch.coffee_maker"]}},"origin":"LOCAL","time_fired":"2022-06-02T18:25:27.398680+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}}}
2022-06-02 13:25:27 DEBUG (Recorder) [homeassistant.components.recorder] Processing task: EventTask(event=<Event call_service[L]: domain=switch, service=turn_off, service_data=entity_id=['switch.coffee_maker']>)
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.protocol] 192.168.15.54 >> {"system": {"set_relay_state": {"state": 0}}}
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.protocol] 192.168.15.54 << {'system': {'set_relay_state': {'err_code': 0}}}
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.coffee_maker_scheduled, old_state=<state automation.coffee_maker_scheduled=on; last_triggered=2022-06-02T13:25:27.394558-05:00, mode=single, current=1, id=1646408179088, friendly_name=Coffee Maker Scheduled @ 2022-06-02T12:09:50.868094-05:00>, new_state=<state automation.coffee_maker_scheduled=on; last_triggered=2022-06-02T13:25:27.394558-05:00, mode=single, current=0, id=1646408179088, friendly_name=Coffee Maker Scheduled @ 2022-06-02T12:09:50.868094-05:00>>
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140581399855312] Sending {"id":74,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"automation.coffee_maker_scheduled","old_state":{"entity_id":"automation.coffee_maker_scheduled","state":"on","attributes":{"last_triggered":"2022-06-02T18:25:27.394558+00:00","mode":"single","current":1,"id":"1646408179088","friendly_name":"Coffee Maker Scheduled"},"last_changed":"2022-06-02T17:09:50.868094+00:00","last_updated":"2022-06-02T18:25:27.394636+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}},"new_state":{"entity_id":"automation.coffee_maker_scheduled","state":"on","attributes":{"last_triggered":"2022-06-02T18:25:27.394558+00:00","mode":"single","current":0,"id":"1646408179088","friendly_name":"Coffee Maker Scheduled"},"last_changed":"2022-06-02T17:09:50.868094+00:00","last_updated":"2022-06-02T18:25:27.406840+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-06-02T18:25:27.406840+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}}}
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Schedule (schedule) for 192.168.15.54>: {'schedule': {'get_rules': None, 'get_next_action': None}}
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Usage (schedule) for 192.168.15.54>: {'schedule': {'get_realtime': None, 'get_daystat': {'year': 2022, 'month': 6}, 'get_monthstat': {'year': 2022}}}
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Antitheft (anti_theft) for 192.168.15.54>: {'anti_theft': {'get_rules': None, 'get_next_action': None}}
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Time (time) for 192.168.15.54>: {'time': {'get_time': None, 'get_timezone': None}}
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.smartdevice] Adding query for <Module Cloud (cnCloud) for 192.168.15.54>: {'cnCloud': {'get_info': None}}
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.protocol] 192.168.15.54 >> {"system": {"get_sysinfo": null}, "schedule": {"get_rules": null, "get_next_action": null, "get_realtime": null, "get_daystat": {"year": 2022, "month": 6}, "get_monthstat": {"year": 2022}}, "anti_theft": {"get_rules": null, "get_next_action": null}, "time": {"get_time": null, "get_timezone": null}, "cnCloud": {"get_info": null}}
2022-06-02 13:25:27 DEBUG (MainThread) [kasa.protocol] 192.168.15.54 << {'anti_theft': {'get_next_action': {'err_code': -2,
                                    'err_msg': 'member not support'},
                'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'cnCloud': {'get_info': {'binded': 0,
                          'cld_connection': 0,
                          'err_code': 0,
                          'fwDlPage': '',
                          'fwNotifyType': -1,
                          'illegalType': 0,
                          'server': 'n-devs.tplinkcloud.com',
                          'stopConnect': 0,
                          'tcspInfo': '',
                          'tcspStatus': 0,
                          'username': ''}},
 'schedule': {'get_daystat': {'day_list': [], 'err_code': 0},
              'get_monthstat': {'err_code': 0, 'month_list': []},
              'get_next_action': {'err_code': -11, 'err_msg': 'time not sync'},
              'get_realtime': {'err_code': -2, 'err_msg': 'member not support'},
              'get_rules': {'err_code': -11, 'err_msg': 'time not sync'}},
 'system': {'get_sysinfo': {'active_mode': 'none',
                            'alias': 'HS103_D',
                            'dev_name': 'Smart Wi-Fi Plug Mini',
                            'deviceId': '8006F0ACE6D1015112B9A92CCC9E37D81D799FC8',
                            'err_code': 0,
                            'feature': 'TIM',
                            'hwId': '80CB7367CEA6E3B6DC96C2855EE7C79A',
                            'hw_ver': '3.0',
                            'icon_hash': '',
                            'latitude_i': 436704,
                            'led_off': 0,
                            'longitude_i': -723130,
                            'mac': '60:32:B1:74:35:74',
                            'mic_type': 'IOT.SMARTPLUGSWITCH',
                            'model': 'HS103(US)',
                            'next_action': {'type': -1},
                            'ntc_state': 0,
                            'oemId': '1925575B7899062F242F15F7AFE4D486',
                            'on_time': 0,
                            'relay_state': 0,
                            'rssi': -56,
                            'status': 'new',
                            'sw_ver': '1.0.2 Build 200602 Rel.114349',
                            'updating': 0}},
 'time': {'get_time': {'err_code': 0,
                       'hour': 6,
                       'mday': 11,
                       'min': 29,
                       'month': 1,
                       'sec': 12,
                       'year': 2000},
          'get_timezone': {'err_code': 0, 'index': 18}}}
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.15.54 data in 0.022 seconds (success: True)
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.coffee_maker, old_state=<state switch.coffee_maker=on; icon=mdi:coffee, friendly_name=Coffee Maker On @ 2022-06-02T13:00:00.422240-05:00>, new_state=<state switch.coffee_maker=off; icon=mdi:coffee, friendly_name=Coffee Maker On @ 2022-06-02T13:25:27.781709-05:00>>
2022-06-02 13:25:27 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140581399855312] Sending {"id":74,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"switch.coffee_maker","old_state":{"entity_id":"switch.coffee_maker","state":"on","attributes":{"icon":"mdi:coffee","friendly_name":"Coffee Maker On"},"last_changed":"2022-06-02T18:00:00.422240+00:00","last_updated":"2022-06-02T18:00:00.422240+00:00","context":{"id":"018125930103f0b56a2312b4d1c67048","parent_id":null,"user_id":null}},"new_state":{"entity_id":"switch.coffee_maker","state":"off","attributes":{"icon":"mdi:coffee","friendly_name":"Coffee Maker On"},"last_changed":"2022-06-02T18:25:27.781709+00:00","last_updated":"2022-06-02T18:25:27.781709+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-06-02T18:25:27.781709+00:00","context":{"id":"018125aa4f6100132690c4294656b214","parent_id":null,"user_id":null}}}
2022-06-02 13:25:27 DEBUG (Recorder) [homeassistant.components.recorder] Processing task: EventTask(event=<Event state_changed[L]: entity_id=switch.coffee_maker, old_state=<state switch.coffee_maker=on; icon=mdi:coffee, friendly_name=Coffee Maker On @ 2022-06-02T13:00:00.422240-05:00>, new_state=<state switch.coffee_maker=off; icon=mdi:coffee, friendly_name=Coffee Maker On @ 2022-06-02T13:25:27.781709-05:00>>)
2022-06-02 13:25:27 DEBUG (Thread-3) [paho.mqtt.client] Sending PINGREQ
2022-06-02 13:25:27 DEBUG (Thread-3) [paho.mqtt.client] Received PINGRESP
2022-06-02 13:25:28 DEBUG (MainThread) [kasa.smartdevice] The device has emeter, querying its information along sysinfo

I’m not seeing a pattern yet.

kreene1987 · June 2, 2022, 7:18pm

I just had this issue with the new calendar “before” event (30 mins before) that was ~3 minutes late in triggering…

chris8 · June 3, 2022, 4:03am

Hmm… I was just going through adding more logging statements to HA to try to figure out what it could possibly be doing… and noticed my system clock wrong. It certainly wasn’t wrong before, but it is off now.

This made me revisit my previous post:

Started right on time, but ended 1:25:27pm, 5m27s late.

Interestingly, in the DEBUG level Home-Assistant log there was not a single event from 1:16 to 1:22:
2022-06-02 13:16:35 DEBUG (MainThread) [homeassistant.components.tplink.coordinator] Finished fetching 192.168.15.67 data in 0.148 seconds (success: True)
2022-06-02 13:22:05 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('172.25.0.1', 54780): b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nST: upnp:rootdevice\r\nMX: 5\r\n\r\n'
So absolutely nothing happened at 1:20, when it was supposed to trigger. 5 minutes later it finally decided to trigger

It is crazy to think HA went from 13:16:35 to 13:22:05 with zero debug log statements. I don’t know if I’ve ever seen a full second go by without a debug log message, much less 5 minutes and 30 seconds with nothing at all! And then immediately afterward, the datetime triggers are all off by 5m30s. What a coincidence!

It seems that something is changing my system clock. @tom_l seems to have had the right idea from the very start.

chris8 · June 3, 2022, 4:26am

Ok, I’m an idiot.

Ever since April 8th the trigger times have been drifting farther and farther away. If I had to guess, I would say this started happening when I updated to 2022.4, but I do not know for sure that I updated that day. The timeline would fit, though.

April 8th wasn’t when I updated to 2022.4.
April 8th was the day that I learned that “just because a cable is keyed to plug in to your modular power supply doesn’t mean the cable is meant for your modular power supply” and fried my motherboard. New motherboard, new RAM, new CPU, took the opportunity to update from Ubuntu 16.04LTS to 20.04LTS…

…but obviously it was the Home Assistant update that was the problem.

kreene1987 · June 3, 2022, 12:12pm

Perhaps I need to go back to the drawing board lol.

chris8 · June 3, 2022, 4:10pm

Haha, well at least this thread has hopefully made you check your system clock
Is your issue persistent or it just happened once?

kreene1987 · June 9, 2022, 8:18pm

yeah something is wrong here:

13 minutes later?:

Phone is on wifi and system time of HA is spot on.

chris8 · June 10, 2022, 4:40pm

It looks like the automation executed right on time. Your issue seems to be that it takes a long time for your phone to receive a notification. You could verify this by having the automation also toggle a light or something to see that it is actually running on time.

Could your phone be sleeping and it receives the notification the next time you turn on your phone screen? I would be narrowing my focus to your phone’s HA and system settings for this issue.

On my Android phones I have much better luck with adding ‘ttl’ and ‘priority’ to my notifications. Here is my garage door notification for an example

service: notify.notify
data:
  title: Garage Door is {{ states("sensor.garage_door_state") }}
  message: >-
    Door has been {{ states("sensor.garage_door_state") }} for {{
    relative_time(states.sensor.garage_door_state.last_changed) }}
  data:
    priority: high
    ttl: 0
    clickAction: lovelace/0
    url: lovelace/0