home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
68.78k stars 28.11k forks source link

2 automations triggered by (almost) indentical trigger wont fire an identical script #116186

Closed Mariusthvdb closed 1 week ago

Mariusthvdb commented 1 week ago

The problem

as title, and see below automations.

they are basically identical, with the sole difference there is a second trigger for a second device on one of them.

If I long press the button, and both automations are enable (not commented) I recieve the notifications of both automations, but neither of them fire the first service, the script.

I only found this out by accident, and it is by no means my intention to keep both automations.

I do feel however they should both turn on the script in the first step in the action block (note that script is of mode: restart.)

If I comment either automation, the action blocks are executed correctly, and both run the script just fine.

Ive also tested this script blocking and not blocking, but that didnt make a difference.

Given the fact I am beta running 2024.5.0b0, I figured it could have to do with some changes in script behavior? this was changed https://github.com/home-assistant/core/pull/115340 but tbh, I wouldnt know the deeper workings of this tbh..

If not, then please consider this a regular issue

What version of Home Assistant Core has the issue?

2024.5.0b0

What was the last working version of Home Assistant Core?

Since I only started using the automations recently, I couldn't say if this also happened on 2024.4.x

What type of installation are you running?

Home Assistant OS

Integration causing the issue

automation script

Link to integration documentation on our website

https://rc.home-assistant.io/integrations/automation https://rc.home-assistant.io/integrations/script/

Diagnostics information

No response

Example YAML snippet

- id: 1710584381827-xyz
  alias: Sneltoets bureau M en W long press
  description: ''
  trigger:
  - platform: state
    entity_id:
    - event.sneltoets_bureau_marijn
    - event.sneltoets_bureau_wijke
  condition:
  - condition: state
    entity_id: binary_sensor.ouders
    state: 'on'
  - condition: or
    conditions:
    - condition: state
      entity_id: event.sneltoets_bureau_marijn
      attribute: event_type
      state: long_press
    - condition: state
      entity_id: event.sneltoets_bureau_wijke
      attribute: event_type
      state: long_press
  action:
  - service: script.aan_de_slag
    metadata: {}
    data: {}
  - service: notify.mobile_app_marijn
    metadata: {}
    data:
      message: lang ingedrukt
      title: M en W ingedrukt
  mode: single

- id: 1710584381827
  alias: Sneltoets bureau M long press
  description: ''
  trigger:
  - platform: state
    entity_id: event.sneltoets_bureau_marijn
  condition:
  - condition: state
    entity_id: binary_sensor.ouders
    state: 'on'
  - condition:
    - condition: state
      entity_id: event.sneltoets_bureau_marijn
      attribute: event_type
      state: long_press
  action:
  - service: script.aan_de_slag
    metadata: {}
    data: {}
  - service: notify.mobile_app_marijn
    metadata: {}
    data:
      message: lang ingedrukt
      title: M ingedrukt
  mode: single

I also tried with device_trigger:

  - platform: device
    device_id: 3bc8c04f5be5ac97bc1376bc244a2420
    domain: homekit_controller
    type: button1
    subtype: long_press

Anything in the logs that might be useful for us?

nothing

Additional information

No response

home-assistant[bot] commented 1 week ago

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

Code owner commands Code owners of `automation` 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 automation` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)


automation documentation automation source (message by IssueLinks)

bdraco commented 1 week ago

To be able to replicate this one, you'll also need to include script.aan_de_slag

Mariusthvdb commented 1 week ago

sure:

  aan_de_slag:
    mode: restart
    sequence:
      - service: script.turn_on
        target:
          entity_id:
            - script.aan_de_slag_select
            - script.scene_aan_de_slag
            - script.turn_on_kantoor_wijke
            - script.turn_on_kantoor_library
      - service: switch.turn_off
        target:
          entity_id:
            - switch.toaster_keuken
            - switch.slaapkamer_bed_outlet
            - switch.slaapkamer_google
            - switch.netwerk_auditorium
      - service: switch.turn_on
        target:
          entity_id: switch.switch_48_poe_port_32_poe #bluetooth_proxy_centraal
      - service: script.switch_tv_library_off
bdraco commented 1 week ago

Looks like it calls yet another script. Can you come up with a simple way to reproduce the problem that doesn't require more than 3 scripts?

Mariusthvdb commented 1 week ago

yes, and that makes it even more obvious. Ive changed the script into

script:

  test_sneltoets_trigger:
    mode: restart
    sequence:
      - service: switch.turn_on
        target:
          entity_id: switch.toaster_keuken

and call that instead of the former like:

    action:
      - service: script.test_sneltoets_trigger

      - service: notify.mobile_app_marijn
        metadata: {}
        data:
          message: M lang ingedrukt
          title: M ingedrukt

in both.

Same effect. I get 2 notifications, but the script is not executed. there is no error in the log. there seems to be an error in the trace rendering the graph so this is the download

trace automation.sneltoets_bureau_marijn_long_press 2024-04-25T18_54_55.962518+00_00.json

this is remarkable, the script remains 'on'

Scherm­afbeelding 2024-04-25 om 20 58 56 Scherm­afbeelding 2024-04-25 om 20 59 56

and cant be cancelled....

I can click the exectute button, and then the switch is finally toggled.

Note:

For testing purposes, I now used a device_trigger on the single entity trigger automation, and the event triggers for the double entity trigger automation.

Apparently that all has no meaning, and it is the fact the script is being called by both, that is somehow blocking correct execution

bdraco commented 1 week ago

So I'm writing a test for the right thing, can you post the exact full slimmed down test scripts?

Mariusthvdb commented 1 week ago

Sure but it’s really all here https://github.com/home-assistant/core/issues/116186#issuecomment-2077969025

that’s all the automation does now

Mariusthvdb commented 1 week ago

ok, so I got a new Shelly BLU ;-)

figured let me test the same scenario, and the outcome is exactly the same. Running below with scripts, does not toggle the light, and, keeps the script in the 'on' state for ever.

using the light.toggle service simply toggles the light once. (which tbh is also a bit surprising...)

Both (script or light.toggle) execute the second notification service.

Always. 100 % reproducible.

script:
  test_shelly_blu_trigger:
    mode: restart
    sequence:
      - service: light.toggle
        target:
          entity_id: light.eettafel

automation:

##########################################################################################
# test

  - id: sneltoets_shelly_blu_long_press
    alias: Sneltoets Shelly Blu long press
    mode: single
    description: ''
    trigger:
      - platform: state
        entity_id: event.shelly_blu_button1_7d75_button
    condition:
      condition: state
      entity_id: event.shelly_blu_button1_7d75_button
      attribute: event_type
      state: long_press
    action:
      - service: script.test_shelly_blu_trigger
#       - service: light.toggle
#         metadata: {}
#         data: {}
#         target:
#           entity_id: light.eettafel
      - service: notify.mobile_app_marijn
        metadata: {}
        data:
          message: Shelly Blu
          title: Shelly Blu long press

  - id: sneltoets_shelly_blu_long_press_copy
    alias: Sneltoets Shelly Blu long press copy
    mode: single
    description: ''
    trigger:
      - platform: state
        entity_id: event.shelly_blu_button1_7d75_button
    condition:
      condition: state
      entity_id: event.shelly_blu_button1_7d75_button
      attribute: event_type
      state: long_press
    action:
      - service: script.test_shelly_blu_trigger
#       - service: light.toggle
#         metadata: {}
#         data: {}
#         target:
#           entity_id: light.eettafel
      - service: notify.mobile_app_marijn
        metadata: {}
        data:
          message: Shelly Blu copy
          title: Shelly Blu long press
bdraco commented 1 week ago

From reading that script, it looks like it would be fast enough now to toggle the light twice, so it would not change state

Mariusthvdb commented 1 week ago

yeah well, that is what I figured, and thats why I also tested it with turn_on.

nothing happening. that is, the light is not turned on, the notification is sent correctly for both.

I just checked the traces, and surprisingly, they both state none of the actions were executed:

Scherm­afbeelding 2024-04-26 om 14 17 15

and yet they were...

IMG_4393

bdraco commented 1 week ago

I'm going to set this up for testing. I'll create input_boolean.test_toggle and than

automation 1

alias: fire toggle on binary_sensor.test_sensor off on 1
description: ""
trigger:
  - platform: state
    entity_id:
      - binary_sensor.test_sensor
    from: "off"
    to: "on"
condition: []
action:
  - service: script.fire_toggle
    metadata: {}
    data: {}
mode: single

automation 2

alias: fire toggle on binary_sensor.test_sensor off on 2
description: ""
trigger:
  - platform: state
    entity_id:
      - binary_sensor.test_sensor
    from: "off"
    to: "on"
condition: []
action:
  - service: script.fire_toggle
    metadata: {}
    data: {}
mode: single
alias: fire toggle
sequence:
  - service: input_boolean.toggle
    metadata: {}
    data: {}
    target:
      entity_id: input_boolean.test_toggle
mode: restart
Mariusthvdb commented 1 week ago

using the direct service: light turned on, notification sent

trace

Scherm­afbeelding 2024-04-26 om 14 20 39
bdraco commented 1 week ago
2024-04-26 07:22:45.794 INFO (MainThread) [homeassistant.components.automation.fire_toggle_on_binary_sensor_test_sensor_off_on_2] fire toggle on binary_sensor.test_sensor off on 2: Running automation actions
2024-04-26 07:22:45.794 INFO (MainThread) [homeassistant.components.automation.fire_toggle_on_binary_sensor_test_sensor_off_on_2] fire toggle on binary_sensor.test_sensor off on 2: Executing step call service
2024-04-26 07:22:45.795 INFO (MainThread) [homeassistant.components.script.fire_toggle] fire toggle: Restarting
2024-04-26 07:22:45.795 INFO (MainThread) [homeassistant.components.automation.fire_toggle_on_binary_sensor_test_sensor_off_on_1] fire toggle on binary_sensor.test_sensor off on 1: Running automation actions
2024-04-26 07:22:45.795 INFO (MainThread) [homeassistant.components.automation.fire_toggle_on_binary_sensor_test_sensor_off_on_1] fire toggle on binary_sensor.test_sensor off on 1: Executing step call service
2024-04-26 07:22:45.796 INFO (MainThread) [homeassistant.components.script.fire_toggle] fire toggle: Restarting
2024-04-26 07:22:45.802 INFO (MainThread) [homeassistant.components.script.fire_toggle] fire toggle: Running script sequence
2024-04-26 07:22:45.803 INFO (MainThread) [homeassistant.components.script.fire_toggle] fire toggle: Running script sequence
Mariusthvdb commented 1 week ago

I'm going to set this up for testing. I'll create input_boolean.test_toggle and than

please also add a second action with the notification?

bdraco commented 1 week ago

If I run it manually I get

2024-04-26 07:24:45.645 INFO (MainThread) [homeassistant.components.script.fire_toggle] fire toggle: Restarting
2024-04-26 07:24:45.648 INFO (MainThread) [homeassistant.components.script.fire_toggle] fire toggle: Running script sequence
2024-04-26 07:24:45.648 INFO (MainThread) [homeassistant.components.script.fire_toggle] fire toggle: Executing step call service

So in your test case the step never executes

Mariusthvdb commented 1 week ago

correct, and the script remains 'on'.

bdraco commented 1 week ago

ok I know whats wrong

bdraco commented 1 week ago

unfortunately when I fix it several tests fail so it means we have some bad tests

bdraco commented 1 week ago

Its the recursive automation protection

bdraco commented 1 week ago
         - tests/components/automation/test_init.py:2653 test_recursive_automation_starting_script[True-restart-script1: Disallowed recursion detected-parallel-2]
         - tests/components/automation/test_init.py:2782 test_recursive_automation[True-restart]

These tests fail when I fix the issue

Mariusthvdb commented 1 week ago

well, that's good isnt it, some bad tests are discovered. or, cant they be fixed...?

bdraco commented 1 week ago

Fixable. Its going to be hard to fix though

Mariusthvdb commented 1 week ago

really sorry, though I am glad you can at least confirm the 'issue', and I wasnt going mad here. it might be an edge case? I did stumble on them when playing around, not by purposely creating an edge case. so maybe not so far fetched as we might hope

btw, I did just now test this again with light.toggle in both automations, and the light is in fact only toggled once, so a state change can be experienced.

not sure if that is also an edge case, as, like you said, it should have been possible (expected maybe even?) that toggling twice would have gone unnoticed. in both automations traces the toggle is shown as executed ;-)

Mariusthvdb commented 1 week ago

btw Nick, could it be the enumeration on these devices is incorrect:

event_types: press, double_press, triple_press, long_press, long_double_press, long_triple_press

those long_double_press and long_triple_press seem impossible, and checking the Shelly manual on them, they are not listed there either.

Scherm­afbeelding 2024-04-26 om 14 44 59

which would stand for press, double_press, triple_press and long_press ? issued his to be sure: https://github.com/home-assistant/core/issues/116245

bdraco commented 1 week ago

I'm not sure I can fix this without removing the Disallowed recursion detected checks

Mariusthvdb commented 1 week ago

just for being 100% sure, I changed 1 script. So the 2 scripts are identical except for the script they run I the first step of the action block: both run correctly. So it 100% boils down to those script being the same

bdraco commented 1 week ago

There is a sleep in the restart path to yield to the event loop, and if I remove, it fixes the issue. However it regresses:

https://github.com/home-assistant/core/issues/68004 https://github.com/home-assistant/core/pull/68178

bdraco commented 1 week ago

So what is happening is the sleep runs and than each script is started and they stop each other because the mode is restart and neither gets to run

Mariusthvdb commented 1 week ago

wow, and thanks! (and confess I had forgotten about https://github.com/home-assistant/core/issues/68004)