Wait_for_trigger event not being seen?

  - alias: "Snapshot garage and send photo when motion detected"
    trigger:
      - platform: state
        entity_id: binary_sensor.garage_exterior_door
        from: 'off'
        to: 'on'
    action:
      - service: aarlo.camera_request_snapshot_to_file
        data:
          entity_id: camera.aarlo_garage
          filename: '/config/www/cameras/garage_latest.jpg'
      - wait_for_trigger:
        - platform: event
          event_type: aarlo_image_updated
        timeout: "00:01:00"
      - service: notify.mobile_app_andrew_phone
        data:
          message: "Motion in garage!"
          data:
            image: !secret garage_image_url

I have this automation in place and when I watch the event bus I see the aarlo_image_updated event pass by (and also see it in dev tools listener) but my automation only continues after timeout instead of after the event as Iā€™d expect.

2020-10-13 22:13:05 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=Snapshot garage and send photo when motion detected, entity_id=automation.snapshot_garage_and_send_photo_when_motion_detected>
2020-10-13 22:13:05 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=aarlo, service=camera_request_snapshot_to_file, service_data=entity_id=camera.aarlo_garage, filename=/config/www/cameras/garage_latest.jpg>
2020-10-13 22:13:11 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event aarlo_snapshot_updated[L]: entity_id=aarlo.garage>
2020-10-13 22:13:11 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event aarlo_image_updated[L]: entity_id=aarlo.garage>
2020-10-13 22:13:11 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event aarlo_snapshot_ready[L]: entity_id=camera.aarlo_garage, file=/config/www/cameras/garage_latest.jpg>
2020-10-13 22:13:15 DEBUG (MainThread) [homeassistant.core] Service did not complete before timeout: <ServiceCall automation.trigger (c:2d690ada0dcb11ebb8d9a9d9b73e7b3c): entity_id=['automation.snapshot_garage_and_send_photo_when_motion_detected'], variables=, skip_condition=True>
2020-10-13 22:14:11 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=notify, service=mobile_app_andrew_phone, service_data=message=Motion in garage!, data=image=https://FQDN/local/cameras/garage_latest.jpg>

What am I missing?

Itā€™s unclear to me why it fails to work. Itā€™s similar to the example in the documentation.

Possibly a bug?

It seems like it could be. I made another very simple automation with the event as a trigger and notification as the action and it fires as expected.

I copied your wait for trigger exactly, fired a fake event and it worked. Verify that your event_type is actually ā€˜aarlo_image_updatedā€™.

- id: '1602677251779'
  alias: wait for trigger test aneisch
  description: ''
  trigger:
  - platform: state
    entity_id: input_boolean.wait_for_trigger
    to: 'on'
  condition: []
  action:
  - service: persistent_notification.create
    data_template:
      message: Triggered at {{ as_timestamp(now()) | timestamp_custom("%I:%M %p")
        }}
  - wait_for_trigger:
    - platform: event
      event_type: aarlo_image_updated
    timeout: '00:01:00'
  - service: persistent_notification.create
    data_template:
      message: Wait for trigger at {{ as_timestamp(now()) | timestamp_custom("%I:%M
        %p") }}
  mode: single

I also notice that this automation will not wait for a trigger if you fire it again inside the 1 minute timeout. If you want it to reset, you need to change it to mode: restart

So to recap:

  1. Verify that your event_type is actually called aarlo_image_updated.
  2. Change mode: restart so that it can fire more than once per minute.

No bug that I can see. Just need to use the correct event and automation settings.

OPā€™s debug log reported this:

 <Event aarlo_image_updated[L]: entity_id=aarlo.garage>

Is the [L] part of the eventā€™s name or is that just an artifact of how the data is presented?

If itā€™s not an artifact, then the event name seems to be correct.

aarlo_image_updated

Nevertheless it doesnā€™t jibe with the positive results of your test. :thinking:

if the event_type is correct, then heā€™s running into the ā€˜singleā€™ automation waiting the full minute before triggering again ā€˜issueā€™. Which is not an issue, itā€™s just how single mode works.

EDIT: Let me turn on debug logging and retry

You got me thinking that might be the culprit but your test example used single mode and wait_for_trigger was successful. Interesting problem we have here.

Waiting to hear what your debug log reports.

Soā€¦

2020-10-14 12:50:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event aarlo_image_updated[R]: entity_id=xxx.yyy>

Not sure what the L or R signify.

Either way, the event_type appears to be the name of the event seen in the logs. I think we need @aneisch to subscribe to the event on the events page.

FWIW, iā€™ve seen this ā€˜restartā€™ trip up alot of people when it comes to wait_for_trigger. It acts the same way as delay. Itā€™s basically waiting for a trigger or the timeout before the automation can be fired again.

Sorry about that, I mean to include the even in my original post.

More logs:

2020-10-14 08:45:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=Snapshot garage and send photo when motion detected, entity_id=automation.snapshot_garage_and_send_photo_when_motion_detected>
2020-10-14 08:45:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=aarlo, service=camera_request_snapshot_to_file, service_data=entity_id=camera.aarlo_garage, filename=/config/www/cameras/garage_latest.jpg>
2020-10-14 08:45:26 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event aarlo_snapshot_updated[L]: entity_id=aarlo.garage>
2020-10-14 08:45:26 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event aarlo_image_updated[L]: entity_id=aarlo.garage>
2020-10-14 08:45:26 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event aarlo_snapshot_ready[L]: entity_id=camera.aarlo_garage, file=/config/www/cameras/garage_latest.jpg>
2020-10-14 08:45:31 DEBUG (MainThread) [homeassistant.core] Service did not complete before timeout: <ServiceCall automation.trigger (c:80e7864d0e2311ebaef9859348d55c06): entity_id=['automation.snapshot_garage_and_send_photo_when_motion_detected'], skip_condition=True, variables=>
2020-10-14 08:46:26 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=notify, service=mobile_app_andrew_phone, service_data=message=Motion in garage!, data=image=https://FQDN/local/cameras/garage_latest.jpg>
2020-10-14 08:46:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.snapshot_garage_and_send_photo_when_motion_detected, old_state=<state automation.snapshot_garage_and_send_photo_when_motion_detected=on; last_triggered=2020-10-14T08:45:21.425626-05:00, mode=single, current=1, friendly_name=Snapshot garage and send photo when motion detected @ 2020-10-13T22:18:11.191407-05:00>, new_state=<state automation.snapshot_garage_and_send_photo_when_motion_detected=on; last_triggered=2020-10-14T08:45:21.425626-05:00, mode=single, current=0, friendly_name=Snapshot garage and send photo when motion detected @ 2020-10-13T22:18:11.191407-05:00>>

Event from subscription:

Event 0 fired 8:45 AM:
{
    "event_type": "aarlo_image_updated",
    "data": {
        "entity_id": "aarlo.garage"
    },
    "origin": "LOCAL",
    "time_fired": "2020-10-14T13:45:26.604262+00:00",
    "context": {
        "id": "83fe155a0e2311eb8ead89753ede56b2",
        "parent_id": null,
        "user_id": null
    }
}

Looks like youā€™re using the correct event name.

A scriptā€™s default mode is single. Just for fun, set it to parallel. I doubt it will improve anything but letā€™s try it to, if for no other reason, eliminate it as a potential factor.

Same behavior when throwing in mode: parallel

Also FWIW the attributes show the count going to 1 then going back to 0. Never more than one when the automation is run.

last_triggered: 2020-10-14T14:03:34.586862+00:00
mode: parallel
current: 0
max: 10
friendly_name: Snapshot garage and send photo when motion detected

Good, because it shouldnā€™t have influenced the automationā€™s behavior in this particular case.
Bad, because now Iā€™m not sure where else to look.


EDIT

What I find interesting is that the first service call is at 08:45:21 but wait_for_trigger gives up waiting at 08:45:31. Thatā€™s not a minute, thatā€™s 10 seconds.

Looking at your debug messages, it appears as if the event is occurring before the wait trigger is starting or itā€™s occurring exactly when itā€™s starting.

Where are you seeing that?

At 08:45:21 the call to take the snapshot is made, at 08:45:26 the event fires letting us know that the snapshot has completed. At that time I expect that the automation will continue and close out.

but the final message (after the 1 minute timeout) occurs exactly 60 seconds after 08:45:26, not 08:45:21

Hereā€™s an abbreviated version of the log:

08:45:21 <automation_triggered: name=Snapshot garage and send photo when motion detected, entity_id=automation.snapshot_garage_and_send_photo_when_motion_detected>
08:45:21 <call_service: domain=aarlo, service=camera_request_snapshot_to_file, service_data=entity_id=camera.aarlo_garage, filename=/config/www/cameras/garage_latest.jpg>
08:45:26 <aarlo_snapshot_updated: entity_id=aarlo.garage>
08:45:26 <aarlo_image_updated: entity_id=aarlo.garage>
08:45:26 <aarlo_snapshot_ready: entity_id=camera.aarlo_garage, file=/config/www/cameras/garage_latest.jpg>
08:45:31 Service did not complete before timeout: <ServiceCall automation.trigger (c:80e7864d0e2311ebaef9859348d55c06): entity_id=['automation.snapshot_garage_and_send_photo_when_motion_detected'], skip_condition=True, variables=>
08:46:26 <call_service: domain=notify, service=mobile_app_andrew_phone, service_data=message=Motion in garage!, data=image=https://FQDN/local/cameras/garage_latest.jpg>
08:46:27 <state_changed: entity_id=automation.snapshot_garage_and_send_photo_when_motion_detected, old_state=<state automation.snapshot_garage_and_send_photo_when_motion_detected=on; last_triggered=2020-10-14T08:45:21.425626-05:00, mode=single, current=1, friendly_name=Snapshot garage and send photo when motion detected @ 2020-10-13T22:18:11.191407-05:00>, new_state=<state automation.snapshot_garage_and_send_photo_when_motion_detected=on; last_triggered=2020-10-14T08:45:21.425626-05:00, mode=single, current=0, friendly_name=Snapshot garage and send photo when motion detected @ 2020-10-13T22:18:11.191407-05:00>>

Thereā€™s something peculiar about the timestamps. The timestamp for ā€œService did not completeā€ ought to be closer (in time) to the end of the actionā€™s execution yet it occurs (08:45:31) almost a full minute before the last reported message (08:46:27).

Yes I agree, let me run a test. I think I have an idea of whatā€™s going on

EDIT: Iā€™m not getting this to occur

08:45:31 Service did not complete before timeout: <ServiceCall automation.trigger (c:80e7864d0e2311ebaef9859348d55c06): entity_id=['automation.snapshot_garage_and_send_photo_when_motion_detected'], skip_condition=True, variables=>

@aneisch try this:

script:
  take_snapshot:
    sequence:
      - service: aarlo.camera_request_snapshot_to_file
        data:
          entity_id: camera.aarlo_garage
          filename: '/config/www/cameras/garage_latest.jpg'

with this automation

  - alias: "Snapshot garage and send photo when motion detected"
    trigger:
      - platform: state
        entity_id: binary_sensor.garage_exterior_door
        from: 'off'
        to: 'on'
    action:
      - service: script.take_snapshot
      - wait_for_trigger:
        - platform: event
          event_type: aarlo_image_updated
        timeout: "00:01:00"
      - service: notify.mobile_app_andrew_phone
        data:
          message: "Motion in garage!"
          data:
            image: !secret garage_image_url

I think whatā€™s happening is that the service is finishing exactly when the wait is starting and the event is getting lost.

Hopefully this will fire the script and the wait_for_trigger should start prior to the event firing. I think youā€™ll see the timeout error go away too

BTWā€¦ Iā€™m triggering this automation via ā€œExecuteā€ button, not sure if itā€™s at all related.

Putting in the script and modification now.

No change.

I pruned out some of the script/automation state_changed lines, I donā€™t think they serve as anything but noise for this.

2020-10-14 10:00:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=automation, service=trigger, service_data=entity_id=automation.snapshot_garage_and_send_photo_when_motion_detected>
2020-10-14 10:00:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=Snapshot garage and send photo when motion detected, entity_id=automation.snapshot_garage_and_send_photo_when_motion_detected>
2020-10-14 10:00:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=script, service=take_garage_snapshot, service_data=>
2020-10-14 10:00:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event script_started[L]: name=take_garage_snapshot, entity_id=script.take_garage_snapshot>
2020-10-14 10:00:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=aarlo, service=camera_request_snapshot_to_file, service_data=entity_id=camera.aarlo_garage, filename=/config/www/cameras/garage_latest.jpg>
2020-10-14 10:00:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event aarlo_snapshot_ready[L]: entity_id=camera.aarlo_garage, file=/config/www/cameras/garage_latest.jpg>
2020-10-14 10:00:39 DEBUG (MainThread) [homeassistant.core] Service did not complete before timeout: <ServiceCall automation.trigger (c:0008a7900e2e11eba17697c4251d3c6c): entity_id=['automation.snapshot_garage_and_send_photo_when_motion_detected'], skip_condition=True, variables=>
2020-10-14 10:01:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=notify, service=mobile_app_andrew_phone, service_data=message=Motion in garage!, data=image=https://FQDN/local/cameras/garage_latest.jpg>