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
73.75k stars 30.87k forks source link

Error executing script. Unexpected error for call_service restore snapshot #108901

Closed smartmatic closed 6 months ago

smartmatic commented 9 months ago

The problem

I've created an automation which creates a snapshot of my homepods before sending a TTS. But there are issues to restore the snapshot that the music is played again after the TTS message.

What version of Home Assistant Core has the issue?

2024.1.5

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

Automation

Link to integration documentation on our website

https://www.home-assistant.io/docs/automation/

Diagnostics information

No response

Example YAML snippet

alias: "Benachrichtigung: Fenster offen nach Lüften"
description: ""
trigger:
  - platform: state
    entity_id:
      - binary_sensor.fenster_state
    to: "on"
    for:
      hours: 0
      minutes: 15
      seconds: 0
  - platform: state
    entity_id:
      - binary_sensor.fenster_state
    to: "on"
    for:
      hours: 0
      minutes: 20
      seconds: 0
  - platform: state
    entity_id:
      - sensor.kuche_dk_links_state
    to: open
    for:
      hours: 0
      minutes: 15
      seconds: 0
  - platform: state
    entity_id:
      - sensor.kuche_dk_rechts_state
    for:
      hours: 0
      minutes: 15
      seconds: 0
    to: open
condition:
  - condition: time
    before: "21:00:00"
    after: "06:00:00"
    weekday:
      - mon
      - tue
      - wed
      - thu
      - fri
      - sat
      - sun
    alias: zwischen 7 und 21 Uhr
  - condition: numeric_state
    entity_id: weather.smart_live
    attribute: temperature
    below: 15
action:
  - service: scene.create
    metadata: {}
    data:
      scene_id: homepod_alle
      snapshot_entities:
        - media_player.homepod_esszimmer
        - media_player.homepod_buero
        - media_player.anita
        - media_player.kuche
  - delay:
      hours: 0
      minutes: 0
      seconds: 2
      milliseconds: 0
  - service: media_player.media_pause
    target:
      entity_id:
        - media_player.anita
        - media_player.homepod_buero
        - media_player.homepod_esszimmer
        - media_player.kuche
    data: {}
  - service: media_player.volume_set
    metadata: {}
    data:
      volume_level: 0.35
    target:
      entity_id:
        - media_player.anita
        - media_player.homepod_buero
        - media_player.homepod_esszimmer
        - media_player.kuche
  - delay:
      hours: 0
      minutes: 0
      seconds: 2
      milliseconds: 0
  - service: tts.cloud_say
    metadata: {}
    data:
      cache: false
      entity_id: media_player.homepod
      message: >-
        Es sind noch Fenster {{ expand('binary_sensor.fenster_state') |
        selectattr('state', 'eq', 'on') | map(attribute='name') | list | join
        (',  ') }} offen
  - alias: Nachricht wenn iPhone Anita zu Hause
    if:
      - condition: state
        entity_id: binary_sensor.fenster_state
        state: "on"
      - condition: state
        entity_id: device_tracker.nitis_iphone
        state: home
    then:
      - service: notify.mobile_app_anitas_iphone
        data:
          title: Lüften
          message: >-
            Es sind noch {{ expand('binary_sensor.fenster_state') |
            selectattr('state', 'eq', 'on') | map(attribute='name') | list |
            join (',  ') }} offen
  - alias: Nachricht wenn iPhone Udo zu Hause
    if:
      - condition: state
        entity_id: binary_sensor.fenster_state
        state: "on"
      - condition: state
        state: home
        entity_id: device_tracker.udos_iphone
    then:
      - service: notify.mobile_app_udos_iphone
        data:
          title: Lüften
          message: >-
            Es sind noch {{ expand('binary_sensor.fenster_state') |
            selectattr('state', 'eq', 'on') | map(attribute='name') | list |
            join (',  ') }} offen
  - delay:
      hours: 0
      minutes: 0
      seconds: 30
      milliseconds: 0
  - service: media_player.media_pause
    target:
      entity_id:
        - media_player.anita
        - media_player.homepod_buero
        - media_player.homepod_esszimmer
        - media_player.kuche
    data: {}
  - delay:
      hours: 0
      minutes: 0
      seconds: 3
      milliseconds: 0
  - service: scene.turn_on
    metadata: {}
    target:
      entity_id: scene.homepod_alle
mode: single

Anything in the logs that might be useful for us?

Logger: homeassistant.components.automation.benachrichtigung_fenster_offen
Source: helpers/script.py:476
Integration: Automatisierung (documentation, issues)
First occurred: 09:14:19 (1 occurrences)
Last logged: 09:14:19

Benachrichtigung: Fenster offen nach Lüften: Error executing script. Unexpected error for call_service at pos 12: gdjb.podbean.com/973de4fc-b80a-3254-9d1f-8f50e9d95eca
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 476, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 713, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 675, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2149, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2186, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 272, in handle_service
    return await service.entity_service_call(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 882, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 952, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/scene/__init__.py", line 114, in _async_activate
    await self.async_activate(**kwargs)
  File "/usr/src/homeassistant/homeassistant/components/homeassistant/scene.py", line 371, in async_activate
    await async_reproduce_state(
  File "/usr/src/homeassistant/homeassistant/helpers/state.py", line 67, in async_reproduce_state
    await asyncio.gather(
  File "/usr/src/homeassistant/homeassistant/helpers/state.py", line 61, in worker
    await platform.async_reproduce_states(
  File "/usr/src/homeassistant/homeassistant/components/media_player/reproduce_state.py", line 144, in async_reproduce_states
    await asyncio.gather(
  File "/usr/src/homeassistant/homeassistant/components/media_player/reproduce_state.py", line 116, in _async_reproduce_states
    await call_service(
  File "/usr/src/homeassistant/homeassistant/components/media_player/reproduce_state.py", line 59, in call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2149, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2186, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 272, in handle_service
    return await service.entity_service_call(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 882, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 952, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/media_player.py", line 300, in async_play_media
    await self.atv.stream.stream_file(media_id)
  File "/usr/local/lib/python3.11/site-packages/pyatv/core/facade.py", line 371, in stream_file
    await self.relay("stream_file")(
  File "/usr/local/lib/python3.11/site-packages/pyatv/protocols/raop/__init__.py", line 360, in stream_file
    audio_file = await open_source(
                 ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyatv/protocols/raop/audio_source.py", line 730, in open_source
    return await FileSource.open(source, sample_rate, channels, sample_size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyatv/protocols/raop/audio_source.py", line 669, in open
    src = await loop.run_in_executor(
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/miniaudio.py", line 943, in decode_file
    filenamebytes = _get_filename_bytes(filename)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/miniaudio.py", line 815, in _get_filename_bytes
    raise FileNotFoundError(filename)
FileNotFoundError: gdjb.podbean.com/973de4fc-b80a-3254-9d1f-8f50e9d95eca

Logger: homeassistant.core
Source: core.py:2165
First occurred: 09:13:53 (1 occurrences)
Last logged: 09:13:53

Error executing service: <ServiceCall media_player.play_media (c:01HN2D9V9E754RF7F81147V8AD): entity_id=['media_player.anita', 'media_player.homepod_buero', 'media_player.kuche', 'media_player.homepod_esszimmer'], extra=, media_type=music, media_id=media-source://tts/cloud?message=Es+sind+noch+Fenster+WC+Fenster,++Bad+Fenster+offen&cache=false>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 2165, in _run_service_call_catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 2186, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 272, in handle_service
    return await service.entity_service_call(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 907, in entity_service_call
    raise result from None
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1497, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 952, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/media_player.py", line 300, in async_play_media
    await self.atv.stream.stream_file(media_id)
  File "/usr/local/lib/python3.11/site-packages/pyatv/core/facade.py", line 371, in stream_file
    await self.relay("stream_file")(
  File "/usr/local/lib/python3.11/site-packages/pyatv/protocols/raop/__init__.py", line 360, in stream_file
    audio_file = await open_source(
                 ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyatv/protocols/raop/audio_source.py", line 729, in open_source
    return await InternetSource.open(source, sample_rate, channels, sample_size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyatv/protocols/raop/audio_source.py", line 610, in open
    raise ProtocolError(source.error_message) from ex
pyatv.exceptions.ProtocolError: Got status 404 with message: Not Found

Logger: pyatv.support.http
Source: runner.py:188
First occurred: 09:13:53 (1 occurrences)
Last logged: 09:13:53

Got response without having a request: HttpResponse(protocol='RTSP', version='1.0', code=200, message='OK', headers={'Date': 'Fri, 26 Jan 2024 08:13:53 GMT', 'Content-Length': '0', 'Server': 'AirTunes/750.14.2', 'CSeq': '12'}, body='')

Additional information

No response

joostlek commented 9 months ago

Core of the issue seems to be FileNotFoundError: gdjb.podbean.com/973de4fc-b80a-3254-9d1f-8f50e9d95eca

I am now curious if this is an atv issue or a tts.cloud_say issue. What integration provides that service?

joostlek commented 9 months ago

atv could maybe use some better error handling here tho, so I will tag it atv anyway

home-assistant[bot] commented 9 months ago

Hey there @postlund, mind taking a look at this issue as it has been labeled with an integration (apple_tv) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `apple_tv` 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 apple_tv` 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)


apple_tv documentation apple_tv source (message by IssueLinks)

smartmatic commented 9 months ago

Core of the issue seems to be FileNotFoundError: gdjb.podbean.com/973de4fc-b80a-3254-9d1f-8f50e9d95eca

I am now curious if this is an atv issue or a tts.cloud_say issue. What integration provides that service?

I think HA. The services i am using are scene.create and scene.turn_on May be an atv issue. I see in the automation trace that only the last action fails with error:

Stopped because an error was encountered at 26. Januar 2024 um 09:14:19 (runtime: 38.26 seconds)

gdjb.podbean.com/973de4fc-b80a-3254-9d1f-8f50e9d95eca

joostlek commented 9 months ago

I just pointed to the right line in the logs, it's complaining about that the file is not found, so: is the file generated correctly? That's done by the tts.cloud_say afaict

smartmatic commented 9 months ago

Hmm, which file? So i hear the TTS message.

joostlek commented 9 months ago

Please read my first comment again. A file is generated with your message and sent to the apple_tv, but that can't play it because it can't find the file

smartmatic commented 9 months ago

Please read my first comment again. A file is generated with your message and sent to the apple_tv, but that can't play it because it can't find the file

That's understood and i read your first comment but i don't know what i should answer. I have attached the yaml from the automation in the issue description. Does a TTS message create a file?

joostlek commented 9 months ago

tts.cloud_say is apparently generating a file gdjb.podbean.com/973de4fc-b80a-3254-9d1f-8f50e9d95eca and sending that to the apple_tv. but it can't find it

smartmatic commented 9 months ago

Yes but for me it's a strange behaviour as the automation sends the notification (TTS). That part works. Why this file is send again to apple_tv does not make sense for me. The last action in my automation is not working and thats the restore of the created scene from the first action.

joostlek commented 9 months ago

Can you send the scene?

smartmatic commented 9 months ago

For whatever reason currently not. I got a message that my media player is already playing a stream but the device is idle.

joostlek commented 9 months ago

No I mean, can you send it here?

smartmatic commented 9 months ago

No I mean, can you send it here?

Unfortunately not, i can only execute the scene but not open it to. Bildschirmfoto 2024-01-26 um 11 14 29

joostlek commented 9 months ago

Where does this scene come from?

smartmatic commented 9 months ago

It's created when you define the action. You get only the new scene if you run once the action. Then the scene will be cretaed. Bildschirmfoto 2024-01-26 um 11 32 00

joostlek commented 9 months ago

Oooh, I get it now.

I think the media source you were connecting to just isn't available anymore, causing this behaviour

joostlek commented 9 months ago

Like I don't know what you were listening, but that was available at that URL. but it wasn't anymore after the notification

smartmatic commented 9 months ago

So it's a bug or can scene.create with snapshots only used for lights? I tought thats the trick that the snapshot records the state which contains the information what i am listening?

joostlek commented 9 months ago

I mean it does restore the state, because it tries to play the same thing but the file it was playing (file/url) is not found.

smartmatic commented 9 months ago

How can it solved?

joostlek commented 9 months ago

I mean it does what you want but it can't be found. Again, I don't know what file or media you were playing when you executed this. This might work with some media and might not with others

smartmatic commented 9 months ago

Different sources like radio stations selected with the radio browser but also apple music or apple podcasts.

issue-triage-workflows[bot] commented 6 months ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.