`Wait for a trigger` Caused Trigger to Occur?

Configuration
1

I recently added the following action as the first of multiple additional steps in an existing automation:

wait_for_trigger:
  - platform: state
    entity_id:
      - media_player.vlc_telnet
    to: idle
    for:
      hours: 0
      minutes: 0
      seconds: 0
timeout:
  hours: 0
  minutes: 6
  seconds: 0
  milliseconds: 0

The media played in VLC by the previous action is ~5:32 and played successfully each time this automation triggered until I added this wait to do more things after it finishes playing. No HAOS component version changes occurred between the normal instance and this odd one.

Before I added the wait to the automation, the VLC logbook entries looked like this:

First, when an automation would run:

VLC-TELNET changed to Playing triggered by automation Wake 2 triggered by time set in Wake 2 Time

Next, when the media stopped playing (by reaching the end of the file or me triggering a script that stops the player [tens of seconds to minutes later]):

VLC-TELNET changed to Idle

After I added the additional action to the automation, the logbook entries looked like this:

No change to the first entry when an automation would run:

VLC-TELNET changed to Playing triggered by automation Wake 2 triggered by time set in Wake 2 Time

Two seconds later before I was even aware the media was playing:

VLC-TELNET changed to Idle triggered by automation Wake 1 triggered by time set in Wake 1 Time

This is all set up via lovelace, so the relevant part of the Actions section in the automation looks like this in the visual editor:

Play media on VLC-TELNET

Wait for 'When VLC-TELNET changes to Idle'

The first action shown here is unchanged from when the automation worked, and the second one is new, matching the YAML at the beginning of this post. At first I was concerned that the “wait” was actually a “trigger and wait” but I searched and now believe the automation is configured correctly based on Wait for sequence to finish - #2 by 123 being a confirmed solution to something similar to what I was attempting.

The logbook entry makes it look like that action must have caused the media player to switch to idle, but I’m not sure if that’s actually what happened. There was also a notification that a login failed due to a bad password, and that notification seemed to imply that VLC-TELNET is what failed to log in. Unfortunately, I dismissed it before getting a screenshot or copying the text.

The relevant section of the trace timeline doesn’t appear to provide any additional useful information, but it looks something like this:

| *Play media on VLC-TELNET
|
| °(media_player.vlc_telnet) turned playing
|
| *Wait for ‘When VLC-TELNET changes to Idle’
|
| 2 seconds later
|
| °(media_player.vlc_telnet) turned idle

I can wait to see what happens next time this automation triggers in case this time was a fluke, and I can update this thread accordingly, but I wanted to go ahead and post this in the interim for a chance to get any insight on what may have happened and where I may need to look to prove it.

2

I’m not really sure what your question is. Is it about the message? All triggers produce the same message and provide the current context. The context does not change in an automation. Without seeing the full automation, it’s hard to say what the context should be. I can say that I’m not surprised that the verbiage is the same because they are both triggers and the context will be persistent throughout the automation.

3

Sorry I wasn’t clear. To the best of my knowledge, the automation shouldn’t trigger VLC to go to idle (the VLC logbook says the automation triggered it to go idle after the most recent run but only indicates that it went idle in prior runs). I guess the short version of my question is as follows:

Did the Wait for a trigger action which I expected to wait for VLC to finish playing media actually trigger VLC to stop playing media, or did something else happen to go wrong the very first time the previously working automation ran again after I added that action to the end of it?

ETA: I suspect the answer is that something else went wrong, in which case my question becomes how do I find out what went wrong given the various places I’ve already checked were inconclusive.

4

I don’t know because you aren’t posting your whole automation. It 100% depends on what all your triggers are.

5

OK, fair enough, I wouldn’t expect that, but I don’t know what I don’t know. What I do know is that the automation is super long and does everything exactly as I expect except for the behavior specific to the added wait function. I didn’t copy and paste it because the entire YAML automation is copying out of HA as one line (something I may need to test and report later on, quite possibly somehow related to the new copy/paste feature, but also potentially specific to my environment, and not my first priority since I hang out in lovelace where possible). Since full YAML is necessary to help, I tried to reproduce the issue with a new short automation and got the behavior I expect, so I may just need to wait until the next time the automation triggers to see if it was just a fluke, but here are two much shorter test automations that both worked exactly as I expect to better explain exactly why I think something else went wrong (even though I don’t know if it’s a fluke or where to gather appropriate diagnostic data):

With this, my first test, where I was hoping but failed to reproduce the issue, the All done notification does not occur until VLC is done playing (runtime was 16.43 seconds including ~2 seconds of tts generation):

alias: New Automation
description: ""
trigger:  - platform: time
    at: "01:23:00"
condition: []
action:
  - service: tts.reversotts_say
    data:  
    cache: false
      entity_id: media_player.vlc_telnet
      message: >-
        I just need to talk for a really long time to see if VLC stops playing
        before I am done talking.  What I have to say isn't important as it only
        serves the the goal of having a play time long enough for something else
        to break.
  - wait_for_trigger:
      - platform: state
        entity_id:
          - media_player.vlc_telnet
        to: idle
    timeout:
      hours: 0
      minutes: 1
      seconds: 0
      milliseconds: 0
  - service: notify.mobile_app_iphone
    data:
      message: All done.
mode: single

With this, a duplicate automation where I remove the wait to confirm my expected behaviors, the All done notification occurs while VLC continues to play and ultimately turns idle later (runtime was 0.55 seconds using cached tts):

alias: Old Automation
description: ""
trigger:  - platform: time
    at: "01:23:00"
condition: []
action:
  - service: tts.reversotts_say
    data:  
    cache: false
      entity_id: media_player.vlc_telnet
      message: >-
        I just need to talk for a really long time to see if VLC stops playing
        before I am done talking.  What I have to say isn't important as it only
        serves the the goal of having a play time long enough for something else
        to break.
  - service: notify.mobile_app_iphone
    data:
      message: All done.
mode: single

The much longer automation that I don’t want to manually reformat ater a copy/paste is also in single mode and also uses a time trigger (albeit from a time entity instead of a hard coded time). It also has conditions in case that could be relevant even though I wouldn’t expect it to be. It also uses media_player.play instead of tts.reversotts_say but the end result in either case is normally that VLC plays a media file and then switches back to idle.

Interestingly, neither of the test automations here lead to a “VLC-TELNET changed to Idle triggered by automation” logbook entry, and probably not-so-incidentally, the “VLC-TELNET changed to Idle” logbook entry is not included in the Related logbook entries section of Traces in either test case. To be clear, that is also not included in the same section of previous traces of the much longer automation even though “VLC-TELNET changed to Idle triggered by automation Wake 1 triggered by time set in Wake 1 Time” was included in the same section of the trace for today’s run.

Also, while laying this out, I remembered that even though I dismissed the warning, there should be a log, so here is the HOME ASSISTANT CORE log related to the notification that occurred when things went wrong:

Log Details (WARNING)

Logger: homeassistant.components.http.ban
Source: components/http/ban.py:82
Integration: HTTP (documentation, issues)
First occurred: 01:23:00 (1 occurrences)
Last logged: 01:23:00

Login attempt or request with invalid authentication from core-vlc.local.hass.io (172.30.33.2). Requested URL: ‘/media/local/amediafile.mp3?authSig=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiI0NGI1MzA5YWRhMGI0ZGJkYmJmNThmNzI2YTk3MzZkNiIsInBhdGgiOiIvbWVkaWEvbG9jYWwvS29ybiAtIEtvcm4gLSAwNyAtIFNob290cyBhbmQgTGFkZGVycy5tcDMiLCJwYXJhbXMiOltdLCJpYXQiOjE2ODk2NzA4MDAsImV4cCI6MTY4OTc1NzIwMH0.LYAj5TpqQhA7_K42WaBS7krjSpAxEX4X3x1T0caJiKY’. (VLC/3.0.18 LibVLC/3.0.18)

The time in the log matched the trigger time of the automation to the second, which is to be expected because all of the actions before media_player.play_media should only take milliseconds. I can report back next time the automation runs on whether or not it was a one-time fluke, and if it isn’t, then maybe I need to focus on the copy/paste issue and circle back to this when that YAML is manageable (I couldn’t find any hidden line breaks or carriage returns to replace in any of my editors, so the YAML above was reformatted by my manually hitting enter for each line). However, if it sounds like (or turns out to have been) a fluke, I guess I’m curious as to if and how I should report it since that would imply isn’t easily reproducible.

6

OK, so I have a lot of new information, but still no clue how to reach a resolution:

  • The issue didn’t recur when I manually ran the automation that originally had the problem.
  • The issue did recur when the same automation ran automatically again.
  • The authentication error does seem to be related to the issue, as that also recurred, so here is the authentication notification (probably not especially useful over the error information previously posted):

Login attempt failed

Login attempt or request with invalid authentication from core-vlc.local.hass.io (172.30.33.2). See the log for details.

  • The copy and paste issue appears to be specific to Safari, so I can now copy and paste the entire YAML.

I did some more testing thinking maybe it was one of the earlier steps in the automation triggering the issue, but I was unable to get the same issue to recur in my other automations. This is starting to look like a bug, but since I haven’t figured out the trigger to reproduce it, I can’t report it yet and could still use some help. I created a duplicate automation to try to reproduce this using a different input_datetime field and the issue didn’t recur, so this issue might not have anything at all to do with the wait. It may be feasible that the actual issue is VLC is failing to authenticate the first time one of its services is called after an amount of time has passed or the calendar day has changed, but I’m not sure why that change would have coincided with my updates to this automation. I may have added the volume adjustment service actions before the play media service action in the same edit where I added all of the actions after the play media service action, but I tried including the volume adjustment service action in my test automations without getting the same result, and it was (obviously) also included in my duplicate automation.

That having been said, while I no longer suspect that the automation is the issue (and certainly no longer suspect that the issue is specific to the Wait for a trigger action), here is the full automation edited to notate some things where the edits shouldn’t be relevant to the issue at hand:

alias: Wake 1
description: ""
trigger:
  - platform: time
    at: input_datetime.wake_1_time
condition:
  - condition: or
    conditions:
      - condition: template
        value_template: >-
          {{now().weekday()<5 and
          is_state('input_boolean.wake_1_weekday','on')}}
      - condition: template
        value_template: >-
          {{now().weekday()>4 and
          is_state('input_boolean.wake_1_weekend','on')}}
action:
  - service: input_boolean.turn_on
    data: {}
    target:
      entity_id: input_boolean.wake_1_triggered
  - service: nuvo_serial.snapshot
    data:
      entity_id:
        - media_player.master_suite
  - service: media_player.turn_on
    data: {}
    target:
      entity_id:
        - media_player.master_suite
  - service: media_player.volume_set
    data:
      volume_level: 0.4
    target:
      entity_id: media_player.master_suite
  - service: media_player.select_source
    data:
      source: Source 6
    target:
      entity_id: media_player.master_suite
  - service: media_player.volume_set
    data:
      volume_level: 0.55
    target:
      entity_id: media_player.vlc_telnet
  - service: media_player.play_media
    target:
      entity_id: media_player.vlc_telnet
    data:
      media_content_id: >-
        media-source://media_source/local/amediafilewheremineis.mp3
      media_content_type: audio/mpeg
    metadata:
      title: metadata copy/pasted from devtools, test automations worked the same with and without it
      thumbnail: null
      media_class: music
      children_media_class: null
      navigateIds:
        - {}
        - media_content_type: app
          media_content_id: media-source://media_source
  - wait_for_trigger:
      - platform: state
        entity_id:
          - media_player.vlc_telnet
        to: idle
        for:
          hours: 0
          minutes: 0
          seconds: 0
    timeout:
      hours: 0
      minutes: 6
      seconds: 0
      milliseconds: 0
  - service: media_player.select_source
    data:
      source: Tuner A
    target:
      entity_id: media_player.master_suite
  - delay:
      hours: 0
      minutes: 10
      seconds: 0
      milliseconds: 0
  - service: media_player.turn_off
    data: {}
    target:
      entity_id: media_player.master_suite
  - service: nuvo_serial.restore
    data:
      entity_id:
        - media_player.master_suite
  - if:
      - condition: state
        entity_id: media_player.basement
        state: "off"
      - condition: state
        entity_id: media_player.bonus_room
        state: "off"
      - condition: state
        entity_id: media_player.garage
        state: "off"
      - condition: state
        entity_id: media_player.kitchen
        state: "off"
      - condition: state
        entity_id: media_player.master_suite
        state: "off"
      - condition: state
        entity_id: media_player.office
        state: "off"
    then:
      - service: button.press
        data: {}
        target:
          entity_id: button.essentia_g_all_zones_off
  - service: input_boolean.turn_off
    data: {}
    target:
      entity_id: input_boolean.wake_1_triggered
mode: single

Anyway, if there is anything there that would change the behavior of the Wait for a trigger action vs the previous sample automations, knowing what may allow me to solve my problem, but as stated above, I’m guessing I need to be troubleshooting the VLC add-on at this point and not the automation itself, so please let me know if that means I should start a separate thread on that and mark this one as solved with a succinct “no it didn’t” resolution post.

ETA: There is a VLC log, but it is very sparse and probably basically says to look at the log I posted previously. It has the following entries, repeated a second time which makes me think they correspond with the two authentication incidents:

  • access stream error: HTTP 401 error
  • main input error: Your input can’t be opened
  • main input error: VLC is unable to open the MRL ‘https://ha.fqdn:port/media/local/amediafile.mp3?authSig=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiI0NGI1MzA5YWRhMGI0ZGJkYmJmNThmNzI2YTk3MzZkNiIsInBhdGgiOiIvbWVkaWEvbG9jYWwvS29ybiAtIEtvcm4gLSAwNyAtIFNob290cyBhbmQgTGFkZGVycy5tcDMiLCJwYXJhbXMiOltdLCJpYXQiOjE2ODk2NzA4MDAsImV4cCI6MTY4OTc1NzIwMH0.LYAj5TpqQhA7_K42WaBS7krjSpAxEX4X3x1T0caJiKY’. Check the log for details.
  • prefetch stream error: unimplemented query (264) in control

These logs appear to be recorded in 43520 (minus) 2b250 units of time during the original incident.

7

Ok, based on this automation, my previous response is correct. The context is the same throughout your automation. I.e. When an automation triggers, it tells you what’s triggering it. Which is why you’re getting triggered by New Automation because that automation contains the trigger.

8

OK, I think you are suggesting that the VLC logbook shows it switching to idle triggered by automation because the automation is still running when it switches to idle after being triggered to play by the automation. That could make sense, but when I cloned the automation and ran it with a different input_datetime helper to try to reproduce my issue, VLC played for the expected 5+ minutes while the automation waited for the VLC idle trigger. In that case, the VLC logbook shows it switched to idle, but doesn’t say it was triggererd by automation even though the automation started it playing and was still active (and waiting for idle just like it was in the other case) when it stopped. The VLC logbook only shows it switching to idle triggered by automation when it switches to idle after a single-digit number of seconds even though it should have been playing for a single digit number of minutes.

If you are telling me the automation is telling VLC to switch to idle, then I am sorry for being incredibly dense but would appreciate it if you could spell out for me exactly how and why it is doing that, because I’m not seeing anything to make me expect that in the UI or YAML.

Otherwise, my issue is that VLC is actually stopping when it shouldn’t be, or more likely, failing to start when triggered by the automation (which could explain the difference in the logbook in spite of what I think you’re trying to say), seemingly because it can’t access the media file when the trigger activates even though it can access the same media file when the same automation is manually run and was also successfully accessing the same media file when the trigger activated on the same automation prior to the changes discussed in this thread.

9

The automation you provided shows you’re only waiting for 1 minute for the trigger and you don’t define the continue_on_timeout.

It is not. It’s a trigger. I’m explaining the logbook, which you are miss interpreting.

This is a completely separate problem and the path you’re going down is a tangent.

10

Ah, this is the automation I wanted from the beginning.

So you’re saying that

fails after you add

?

12

This is what I originally thought, hence the original question in the subject. I no longer think that is the actual problem. As a mod, can you see my deleted post? I deleted it because I saw you had replied and thought we were on the same page, but if you can see it, maybe we stil aren’t.

ETA: I think one of us undeleted it. It was in reply to your post before the one it is beneath.

13

Also, maybe continue_on_timeout is a default? I mean, that YAML matches and the GUI looks like this:

Screenshot 2023-07-19 at 9.58.27 AM
Screenshot 2023-07-19 at 9.58.27 AM1038×339 14.9 KB

14

That’s most likely a failing service call that results in an IDLE state on the media player and is not related to the trigger.

15

It could default to true, I don’t have that memorized.

16

FYI, when debugging the automations, you shouldn’t be looking at the logbook for the single device. That’s what spiraled this conversation off the deep end.

You should follow the automation’s trace, which shows you exactly what happens when. It also shows you the full logbook for all entities associated with the automation.

image
image1509×707 31.6 KB

image
image1526×734 35.8 KB

You can click on each node as well and see what it did.

17

OK, so I think we agree that something failing is my problem and it shouldn’t be related to adding this wait action. That seems to be supported by the fact that this wait doesn’t cause the same issue when the same automation is run manually. Unfortunately, I’m not sure how to prove that out further because even if I set the wait trigger to include from: playing, the playing state appears to be detected in spite of the failure (per the logbook). Operating under the assumption that this is a failure, it’s difficult to reproduce while simultaneously being oddly consistent. I can guess that maybe it is being caused the first time VLC runs after a date change, but that doesn’t make a ton of sense assuming that I changed the automation as opposed to any version.

Auto update is not turned on in the add-on, but upon further consideration, it is possible that I installed 2023.7.2 and made these changes on different days which fell between the same automation runs. I don’t think so, as I believe the previous iteration of the automation worked fine on the day I made the edit, but before I made it, and my last backup lines up with the 2023.7.2 release, so I guess it’s feasible (I should have backed up again before editing the automation, but I didn’t, so I’m not 100% certain when I edited). In trying to verify that, I notice that 2023.7.4 is out per the release notes, so trying it in case anything changes seems reasonable, but the I’m seeing “No updates available” in Settings → System → Updates even after I hit the Check for updates button. Is that ever to be expected?

Regarding the tangent, I again apologize for being unclear, but I thought it was obvious whether or not the logbook was included in the trace from the “triggered by” verbiage. I’m probably making bad assumptions because I’m working backwards. I started in the logbook yesterday and landed on that particular logbook entry because the wait for trigger node specifically says that it changed to idle and I didn’t know why it switched to idle. I subsequently noticed that the VLC switch to idle logbook entry is only shown in traces when it says it was triggered by the automation (previous traces and test traces where the issue doesn’t occur don’t show the switch to idle log entry, and the switch to idle log entry in those cases doesn’t say it was triggered by the automation), so I thought all that was clear in my original post. Based on what you’re telling me, this may not be expected, either, and the trace supportingly also says “Not all shown logbook entries might be related to this automation.” OTOH, upon closer inspection, other logbook entries that are definitely triggered by the automation are also missing from the trace, so maybe that quote meant to say stomething like “All logbook entries related to this automation might not be shown.”

In either case, do you have any thoughts on how I might troubleshoot this further beyond just trying different things to see when/if I can get it to reproduce? Regarless, now that it looks like this is a VLC issue as opposed to a Wait for a trigger issue, should I start a new thread and/or edit the name of this one?

18

Click on each node, you can see the result of each node. It will tell you if it waited and how long it waited for it to trigger when going to idle… or if it timed out.

Yes, use the trace functionality I listed above to see what’s really happening. You can follow a trace for any automation and it shows you what it did.

19

The trace shows the automation working perfectly fine and has from the beginning. My original concern was whether I misunderstood what Wait for a trigger was supposed to do (I didn’t). My outstanding issue is that VLC stops playing prematurely (or fails to start playing even though it switches to a playing state when triggered) while I can’t find a cause to correct or figure out how to reproduce the behavior to report a bug.

20

I am no longer experiencing this issue and leave it behind with only the following two pieces of knowledge.

  1. This was NOT an automation problem, Wait for a trigger is NOT intended to cause a trigger and wasn’t (consistently or per the automation traces) causing a trigger in this case.

  2. Whatever was causing this behavior consistently for 1 automation only (not clones of it) when triggered only (not when run manually) went away with an HA restart (not even a reboot).