Automation does not stop or ends incorrect, which causes Already running messages

ridderr commented 1 year ago

The problem

Some automations (randomly) do not end correctly which results in warning messages: 2023-08-05 10:53:24.273 WARNING (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Already running.

It's a bit hard to track but one of my automations is run very frequently and therefor I was able to log the issue.

Ones this occurs I have to restart HA. It's not related to this specific automation. I also have seen it on other.

What version of Home Assistant Core has the issue?

2023.8.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

No response

Link to integration documentation on our website

No response

Diagnostics information

2023-08-05 09:34:04.737 DEBUG (MainThread) [homeassistant.components.automation.lampen_gang] Automation trigger 'None' triggered by state of light.lampen_gang
2023-08-05 09:34:04.738 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Running automation actions
2023-08-05 09:34:04.742 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Running automation actions
2023-08-05 09:34:04.743 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Choose at step 1: default: Running automation actions
2023-08-05 09:34:04.744 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Choose at step 1: default: Executing step device automation
2023-08-05 09:37:37.372 DEBUG (MainThread) [homeassistant.components.automation.lampen_gang] Automation trigger 'None' triggered by state of light.lampen_gang
2023-08-05 09:37:37.373 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Running automation actions
2023-08-05 09:37:37.379 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Running automation actions
2023-08-05 09:37:37.382 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Choose at step 1: default: Running automation actions
2023-08-05 09:37:37.382 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Choose at step 1: default: Executing step device automation
2023-08-05 09:49:47.532 DEBUG (MainThread) [homeassistant.components.automation.lampen_gang] Automation trigger 'None' triggered by state of light.lampen_gang
2023-08-05 09:49:47.533 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Running automation actions
2023-08-05 09:49:47.534 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Running automation actions
2023-08-05 09:49:47.535 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Choose at step 1: default: Running automation actions
2023-08-05 09:49:47.535 INFO (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Choose at step 1: choice 1: Choose at step 1: default: Executing step device automation
2023-08-05 09:50:27.757 DEBUG (MainThread) [homeassistant.components.automation.lampen_gang] Automation trigger 'None' triggered by state of light.lampen_gang
2023-08-05 09:50:27.758 WARNING (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Already running
2023-08-05 10:27:33.403 DEBUG (MainThread) [homeassistant.components.automation.lampen_gang] Automation trigger 'None' triggered by state of light.lampen_gang
2023-08-05 10:27:33.404 WARNING (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Already running
2023-08-05 10:53:24.272 DEBUG (MainThread) [homeassistant.components.automation.lampen_gang] Automation trigger 'None' triggered by state of light.lampen_gang
2025-08-05 10:53:24.273 WARNING (MainThread) [homeassistant.components.automation.lampen_gang] Gang lampen: Already running

Example YAML snippet

alias: Gang lampen
description: ""
trigger:
  - platform: device
    type: turned_on
    device_id: 24ebf39cdf4049f553684a0acfd49ebf
    entity_id: light.lampen_gang
    domain: light
    id: S1-switch
  - platform: device
    type: turned_on
    device_id: 24ebf39cdf4049f553684a0acfd49ebf
    entity_id: light.lampen_gang_2
    domain: light
    id: S2-switch
  - platform: device
    type: turned_off
    device_id: 24ebf39cdf4049f553684a0acfd49ebf
    entity_id: light.lampen_gang_2
    domain: light
    id: S2-switch
condition: []
action:
  - choose:
      - conditions:
          - condition: trigger
            id: S1-switch
        sequence:
          - choose:
              - conditions:
                  - condition: state
                    entity_id: input_boolean.lightson
                    state: "on"
                  - condition: device
                    type: is_off
                    device_id: 0a034a1cea88e3ff62c950782e7cf10a
                    entity_id: switch.staande_lamp
                    domain: switch
                sequence:
                  - type: turn_on
                    device_id: 24ebf39cdf4049f553684a0acfd49ebf
                    entity_id: light.lampen_gang
                    domain: light
                    brightness_pct: 1
            default:
              - type: turn_on
                device_id: 24ebf39cdf4049f553684a0acfd49ebf
                entity_id: light.lampen_gang
                domain: light
                brightness_pct: 20
      - conditions:
          - condition: trigger
            id: S2-switch
        sequence:
          - choose:
              - conditions:
                  - condition: device
                    type: is_on
                    device_id: 24ebf39cdf4049f553684a0acfd49ebf
                    entity_id: light.lampen_gang
                    domain: light
                sequence:
                  - type: turn_on
                    device_id: 24ebf39cdf4049f553684a0acfd49ebf
                    entity_id: light.lampen_gang
                    domain: light
                    brightness_pct: 100
            default:
              - type: turn_off
                device_id: 24ebf39cdf4049f553684a0acfd49ebf
                entity_id: light.lampen_gang
                domain: light
    default: []
mode: single

Anything in the logs that might be useful for us?

No response

Additional information

No response

joostlek commented 1 year ago

Keep in mind that the automation is in mode: single so it only run one at a time. If you want to run this multiple times at the same time I think you should switch to parallel

ridderr commented 1 year ago

Yes I know, but once this occurs none will run anymore. it looks like it stays in running mode (what I have seen, but is not in the trace). (I will will increase the number of trace instances to keep). Also see the time stamp, there is a lot of time between each invocation.

joostlek commented 1 year ago

What kind of devices are they? What integration do you use for them?

ridderr commented 1 year ago

It's a Z-Wave devices, but I'm not sure if this is related to a Z-Wave device. I have seen it in another automation which is not driving a Z-Wave device. This automation is run very often because it is triggered when someone is in the 'hallway'

Do you have advice to increase logging? I have added to the lampen_gang automation: trace: stored_traces: 25

I currently have below in configuration.yaml but this is only giving limited information logger: default: warning logs: homeassistant.components.automation.lampen_gang: debug

joostlek commented 1 year ago

So apparently some other people on the forum had this as well. The current theory is that the Z-Wave device have a latency issue. I am no expert, but that's what I've heard.

Can you maybe track down this for the other automations without Z-Wave devices? Maybe it could lead to a wider problem or problem in more integrations

I am no expert in the best way to log these things sadly

home-assistant[bot] commented 1 year ago

Hey there @home-assistant/z-wave, mind taking a look at this issue as it has been labeled with an integration (zwave_js) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `zwave_js` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign zwave_js` Removes the current integration label and assignees on the issue, add the integration domain after the command.

_{^{(message by CodeOwnersMention)}}

zwave_js documentation zwave_js source _{^{(message by IssueLinks)}}

tdejneka commented 1 year ago

The automation posted above is very straightforward and simply turns on/off some Zwave lights. One wouldn't normally expect its execution time to be very long (< 1 second). However it appears to be waiting forever for a response from the controlled device(s) that never arrives. As a result, the automation never finishes and becomes non-responsive to subsequent attempts to trigger it, notably if mode is single or restart.

The examples that users have presented in the forum are automations that communicate with devices using Zwave and Zigbee. However indications are that the problem may not be limited to just those two integrations; potentially it's any integration that doesn't promptly reply to a transmitted command. In other words, it appears like some sort of internal timeout mechanism may be misbehaving.

FWIW, an automation employing mode: restart should abort execution if it's triggered again. However, users have reported the automations don't abort and the value of their current attribute increases with each subsequent triggering of the automation. In other words, it's stuck waiting forever and queues subsequent execution requests. That's abnormal; the automation's mode is restart but it's behaving like queued.

ridderr commented 1 year ago

Hi, I have to same issue on an automation which is not Z-Wave related.

Now this automation is 'blocked' and all subsequent call to this automation stops. This automation run every minute and checks if current time matches the actual time.

joostlek commented 1 year ago

Can you share the automation?

ridderr commented 1 year ago

It's using a blueprint but the automation is:

joostlek commented 1 year ago

Can you send it as text 😇

ridderr commented 1 year ago

The blueprint is here: https://gist.github.com/sbyx/96c43b13b90ae1c35b872313ba1d2d2d

alias: Slaapkamer Wake-up light alarm with sunrise effect
description: ""
use_blueprint:
  path: sbyx/wake-up-light-alarm-with-sunrise-effect.yaml
  input:
    light_entity: light.ledstrip_slaapkamer
    sunrise_duration: 15
    manual_time: "06:01:00"
    timestamp_sensor: sensor.ridderr_next_alarm
    post_sunrise_actions:
      - service: script.post_wakeup
        data: {}
    min_mired: 465
    check_entity: person.ruud_de_ridder

tdejneka commented 1 year ago

The linked blueprint is designed to create an automation that triggers every minute and runs in single mode.

From the screenshot you provided, it appears that it never even finishes a single execution because the last reported message is "Still running".

What is the integration used by light.ledstrip_slaapkamer?

If possible, download and post the automation's trace file.

joostlek commented 1 year ago

I tried to reproduce this and I got the same result as ridderr, but I removed the blueprint from my instance now oops.

ridderr commented 1 year ago

The linked blueprint is designed to create an automation that triggers every minute and runs in single mode.

From the screenshot you provided, it appears that it never even finishes a single execution because the last reported message is "Still running".

What is the integration used by light.ledstrip_slaapkamer?

If possible, download and post the automation's trace file.

light.ledstrip_slaapkamer is a Z-Wave device but it is not activated because the time doesn't match my alarm time. I noticed that when I disable/enable the automation it will hang immediately.

tdejneka commented 1 year ago

Is a trace file available?

ridderr commented 1 year ago

I now have a reproduceable situation and could enable debug logging:

2023-08-06 16:28:00.194 DEBUG (MainThread) [homeassistant.components.automation.wake_up_pre_post_actions] Automation trigger 'None' triggered by time pattern 2023-08-06 16:28:00.432 DEBUG (MainThread) [homeassistant.components.automation.wake_up_light_alarm_with_sunrise_effect] Automation trigger 'None' triggered by time pattern 2023-08-06 16:28:00.441 INFO (MainThread) [homeassistant.components.automation.wake_up_light_alarm_with_sunrise_effect] Slaapkamer Wake-up light alarm with sunrise effect: Running automation actions 2023-08-06 16:28:00.441 INFO (MainThread) [homeassistant.components.automation.wake_up_light_alarm_with_sunrise_effect] Slaapkamer Wake-up light alarm with sunrise effect: Executing step wait template 2023-08-06 16:28:00.442 INFO (MainThread) [homeassistant.components.automation.wake_up_light_alarm_with_sunrise_effect] Slaapkamer Wake-up light alarm with sunrise effect: Executing step wait template

tdejneka commented 1 year ago

I'll try one last time: Post the automation's trace file (if it's available). Use the "Download trace" command from the menu found in the upper-right corner.

ridderr commented 1 year ago

Ok, thanks for the guidance. Was not aware of this :-(

trace automation.wake_up_pre_post_actions 2023-08-06T16_15_00.319693+00_00.zip

ridderr commented 1 year ago

Sorry, this works as designed. I thought it was related to the issue there is in the system. Will raise a new issue ones I have found the required information.

home-assistant / core