Spotify connect devices not found with multiple accounts

tikeyknax commented 1 year ago

I'm using spotcast with multiple spotify accounts and on different spotify connect devices. It works nicely if the spotify account I'm using in spotcast is the last one that played anything on the spotify connect device that I'm using. However, if the other spotify account was recently using that device, it fails with a "Device not found" or "Could not find device" error, see log below.

I'm not sure but this might be a restriction of spotify itself, so maybe it cannot be fixed in spotcast. If not, maybe a workaround to use the account that last played on the device could be used. I'm currently using such a workaround in my script:

spotify_play:
    alias: Spotify Play
    description: 'Play playlist in Spotify'
    sequence:
        - variables:
            # For debugging, use fixed media otherwise it comes from MQTT
            # media: spotify:playlist:718z1xDP4P2qzJzy8lidGc
            # Get the target_device_name from the input select. These names have
            # to match the names that are shown in the spotify accounts
            # source_list.
            target_device_name: "{{ states('input_select.musicbox_target_device') }}"
            # Check which account was playing last on the target device as only
            # this account can be used:
            spotify_account: >
              {% if target_device_name in (state_attr('media_player.spotify_thomas', 'source_list'))|trim %} thomas
              {% elif target_device_name in (state_attr('media_player.spotify_anna', 'source_list'))|trim %} anna
              {% else %} error in the automation
              {% endif %}
        - service: logbook.log
          data:
            name: MusicBox
            message:  >
              starts playing spotify on '{{ target_device_name }}' with account '{{ spotify_account }}' media '{{ media }}'
        - service: spotcast.start
          data:
            device_name: '{{ target_device_name }}'
            random_song: false
            repeat: "off"
            start_volume: 22
            account: '{{ spotify_account }}'
            uri: '{{ media }}'

Log with spotify_device_id:

Oct 22 19:31:43 server-pi python[142640]: 2022-10-22 19:31:43.100 INFO (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Running script sequence
Oct 22 19:31:43 server-pi python[142640]: 2022-10-22 19:31:43.101 INFO (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Executing step setting variables
Oct 22 19:31:43 server-pi python[142640]: 2022-10-22 19:31:43.103 INFO (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Executing step call service
Oct 22 19:31:43 server-pi python[142640]: 2022-10-22 19:31:43.106 INFO (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Executing step call service
Oct 22 19:31:43 server-pi python[142640]: 2022-10-22 19:31:43.415 ERROR (SyncWorker_3) [spotipy.client] HTTP Error for PUT to https://api.spotify.com/v1/me/player/play?device_id=055a55a152a33ae1fec9bc657e83091d2ab31c28 with Params: {} returned 404 due to Device not found
Oct 22 19:31:43 server-pi python[142640]: 2022-10-22 19:31:43.420 ERROR (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Error executing script. Unexpected error for call_service at pos 3: http status: 404, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=055a55a152a33ae1fec9bc657e83091d2ab31c28:
Oct 22 19:31:43 server-pi python[142640]:  Device not found, reason: None
Oct 22 19:31:43 server-pi python[142640]: Traceback (most recent call last):
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/spotipy/client.py", line 245, in _internal_call
Oct 22 19:31:43 server-pi python[142640]:     response.raise_for_status()
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/requests/models.py", line 1021, in raise_for_status
Oct 22 19:31:43 server-pi python[142640]:     raise HTTPError(http_error_msg, response=self)
Oct 22 19:31:43 server-pi python[142640]: requests.exceptions.HTTPError: 404 Client Error: Not Found for url: https://api.spotify.com/v1/me/player/play?device_id=055a55a152a33ae1fec9bc657e83091d2ab31c28
Oct 22 19:31:43 server-pi python[142640]: During handling of the above exception, another exception occurred:
Oct 22 19:31:43 server-pi python[142640]: Traceback (most recent call last):
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 451, in _async_step
Oct 22 19:31:43 server-pi python[142640]:     await getattr(self, handler)()
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 684, in _async_call_service_step
Oct 22 19:31:43 server-pi python[142640]:     await service_task
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1738, in async_call
Oct 22 19:31:43 server-pi python[142640]:     task.result()
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1781, in _execute_service
Oct 22 19:31:43 server-pi python[142640]:     await self._hass.async_add_executor_job(
Oct 22 19:31:43 server-pi python[142640]:   File "/usr/lib/python3.9/concurrent/futures/thread.py", line 52, in run
Oct 22 19:31:43 server-pi python[142640]:     result = self.fn(*self.args, **self.kwargs)
Oct 22 19:31:43 server-pi python[142640]:   File "/home/homeassistant/.homeassistant/custom_components/spotcast/__init__.py", line 225, in start_casting
Oct 22 19:31:43 server-pi python[142640]:     spotcast_controller.play(
Oct 22 19:31:43 server-pi python[142640]:   File "/home/homeassistant/.homeassistant/custom_components/spotcast/spotcast_controller.py", line 312, in play
Oct 22 19:31:43 server-pi python[142640]:     client.start_playback(**kwargs)
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/spotipy/client.py", line 1767, in start_playback
Oct 22 19:31:43 server-pi python[142640]:     return self._put(
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/spotipy/client.py", line 312, in _put
Oct 22 19:31:43 server-pi python[142640]:     return self._internal_call("PUT", url, payload, kwargs)
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/spotipy/client.py", line 267, in _internal_call
Oct 22 19:31:43 server-pi python[142640]:     raise SpotifyException(
Oct 22 19:31:43 server-pi python[142640]: spotipy.exceptions.SpotifyException: http status: 404, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=055a55a152a33ae1fec9bc657e83091d2ab31c28:
Oct 22 19:31:43 server-pi python[142640]:  Device not found, reason: None
Oct 22 19:31:43 server-pi python[142640]: 2022-10-22 19:31:43.434 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [546740151824] http status: 404, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=055a55a152a33ae1fec9bc657e83091d2ab31c28:
Oct 22 19:31:43 server-pi python[142640]:  Device not found, reason: None
Oct 22 19:31:43 server-pi python[142640]: Traceback (most recent call last):
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/spotipy/client.py", line 245, in _internal_call
Oct 22 19:31:43 server-pi python[142640]:     response.raise_for_status()
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/requests/models.py", line 1021, in raise_for_status
Oct 22 19:31:43 server-pi python[142640]:     raise HTTPError(http_error_msg, response=self)
Oct 22 19:31:43 server-pi python[142640]: requests.exceptions.HTTPError: 404 Client Error: Not Found for url: https://api.spotify.com/v1/me/player/play?device_id=055a55a152a33ae1fec9bc657e83091d2ab31c28
Oct 22 19:31:43 server-pi python[142640]: During handling of the above exception, another exception occurred:
Oct 22 19:31:43 server-pi python[142640]: Traceback (most recent call last):
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/components/websocket_api/commands.py", line 202, in handle_call_service
Oct 22 19:31:43 server-pi python[142640]:     await hass.services.async_call(
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1738, in async_call
Oct 22 19:31:43 server-pi python[142640]:     task.result()
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1775, in _execute_service
Oct 22 19:31:43 server-pi python[142640]:     await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/components/script/__init__.py", line 410, in _service_handler
Oct 22 19:31:43 server-pi python[142640]:     await self.async_turn_on(variables=service.data, context=service.context)
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/components/script/__init__.py", line 369, in async_turn_on
Oct 22 19:31:43 server-pi python[142640]:     await coro
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/components/script/__init__.py", line 399, in _async_run
Oct 22 19:31:43 server-pi python[142640]:     return await self.script.async_run(script_vars, context)
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 1524, in async_run
Oct 22 19:31:43 server-pi python[142640]:     await asyncio.shield(run.async_run())
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 409, in async_run
Oct 22 19:31:43 server-pi python[142640]:     await self._async_step(log_exceptions=False)
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 453, in _async_step
Oct 22 19:31:43 server-pi python[142640]:     self._handle_exception(
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 476, in _handle_exception
Oct 22 19:31:43 server-pi python[142640]:     raise exception
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 451, in _async_step
Oct 22 19:31:43 server-pi python[142640]:     await getattr(self, handler)()
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 684, in _async_call_service_step
Oct 22 19:31:43 server-pi python[142640]:     await service_task
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1738, in async_call
Oct 22 19:31:43 server-pi python[142640]:     task.result()
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1781, in _execute_service
Oct 22 19:31:43 server-pi python[142640]:     await self._hass.async_add_executor_job(
Oct 22 19:31:43 server-pi python[142640]:   File "/usr/lib/python3.9/concurrent/futures/thread.py", line 52, in run
Oct 22 19:31:43 server-pi python[142640]:     result = self.fn(*self.args, **self.kwargs)
Oct 22 19:31:43 server-pi python[142640]:   File "/home/homeassistant/.homeassistant/custom_components/spotcast/__init__.py", line 225, in start_casting
Oct 22 19:31:43 server-pi python[142640]:     spotcast_controller.play(
Oct 22 19:31:43 server-pi python[142640]:   File "/home/homeassistant/.homeassistant/custom_components/spotcast/spotcast_controller.py", line 312, in play
Oct 22 19:31:43 server-pi python[142640]:     client.start_playback(**kwargs)
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/spotipy/client.py", line 1767, in start_playback
Oct 22 19:31:43 server-pi python[142640]:     return self._put(
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/spotipy/client.py", line 312, in _put
Oct 22 19:31:43 server-pi python[142640]:     return self._internal_call("PUT", url, payload, kwargs)
Oct 22 19:31:43 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/spotipy/client.py", line 267, in _internal_call
Oct 22 19:31:43 server-pi python[142640]:     raise SpotifyException(
Oct 22 19:31:43 server-pi python[142640]: spotipy.exceptions.SpotifyException: http status: 404, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=055a55a152a33ae1fec9bc657e83091d2ab31c28:
Oct 22 19:31:43 server-pi python[142640]:  Device not found, reason: None

Log with friendly name:

Oct 22 19:33:49 server-pi python[142640]: 2022-10-22 19:33:49.857 INFO (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Running script sequence
Oct 22 19:33:49 server-pi python[142640]: 2022-10-22 19:33:49.858 INFO (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Executing step setting variables
Oct 22 19:33:49 server-pi python[142640]: 2022-10-22 19:33:49.861 INFO (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Executing step call service
Oct 22 19:33:49 server-pi python[142640]: 2022-10-22 19:33:49.866 INFO (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Executing step call service
Oct 22 19:33:50 server-pi python[142640]: 2022-10-22 19:33:50.507 ERROR (SyncWorker_0) [custom_components.spotcast.spotcast_controller] Could not find device Esszimmer from hass.data
Oct 22 19:33:50 server-pi python[142640]: 2022-10-22 19:33:50.510 ERROR (MainThread) [homeassistant.components.script.spotify_play_debug] Debug Spotify Play: Error executing script. Error for call_service at pos 3: Could not find device with name Esszimmer
Oct 22 19:33:50 server-pi python[142640]: 2022-10-22 19:33:50.516 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [546740151824] Could not find device with name Esszimmer
Oct 22 19:33:50 server-pi python[142640]: Traceback (most recent call last):
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/components/websocket_api/commands.py", line 202, in handle_call_service
Oct 22 19:33:50 server-pi python[142640]:     await hass.services.async_call(
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1738, in async_call
Oct 22 19:33:50 server-pi python[142640]:     task.result()
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1775, in _execute_service
Oct 22 19:33:50 server-pi python[142640]:     await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/components/script/__init__.py", line 410, in _service_handler
Oct 22 19:33:50 server-pi python[142640]:     await self.async_turn_on(variables=service.data, context=service.context)
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/components/script/__init__.py", line 369, in async_turn_on
Oct 22 19:33:50 server-pi python[142640]:     await coro
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/components/script/__init__.py", line 399, in _async_run
Oct 22 19:33:50 server-pi python[142640]:     return await self.script.async_run(script_vars, context)
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 1524, in async_run
Oct 22 19:33:50 server-pi python[142640]:     await asyncio.shield(run.async_run())
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 409, in async_run
Oct 22 19:33:50 server-pi python[142640]:     await self._async_step(log_exceptions=False)
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 453, in _async_step
Oct 22 19:33:50 server-pi python[142640]:     self._handle_exception(
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 476, in _handle_exception
Oct 22 19:33:50 server-pi python[142640]:     raise exception
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 451, in _async_step
Oct 22 19:33:50 server-pi python[142640]:     await getattr(self, handler)()
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/helpers/script.py", line 684, in _async_call_service_step
Oct 22 19:33:50 server-pi python[142640]:     await service_task
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1738, in async_call
Oct 22 19:33:50 server-pi python[142640]:     task.result()
Oct 22 19:33:50 server-pi python[142640]:   File "/srv/homeassistant/lib/python3.9/site-packages/homeassistant/core.py", line 1781, in _execute_service
Oct 22 19:33:50 server-pi python[142640]:     await self._hass.async_add_executor_job(
Oct 22 19:33:50 server-pi python[142640]:   File "/usr/lib/python3.9/concurrent/futures/thread.py", line 52, in run
Oct 22 19:33:50 server-pi python[142640]:     result = self.fn(*self.args, **self.kwargs)
Oct 22 19:33:50 server-pi python[142640]:   File "/home/homeassistant/.homeassistant/custom_components/spotcast/__init__.py", line 190, in start_casting
Oct 22 19:33:50 server-pi python[142640]:     spotify_device_id = spotcast_controller.get_spotify_device_id(
Oct 22 19:33:50 server-pi python[142640]:   File "/home/homeassistant/.homeassistant/custom_components/spotcast/spotcast_controller.py", line 234, in get_spotify_device_id
Oct 22 19:33:50 server-pi python[142640]:     spotify_cast_device = SpotifyCastDevice(
Oct 22 19:33:50 server-pi python[142640]:   File "/home/homeassistant/.homeassistant/custom_components/spotcast/spotcast_controller.py", line 62, in __init__
Oct 22 19:33:50 server-pi python[142640]:     self.castDevice = self.getChromecastDevice(device_name)
Oct 22 19:33:50 server-pi python[142640]:   File "/home/homeassistant/.homeassistant/custom_components/spotcast/spotcast_controller.py", line 88, in getChromecastDevice
Oct 22 19:33:50 server-pi python[142640]:     raise HomeAssistantError(
Oct 22 19:33:50 server-pi python[142640]: homeassistant.exceptions.HomeAssistantError: Could not find device with name Esszimmer

[x] Using latest version of spotcast
[x] Using latest stable version of Home Assistant
[x] I have setup the Spotify integration in Home Assistant
[x] I have Spotify Premium
[x] I am using multiple accounts
[x] I have renewed my sp_dc and sp_key values and restarted Home Assistant (see README)
[x] I'm attaching relevant logs with level debug for component spotcast (see README)
[x] I'm using entity_id in the service call and have tried device_name but the issue remains

Environment

Installation type: [HA_OS|Container|Supervised|Core]
HA version: [ 2022.10.5]
spotcast version: [3.6.30 ]

DennisWilken commented 1 year ago

I have exactly the same issue. We have three Musiccast device in the kids and parents bedrooms. I have an alarm script that starts a Spotify playlist from the corresponding account. However, when my wife or I use our phone to turn on some music before, the script doesn't work anymore using the kids accounts. I was thinking of using an additional media player to free the device from the old account which isn't a pretty solution either. Switching from the spotify_device_id to device_name doesn't help.

fcusson commented 1 year ago

@tikeyknax the first problem you had should normally be resolved with v3.7.0. Can you confirm if it works now.

fcusson commented 1 year ago

@DennisWilken can you provide a debug log, I want to check if you have the same problem or a different error call

DennisWilken commented 1 year ago

@fcusson sure!

I just update to version 3.7. Home assistant is on version 2023.2.4. I ran the script:

testspotify:
  sequence:
  - service: spotcast.start
    data:
      account: dennis
      #device_name: Schafzimmer
      spotify_device_id: 4a1991661365430c761186c2961bb9a5cfdXXXX
      uri: spotify:playlist:2BDfRXOimfjlWThp0pG61R  
      random_song: true
      shuffle: true

and after that the script testspotifyviola with the account "viola". This the log that I got on debug level.

2023-02-14 19:21:56.950 INFO (MainThread) [homeassistant.components.s_waitercript.testspotify] testspotify: Running script sequence
2023-02-14 19:21:56.951 INFO (MainThread) [homeassistant.components.script.testspotify] testspotify: Executing step call service
2023-02-14 19:21:56.951 DEBUG (SyncWorker_10) [custom_components.spotcast.spotcast_controller] setting up with  account dennis
2023-02-14 19:21:57.120 DEBUG (SyncWorker_10) [custom_components.spotcast.spotcast_controller] expires: 1676402217 time: 1676398917.1201138
2023-02-14 19:21:57.120 DEBUG (SyncWorker_10) [custom_components.spotcast.spotcast_controller] Playing URI: spotify:playlist:2BDfRXOimfjlWThp0XXXXX on device-id: 4a1991661365430c761186c2961bb9a5cfdXXXX
2023-02-14 19:21:57.437 DEBUG (SyncWorker_10) [custom_components.spotcast.spotcast_controller] Start playback at random position: 37
2023-02-14 19:21:57.437 DEBUG (SyncWorker_10) [custom_components.spotcast.spotcast_controller] Playing context uri using context_uri for uri: "spotify:playlist:2BDfRXOimfjlWThp0XXXXX" (random_song: True)
2023-02-14 19:21:57.741 DEBUG (SyncWorker_10) [custom_components.spotcast] Turning shuffle on
2023-02-14 19:22:00.930 DEBUG (SyncWorker_10) [custom_components.spotcast] Turning repeat on
2023-02-14 19:22:04.141 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aiomusiccast/pyamaha.py", line 248, in request_json
    response = await self.get(args[0])
  File "/usr/local/lib/python3.10/site-packages/aiomusiccast/pyamaha.py", line 268, in get
    return await self.client.get(uri.format(host=self.ip), headers=self._headers, timeout=ClientTimeout(total=5))
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client.py", line 559, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client_reqrep.py", line 898, in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
  File "/usr/local/lib/python3.10/site-packages/aiohttp/streams.py", line 616, in read
    await self._waiter
aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aiomusiccast/musiccast_device.py", line 135, in handle
    await self._fetch_netusb()
  File "/usr/local/lib/python3.10/site-packages/aiomusiccast/musiccast_device.py", line 194, in _fetch_netusb
    self._netusb_play_info = await self.device.request_json(NetUSB.get_play_info())
  File "/usr/local/lib/python3.10/site-packages/aiomusiccast/pyamaha.py", line 256, in request_json
    raise MusicCastConnectionException() from ce
aiomusiccast.exceptions.MusicCastConnectionException

2023-02-14 19:22:08.334 INFO (MainThread) [homeassistant.components.script.testspotifyviola] testspotifyviola: Running script sequence
2023-02-14 19:22:08.335 INFO (MainThread) [homeassistant.components.script.testspotifyviola] testspotifyviola: Executing step call service
2023-02-14 19:22:08.336 DEBUG (SyncWorker_5) [custom_components.spotcast.spotcast_controller] setting up with  account viola
2023-02-14 19:22:08.477 DEBUG (SyncWorker_5) [custom_components.spotcast.spotcast_controller] expires: 1676402228 time: 1676398928.4775908
2023-02-14 19:22:08.478 DEBUG (SyncWorker_5) [custom_components.spotcast.spotcast_controller] Playing URI: spotify:playlist:2BDfRXOimfjlWThp0XXXXX on device-id: 4a1991661365430c761186c2961bb9a5cfdXXXX
2023-02-14 19:22:08.884 DEBUG (SyncWorker_5) [custom_components.spotcast.spotcast_controller] Start playback at random position: 9
2023-02-14 19:22:08.884 DEBUG (SyncWorker_5) [custom_components.spotcast.spotcast_controller] Playing context uri using context_uri for uri: "spotify:playlist:2BDfRXOimfjlWThp0XXXXX" (random_song: True)
2023-02-14 19:22:08.975 ERROR (SyncWorker_5) [spotipy.client] HTTP Error for PUT to https://api.spotify.com/v1/me/player/play?device_id=4a1991661365430c761186c2961bb9a5cfdXXXX with Params: {} returned 404 due to Device not found
2023-02-14 19:22:08.977 ERROR (MainThread) [homeassistant.components.script.testspotifyviola] testspotifyviola: Error executing script. Unexpected error for call_service at pos 1: http status: 404, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=4a1991661365430c761186c2961bb9a5cfdXXXX:
 Device not found, reason: None
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/spotipy/client.py", line 269, in _internal_call
    response.raise_for_status()
  File "/usr/local/lib/python3.10/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: Not Found for url: https://api.spotify.com/v1/me/player/play?device_id=4a1991661365430c761186c2961bb9a5cfdXXXX

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 451, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 684, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1787, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1830, in _execute_service
    await self._hass.async_add_executor_job(
  File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/spotcast/__init__.py", line 256, in start_casting
    spotcast_controller.play(
  File "/config/custom_components/spotcast/spotcast_controller.py", line 323, in play
    client.start_playback(**kwargs)
  File "/usr/local/lib/python3.10/site-packages/spotipy/client.py", line 1819, in start_playback
    return self._put(
  File "/usr/local/lib/python3.10/site-packages/spotipy/client.py", line 336, in _put
    return self._internal_call("PUT", url, payload, kwargs)
  File "/usr/local/lib/python3.10/site-packages/spotipy/client.py", line 291, in _internal_call
    raise SpotifyException(
spotipy.exceptions.SpotifyException: http status: 404, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=4a1991661365430c761186c2961bb9a5cfdXXXX:
 Device not found, reason: None
2023-02-14 19:22:08.981 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140349619186864] http status: 404, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=4a1991661365430c761186c2961bb9a5cfdXXXX:
 Device not found, reason: None
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/spotipy/client.py", line 269, in _internal_call
    response.raise_for_status()
  File "/usr/local/lib/python3.10/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: Not Found for url: https://api.spotify.com/v1/me/player/play?device_id=4a1991661365430c761186c2961bb9a5cfdXXXX

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 200, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1787, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1824, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 472, in _service_handler
    await self.async_turn_on(variables=service.data, context=service.context)
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 431, in async_turn_on
    await coro
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 461, in _async_run
    return await self.script.async_run(script_vars, context)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1524, in async_run
    await asyncio.shield(run.async_run())
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 409, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 453, in _async_step
    self._handle_exception(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 476, in _handle_exception
    raise exception
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 451, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 684, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1787, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1830, in _execute_service
    await self._hass.async_add_executor_job(
  File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/spotcast/__init__.py", line 256, in start_casting
    spotcast_controller.play(
  File "/config/custom_components/spotcast/spotcast_controller.py", line 323, in play
    client.start_playback(**kwargs)
  File "/usr/local/lib/python3.10/site-packages/spotipy/client.py", line 1819, in start_playback
    return self._put(
  File "/usr/local/lib/python3.10/site-packages/spotipy/client.py", line 336, in _put
    return self._internal_call("PUT", url, payload, kwargs)
  File "/usr/local/lib/python3.10/site-packages/spotipy/client.py", line 291, in _internal_call
    raise SpotifyException(
spotipy.exceptions.SpotifyException: http status: 404, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=4a1991661365430c761186c2961bb9a5cfdXXXX:
 Device not found, reason: None

Is there more information that you need?

P.S. Is there an easy way to export the log filtered by component? In the UI I don't see the debug output. In the full log that I downloaded, I had to manually pick the relevant pieces.

fcusson commented 1 year ago

@DennisWilken

P.S. Is there an easy way to export the log filtered by component? In the UI I don't see the debug output. In the full log that I downloaded, Ihad to manually pick the relevant pieces.

You can simply input a search in the log page, it filter your full log to only the lines with your search terms.

So if I understand correctly, the problem onyl seems to happen when the player is already in use by another account? Can you confirm I understand or clarify? I want to make sure I check for the right thing.

Also I just got my partner to update her sp_dc and sp_key so I can finally restart doing multi account test. I should be able to debug the problem now.

DennisWilken commented 1 year ago

That's right. The device can be turned off for a while. I can also change the source to something else on the media player, e.g. radio. As long as the last spotify account playing something on the device doesn't match the one used by spotcast, I run into the issue. I also tested a JBL speaker that is regconised as a Google Cast device with the same issue.

I am curious to see if you can reproduce the problem. Thanks for the support!

tikeyknax commented 1 year ago

@fcusson Thanks for taking a look into the issue. It took me a while to update. By now, @DennisWilken has already provide the answers. I can confirm that the issue still exists independent of whether I use the device name or the device id.

pbryan7 commented 1 year ago

I too have the same problem... I have a HEOS speaker that is usually controlled from HA with a spotify account I made specifically for HA, and it works really well... but occasionally someone in the house uses their spotify phone app to directly cast to that speaker from their phone and their spotify account. From what I can tell, the Spotify API will stop returning the device when called from the HA account, when a different account was the last to access/use it. I'm assuming that is what causes the 'device not found' errors with SpotCast. It seems that the official Spotify apps, on phones, or even the Windows app, will detect speakers on the local network (not just from the API) and reassign/add them back to the active account... It seems SpotCast doesn't have this power (yet?).

My only solution thus far, is when this problem is discovered/reported, I log into the HA spotify account on my windows app and start a song to that speaker, that re-associates it to the HA account and then all my automatons work fine again. (until somebody else uses the speaker again, fortunately for me, this is rare)

wildekek commented 1 year ago

Indeed it looks like the Spotify API does not return the spotify connect device anymore when another user is already connected to that device. The only way to make it show up in the API is by joining a group session or by taking over the device in another (desktop/mobile) client. Seems the spotify web client also uses the same API as it has the same problem.

1aranzant commented 8 months ago

This renders the spotify integration and spotcast pretty useless for multi-user use...

KlumzyKlein commented 1 month ago

Has anyone found a fix for this yet?

fcusson commented 1 month ago

Has anyone found a fix for this yet?

The problem is with the spotify Api. Devices already in use by another account will not show up as available until they are no longer in use.

At the moment, the best solution is to stop the media playing from the other account and then making the service call to spotcast.

DennisWilken commented 1 month ago

Has anyone had a look if the problem has been discussed in the Spotify Developer Community ? I will have a look, as soon as I find the time.

I have the problem that my wife often turns on some music on my kid's speaker with her phone. In this case, when the morning alarm routine starts, Spotcast can't use my kid's account to start playing on their speakers. If I understand correctly, would it be sufficient if I connected my wife's account to a different speaker before I run the alarm?

Is it possible to somehow, as a workaround, set up virtual dummy speakers for that purpose?

KlumzyKlein commented 1 month ago

Has anyone found a fix for this yet?

The problem is with the spotify Api. Devices already in use by another account will not show up as available until they are no longer in use.

At the moment, the best solution is to stop the media playing from the other account and then making the service call to spotcast.

Been having a play around. I think the issue I am having may be specific to Amazon Echo devices. For the 6 devices and 4 groups I have, I always get a mix of some devices and some groups on my spotify and the rest on my partners spotify account. This happens even when not playing anything at all.

For example, below you can see me playing on all devices and the mix between devices available on connect:

Moving my music to the office and pausing my partners music I see these devices (eventually when it refreshes):

Using a separate Alexa Media config to see what is on her account, I can see that music is paused on the missing devices:

So thinking that Alexa is somehow forming a sort of hold on these devices so the Spotify API treats them as playing. I looked around and there is no way (I know of) to flush these devices.

fondberg / spotcast

Spotify connect devices not found with multiple accounts #358

Environment