core: Service media_player.volume_set fails for AppleTV/Homepods #2

The problem

Hello,

I get an timeout error with the last beta as well as the stable version of home assistant starting from 2022.08 up to the current Home Assistant stable version if I want to set the volume of my homepods with the help of the service “media_player.volume_set”. This is a follow up issue of #72618. It is not working as expected. The volume can not be changed.

There is a workaround by calling media_player.media_stop first, then media_player.volume_set. However, you lost the information about the current media play.

What version of Home Assistant Core has the issue?

core-2022.08 up to core-2023.5.4

What was the last working version of Home Assistant Core?

core-2022.5.3

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Apple_TV

Link to integration documentation on our website

https://www.home-assistant.io/integrations/apple_tv/

Diagnostics information

No response

Example YAML snippet

service: media_player.volume_set
data:
  volume_level: 0.3
target:
  entity_id: media_player.kue_media_homepod_friday

Anything in the logs that might be useful for us?

Logger: homeassistant.helpers.script.websocket_api_script
Source: components/apple_tv/media_player.py:492
First occurred: 11:18:09 (2 occurrences)
Last logged: 11:18:18

websocket_api script: Error executing script. Unexpected error for call_service at pos 1:
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/asyncio/locks.py", line 214, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 447, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 680, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1713, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1750, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 676, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 930, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 713, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/media_player.py", line 492, in async_set_volume_level
    await self.atv.audio.set_volume(volume * 100.0)
  File "/usr/local/lib/python3.10/site-packages/pyatv/core/facade.py", line 443, in set_volume
    await self.relay("set_volume")(level)
  File "/usr/local/lib/python3.10/site-packages/pyatv/protocols/mrp/__init__.py", line 756, in set_volume
    await asyncio.wait_for(self._volume_event.wait(), timeout=5.0)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError


Logger: homeassistant.components.websocket_api.http.connection
Source: components/apple_tv/media_player.py:492
Integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 11:24:22 (1 occurrences)
Last logged: 11:24:22

[2571583984]
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/asyncio/locks.py", line 214, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 199, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1713, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1750, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 676, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 930, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 713, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/media_player.py", line 492, in async_set_volume_level
    await self.atv.audio.set_volume(volume * 100.0)
  File "/usr/local/lib/python3.10/site-packages/pyatv/core/facade.py", line 443, in set_volume
    await self.relay("set_volume")(level)
  File "/usr/local/lib/python3.10/site-packages/pyatv/protocols/mrp/__init__.py", line 756, in set_volume
    await asyncio.wait_for(self._volume_event.wait(), timeout=5.0)
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

Additional information

No response

About this issue

Original URL
State: closed
Created 2 years ago
Comments: 22 (2 by maintainers)

Most upvoted comments

@postlund, I am observing the following behavior, which may be helpful in troubleshooting:

If I set the volume explicitly via volume_set, the playback volume on my HomePod mini DOES change. However, the volume_level attribute DOES NOT change on the media_player entity, the TimeoutError mentioned above is thrown in logs, and Failed to call service media_player/volume_set. is shown in the frontend.
If I try to incrementally change the volume through volume_up and volume_down, the playback volume on the HomePod Mini DOES NOT change, nor is any change reflected in the volume_level attribute of the media_player entity. This also throws the errors mentioned above.

So what I find interesting is that no matter what service is called from Home Assistant, the volume_level attribute does not change - even if (in the case of volume_set) the volume is actually changed on the device itself. I’m wondering if the errors are being thrown because the integration is waiting performing a calculation or validation when trying to change the volume, and this logic fails because the volume_level attribute never updates.

Final observation - I also now see that the volume_level attribute also does not change when I adjust the volume via my iPhone, or directly on the HomePod itself. However, if I reload the integration, the attribute DOES update to the correct value, but fails to register any subsequent changes.

UPDATE: After working through the code some more, I wondering if VOLUME_DID_CHANGE messages are no longer being sent (or received)?

MizterB on Jan 23, 2023

@postlund: I installed the stable version of 2022.08 and the error still exists. The service is not working properly. Now, I get the timeout error (see first post).

Gloomyeye on Aug 4, 2022

This is fixed in the release coming out today.

EDIT: or at least it should be.

postlund on Aug 3, 2022

The error still exists in 2022.11.0. The workaround, by calling media_player.media_stop first, then media_player.volume_set is working. However, you lost the information abot the current or last media play.

Gloomyeye on Nov 4, 2022

I’m still having the volume issues in 2022.9.7.

I found a workaround, by calling media_player.media_stop first, then media_player.volume_set

stevesreed on Sep 28, 2022