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>