Triggered timer.finish but timer state is still active

Configuration
1

Hi. For each of my lights, I have two timers - one that starts when “turned on based on motion (automatic)” and the other starts when “turned on by a switch”. Once both are finished, the light is turned off. As I am doing this for quite a few lights, I wanted to save myself the duplication and made the automation action a bit generic by handling all timers at once. This used to work very reliably, but (subjectively) since yesterday and maybe (or maybe not :man_shrugging: ) recent updates (HA Core, etc as well as some new scripts on my side) it stopped working.

I debugged it to the issue being that the timer that finishes is not set to state “idle”, which my script assumes and which worked previously. Minimal example:

- alias: debug
  trigger:
    platform: event
    event_type: timer.finished
  action:
    - service: system_log.write
      data_template:
        level: error
        logger: homeassistant.components.mylogger
        message: "timer that finished: {{ trigger.event.data.entity_id }}. Its state: {{ states[trigger.event.data.entity_id] }}"

and the log shows e.g. timer that finished: timer.manual_timer_hallway_whiteboard. Its state: <template TemplateState(<state timer.manual_timer_hallway_whiteboard=active; duration=0:00:20, editable=False, finishes_at=2024-04-06T14:41:55+00:00, remaining=0:00:20 @ 2024-04-06T16:41:35.313915+02:00>)>

As this script was not changed (verified by comparing with a backup version from last month), I wonder whether any default or behavior changed. I see in older logs that apparently this issue happened in the past as well, but only very rarely. Now it happens every single time. So maybe some configuration changes on my side or in general causes this to be more consistent?

What is the expected behavior? From my perspective, when I get the timer.finished event for timer X, I would assume that timer.X is not in state “active” anymore but “idle” (otherwise, has it really finished? :wink: ). Is this a misconception?

2

It looks to me like your template’s query is happening too quickly, before the state change event happens. In testing on my instance, adding just a 1 millisecond delay as the first action solves the issue.

3

Hmm, this is … interesting behavior. Is this by design or is this a bug? Because I feel like the behavior should be consistent and not change based on some timing issue that could be heavily influenced based on the load of the machine?

Anyway, it seems to do the trick. Thank you! :heart: I also changed my script to not rely on it (I have very bad experience with picking “correct” delays - it’s either going to be WAY too long always, or sometimes too short causing flaky behavior).

4

I agree with you, but I don’t know enough about how timers work in the backend to know if it’s technically a bug or an unavoidable consequence of the fact that timer events need to be more “timely” than state-changed events (so they get posted first)… combined with the fact that your automation is so short.