Automation time not working correctly

Hi All, I have a simple automation to turn a lamp off at 22:15. It never happens at the correct time. It turns off the lamp at random times early in the morning.
Last night, the trace timeline reported it was triggered at 04:27:28. I have checked the logs, and there are no errors with this automation.
I have checked my time (utc, utcnow) both are are correct and the lamp id is also correct.
The lamp (a shelly 2) is turned on at dusk using a blueprint (CyanAutomation/lights_on_at_sunset.yaml) that works every day ok.
Here is the automation to turn the light off.

alias: Lights off
description: Lights off
trigger:
  - platform: time
    at: "22:15:00"
condition: []
action:
  - service: light.turn_off
    data: {}
    target:
      device_id: db99d5be436bd76217583f9b221d45c0
mode: single

many thanks for any help.

Are you are you in the UTC + 0 time zone?

The trigger uses the underlying operating system time. So the time and time zone must be set correctly for both home assistant and your OS.

Yes in the UK, UTC+0

What does {{ now() }} report?

2023-01-29 14:17:07.199266+00:00

at Sunday 29th. Jan 14:17

How did you install home assistant?

its a virtual machine running on virtualbox in a Macmini.
I already had the Macmini on 24/7 so, it made sense. No problems with anything apart from the time automation.

Ok, check the Macmini has the correct time and timezone.

yes, just checked to be sure.

First, you mention the trace timeline. However, according to the snippet you provided, the automation doesn’t have an id, and as far as I know, an id is a requirement for the trace system. So, exactly where did you see that time of 04:27:28? The log? The Logbook? 
?

Regarding clock and time zone settings, generally, if they are incorrect, that can account for a difference in when a time trigger should fire and when it actually does. However, the difference shouldn’t be random, it should be pretty consistent. The fact that it is random seems to indicate something more involved. Also, since the template “{{ now() }}” returns the expected time, in the expected time zone, that is evidence that the clock and time zone are set correctly.

You could try the following in the template page:

{{ now() }}
{{ now().now() }}

The former shows an “aware” time (i.e., with time zone info) in the time zone HA is configured for. The latter shows a “naive” time (i.e., no time zone knowledge) in the underlying OS’s time zone. If they match, and are what you expect, that’s further proof that the underlying OS’s clock & time zone are set correctly and agree with HA’s time zone setting.

Have you made any progress since your last post?

1 Like
  1. the trace timeline I saw by selecting the lights off animation, then selected traces in the top right, step details are highlighted with the last execution time showing at the top. If I select the execution time, it then shows the last 5 executions. The one at 22:38 is me running the automation to turn the light off “manually”Screenshot 2023-01-31 at 09.53.02
    all random times. If the time zone was incorrect, wouldn’t the execution times be wrong by x hours?

  2. None of my automations have an id. Do I need one? How do I add an id?

  3. template page at 09:59 =
    2023-01-31 09:59:02.842022+00:00
    2023-01-31 09:59:02.842126

  4. No Progress. I created another “test lights off” animation. to trigger at 22:20. It was executed at 08:02:29 this morning.

Next step, I will add a new test esphome device with a new on and off animation, and see what happens.
Perhaps its the lamp1 switch_0 device (now grasping at straws)

Yes, that’s what I would expect. FWIW, I just checked the traces of one of my automations that has a time trigger and when the time trigger fires the execution time is exactly that time.

Hmm, sorry, seems like I made an incorrect statement. I’ve been using HA since way before the trace system was added and none of my automations had IDs. I seem to recall seeing somewhere in the UI that traces weren’t available for my automations due to lacking IDs, so I added them. Maybe something changed since then, or maybe I just got confused. If your automations don’t have IDs, then it’s probably because you wrote them manually in YAML files. The UI always adds IDs. To add an ID manually, just use the id option:

- alias: Blah blah automation
  id: blah_blah_automation
  trigger: ...

The ID can pretty much be anything, as long as it’s unique amongst all the automations in your system.

I would try adding an automation that has a single time trigger, and have the action be empty (action: []), or maybe just have it fire an event (action: {"event": "TEST"}).

BTW, what version of HA Core are you running?

ok, I will add an id and as a new automation as you described above.
HA Core etc.

  "home_assistant": {
    "installation_type": "Home Assistant OS",
    "version": "2023.1.7",
    "dev": false,
    "hassio": true,
    "virtualenv": false,
    "python_version": "3.10.7",
    "docker": true,
    "arch": "x86_64",
    "timezone": "GB",
    "os_name": "Linux",
    "os_version": "5.15.90",
    "supervisor": "2023.01.1",
    "host_os": "Home Assistant OS 9.5",
    "docker_version": "20.10.22",
    "chassis": "vm",
    "run_as_root": true
  },

ID added in yaml, saved reopened and it disappeared. Thinking the yaml editor does not show it, I
looked at automations.yaml, and there it is! Also, there is already an ID in every automation script in my automations.yaml. So, I removed the ID I put in to avoid two ID’s.
Therefore the ID exists for every animation, but you can only see it in automations.yaml.

created a test-relay in esphome
created an automation note the ‘generated’ ID

- id: '1675178054773'
  alias: relay-test-on
  description: relay-test-on
  trigger:
  - platform: time
    at: '15:38:00'
  condition: []
  action:
  - event: TEST
    event_data: {}
  mode: single

This worked at 15:38:24. Brilliant
I will now change the event to switch on test-relay, and report back

test-relay working on and off within 10 seconds of the trigger timer.
I added my lamp (the shelly 2 device), it turned on after 38 seconds, ok but it turned off 3 1/2 minutes late. Far better than the random 12 -15 hours of the existing lights_off automation.
I cannot see any difference between the lights-off and my new test-relay off automation.

I had a helper (as advised in a post) “to switch as X” I deleted that, and the of time is now within a minute. It is more than likely the polling time of the shelly 2 device.

conclusion :- there was something wrong with the lights-off automation that was further complicated by the delay/no response of the shelly 2 device. I do not know it HA waits for a ping back from the shelly device or not.
I will in future look at the automations.yaml to check any mistakes.

Anyway, its working now and I can order two more shelly 2 devices to replace my ancient X10 devices.
I will try to resolve the timing delays of the shelly 2 device in a new post.
Many thanks to everyone who has contributed to this post to help me learn more about HA.

Still, it shouldn’t be minutes. Milliseconds, sure, seconds even, maybe, but not minutes and surely not hours ever.

It sounds to me like you have a misbehaving integration. Do you have any custom integrations installed?

Yes I agree. Two custom integration, security spy (now removed) and hacs. It did not turn off the light at 10:15 last night.
I have deleted all the automations, checked the automations.yaml that contained only [] and restarted HA.
I added 1 automation that creates a message on my iphone when the garage door is opened.
This works perfectly. (not using time). So there is no time lag with HA running in a VM.
created test-relay-on and test-relay-off
trigger time test-relay-on 11:00 time executed 11:00:06 good
trigger time test-relay-off 11:02 time executed 11:03:28 not good

better but as you said above not correct

I did discover one thing new about how time triggers work. Starting in 2022.12, there is a random offset of between 50 and 500 msec added to each time trigger (and some other things in the system that are scheduled to run at a particular second.) This means, e.g., if you have a time trigger at “09:00:00”, it will try to run at anywhere from “09:00:00.050” and “09:00:00.500”. Normally this isn’t an issue. It was done to prevent many, many time-based events, all scheduled at the same time (particularly, at a time whose microseconds component is zero), from all trying to run at exactly the same time. See Fix high latency from thundering heard at 0 microseconds by bdraco · Pull Request #82233 · home-assistant/core (github.com).

I should also mention that offset is calculated once per time-based event. I.e., for a particular time trigger, it will get a random offset that stays the same for that trigger. A different trigger will get a different offset, that then stays the same for that particular trigger, etc. To put that another way, each time trigger will have a different offset, but for each trigger its offset won’t be changing.

But this still doesn’t explain what you’ve been experiencing.

I’ve been refreshing my memory on how time-based things work in HA. The bottom line seems to be that there is a monotonic clock used for scheduling time-based events. When an event needs to be scheduled, the current time (i.e., time.time()) is subtracted from the desired time (typically from something roughly like now().timestamp()), to get a time delta (in seconds.) Then a “callback” is placed to run that (delta) amount of time in the future, based on the monotonic clock.

So, what does that all mean?

First, time.time(), now().timestamp(), etc. are based on the underlying OS’s time. If that time gets adjusted (NTP, etc.) between the time the event is scheduled (and for a fixed time trigger, that is basically once per day), and when it runs, that could, at least partially, explain the difference you’re seeing.

The other thing is, if the monotonic clock (which is not supposed to change when the underlying clock is adjusted, that’s the whole point of a “monotonic” clock) that is used for actually scheduling the events is drifting, that could also, at least partially, explain the differences.

I’m running some experiments on my own system. I already have a relatively simple custom integration I wrote that does something every five minutes. I added code to it to check the difference between time.time() and the monotonic clock when it starts, and then every five minutes. If the underlying clock isn’t adjusted, and everything is working perfectly (which, of course, they never are), in theory the difference between time.time() and the monotonic clock should not change. Any change in that difference would be drift of one, if not both, of the clocks.

I’ve run it for a bit, and so far, it looks like on my system the drift is around 1 ”sec / 5 minutes. That would mean the drift would be around 300 ”sec or less per day.

EDIT: Sorry, that’s wrong. I initially misinterpreted the results. The difference is actually staying about the same, so for the short time I’ve run it, I do not see any drift.

If you’d like to try it, I can certainly whip up a custom integration that does just this. Right now, it’s just logging to home-assistant.log, but it would be easy for it to create a sensor that could be displayed in a history window. Let me know if you’re interested.

In the meantime, it would be interesting to know something more about your system. You said, “its a virtual machine running on virtualbox in a Macmini.” What do you have for acceleration under the VM’s system settings? Does the VBox UI, when HA is running, show that virtualization acceleration is enabled in the tray in the bottom right? Is virtualization acceleration (e.g., VT-x, etc.) enabled in the “system BIOS” (or whatever is the equivalent on a Macmini)?

Also, here is a potential, at least temporary, workaround


Instead of using:

trigger:
  - platform: time
    at: "09:00:00"

Try this:

trigger:
  - platform: template
    value_template: "{{ now() > today_at("09:00:00") }}"

Note that a template trigger will “fire” when it evaluates as true after having evaluated as false. That means, if HA starts when it is already after the specified time, the template will evaluate as true. This will not cause it to fire (because it didn’t change from false to true.) It will have to evaluate as false (when it gets to midnight), and then evaluate as true (when it gets to specified time), for it to fire. Then, this repeats, meaning it will only fire once a day when it crosses from before the time to after the time. Note that the template will be re-evaluated at the beginning of every minute.

Just like a time trigger, it’s also possible to use the template trigger to compare the time against an input_datetime helper, if you should need that, too.

@chrisfairbrother did any of that help?

Sorry Phil, I was not allowed to ‘play’ yesterday.
Many thanks for your detailed explanation of the time function, very interesting. I will try your value_template and look at the VM today.
Chris

1 Like