My 2022.12.6 Home Assistant core installation (virtualenv in Xubuntu 22.04LTS) is on a dedicated Celeron N3350 4MB Ram mini-pc. Upon recently activating my holiday lighting schedule, I noticed that the time trigger for the automations were firing just a few (~1-3) minutes late. Looking further, this seems to be happening in all my automations with a time based trigger.
I have done some rudimentary investigation / troubleshooting but am out of ideas. Looking for suggestions on what to try next.
For example, here are two different automations. One turns the lights on front of the house on at 6:30:01 AM in the morning if the sun is not already up. The second turns the indoor christmas lights on at 8:00:01 AM if anyone is at home. Both of these were manually set up via YAML:
- id: 'automation_14'
alias: Front Lights On In Morning
trigger:
- platform: time
at: '06:30:01'
condition:
condition: and
conditions:
- condition: sun
before: sunrise
- condition: time
weekday:
- mon
- tue
- wed
- thu
- fri
action:
- service: light.turn_on
data:
entity_id:
- light.driveway_lights
- id: 'automation_24'
alias: Turn Indoor Christmas Lights On
trigger:
- platform: state
entity_id: group.people
from: 'not_home'
to: 'home'
for: '00:1:00'
- platform: time
at: '08:00:01'
condition:
condition: and
conditions:
- condition: state
entity_id: group.people
state: 'home'
- condition: time
before: '23:00:00'
- condition: state
entity_id: input_boolean.holiday_lights
state: "on"
action:
- service: scene.turn_on
data:
entity_id:
- scene.christmas_indoor_on
Here is the relevant automation component DEBUG log from yesterday morning and this morning. Notice both are late relative to expected start time though by variable amounts day / day.
2022-12-15 06:30:57.948 DEBUG (MainThread) [homeassistant.components.automation.front_lights_on_in_morning] Automation trigger 'None' triggered by time
2022-12-15 06:30:57.951 INFO (MainThread) [homeassistant.components.automation.front_lights_on_in_morning] Front Lights On In Morning: Running automation actions
2022-12-15 06:30:57.952 INFO (MainThread) [homeassistant.components.automation.front_lights_on_in_morning] Front Lights On In Morning: Executing step call service
2022-12-15 08:01:10.078 DEBUG (MainThread) [homeassistant.components.automation.turn_indoor_christmas_lights_on] Automation trigger 'None' triggered by time
2022-12-15 08:01:10.081 INFO (MainThread) [homeassistant.components.automation.turn_indoor_christmas_lights_on] Turn Indoor Christmas Lights On: Running automation actions
2022-12-15 08:01:10.082 INFO (MainThread) [homeassistant.components.automation.turn_indoor_christmas_lights_on] Turn Indoor Christmas Lights On: Executing step call service
2022-12-16 06:33:24.019 DEBUG (MainThread) [homeassistant.components.automation.front_lights_on_in_morning] Automation trigger 'None' triggered by time
2022-12-16 06:33:24.023 INFO (MainThread) [homeassistant.components.automation.front_lights_on_in_morning] Front Lights On In Morning: Running automation actions
2022-12-16 06:33:24.023 INFO (MainThread) [homeassistant.components.automation.front_lights_on_in_morning] Front Lights On In Morning: Executing step call service
2022-12-16 08:03:25.577 DEBUG (MainThread) [homeassistant.components.automation.turn_indoor_christmas_lights_on] Automation trigger 'None' triggered by time
2022-12-16 08:03:25.580 INFO (MainThread) [homeassistant.components.automation.turn_indoor_christmas_lights_on] Turn Indoor Christmas Lights On: Running automation actions
2022-12-16 08:03:25.581 INFO (MainThread) [homeassistant.components.automation.turn_indoor_christmas_lights_on] Turn Indoor Christmas Lights On: Executing step call service
As can be seen in the time entries for log time, Home Assistant is aware of the correct time. To further confirm this:
{{ now() }}
{{ now().astimezone() }}
{{ utcnow().astimezone() }}
{{ now().now() }}
{{ now().today() }}
{{ now().utcnow() }}
{{ utcnow() }}
{{ now().tzinfo }}
{{ now().astimezone().tzinfo }}
{{ utcnow().tzinfo }}
2022-12-16 09:27:00.410764-05:00
2022-12-16 09:27:00.410892-05:00
2022-12-16 09:27:00.411127-05:00
2022-12-16 09:27:00.411370
2022-12-16 09:27:00.411525
2022-12-16 14:27:00.411673
2022-12-16 14:27:00.411731+00:00
America/Indianapolis
EST
UTC
I have also looked at the CPU utilization to confirm that the machine is not heavily stressed.
top - 09:28:26 up 7 days, 26 min, 4 users, load average: 0.33, 0.24, 0.25
Tasks: 187 total, 1 running, 186 sleeping, 0 stopped, 0 zombie
%Cpu(s): 5.8 us, 3.1 sy, 0.0 ni, 90.1 id, 0.7 wa, 0.0 hi, 0.3 si, 0.0 st
MiB Mem : 3742.0 total, 156.4 free, 1111.5 used, 2474.1 buff/cache
MiB Swap: 1359.6 total, 1259.1 free, 100.5 used. 2322.0 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
150000 homeass+ 20 0 1890460 388652 58128 S 11.6 10.1 245:43.81 hass
1020 homeass+ 20 0 1007688 147448 25052 S 5.0 3.8 276:16.51 node
526 avahi 20 0 8148 4044 3268 S 1.3 0.1 32:29.65 avahi-daemon
1253 pletchtd 20 0 664924 23460 14372 S 0.7 0.6 13:38.89 panel-10-pulsea
190243 pletchtd 20 0 13192 4192 3372 R 0.7 0.1 0:17.87 top
22 root 20 0 0 0 0 S 0.3 0.0 0:42.27 ksoftirqd/1
245 root 19 -1 64464 15348 13880 S 0.3 0.4 5:09.53 systemd-journal
558 root 20 0 128556 9132 8320 S 0.3 0.2 1:14.15 thermald
4182 homeass+ 20 0 1311228 37152 11376 S 0.3 1.0 17:05.95 RTSPtoWeb
I think this issue has been going on for a while but I only noticed having recently enabled my holiday lighting routine. For example, I have a backup that includes a log showing a delayed automation start back in 05-Jun-2022. I don’t have any further logs before then so I can’t accurately state when the issue started.
Any thoughts?