Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Casting returns error 'total' #267

Closed
6 tasks done
Mothamoz opened this issue Dec 1, 2021 · 20 comments
Closed
6 tasks done

Casting returns error 'total' #267

Mothamoz opened this issue Dec 1, 2021 · 20 comments
Labels
bug Something isn't working dependency issue issue exist because of dependency not the project itself

Comments

@Mothamoz
Copy link

Mothamoz commented Dec 1, 2021

Description
Spotcasting my playlist to a device (through entity_id) works fine, however whenever I enable 'Random Song' or 'Offset' the service doesn't run at all and errors out saying 'total'. See logs below for more information.

  • Using latest version of spotcast
  • I have setup the Spotify integration in Home Assistant
  • Using latest stable version of Home Assistant
  • I have Spotify Premium
  • I'm attaching relevant logs with level debug for component spotcast (see README)
  • I'm using entity_id in the service call and have tried device_name but the issue remains

Environment (please complete the following information):

  • HA version: core-2021.11.5
  • spotcast version: 3.6.21

LOGS:

Logger: homeassistant.components.websocket_api.http.connection
Source: custom_components/spotcast/spotcast_controller.py:263
Integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 3:59:24 p.m. (14 occurrences)
Last logged: 4:13:59 p.m.
[281472494122992] 'total'

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 185, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 280, in service_handler
    await script_entity.async_turn_on(
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 384, in async_turn_on
    await coro
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 410, in _async_run
    return await self.script.async_run(script_vars, context)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1243, in async_run
    await asyncio.shield(run.async_run())
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 353, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 371, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 571, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1534, in _execute_service
    await self._hass.async_add_executor_job(handler.job.target, service_call)
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/spotcast/__init__.py", line 176, in start_casting
    spotcast_controller.play(
  File "/config/custom_components/spotcast/spotcast_controller.py", line 263, in play
    position = random.randint(0, results["total"] - 1)
KeyError: 'total'
@Mothamoz Mothamoz changed the title Casting Casting returns error ' Dec 1, 2021
@Mothamoz Mothamoz changed the title Casting returns error ' Casting returns error 'total' Dec 1, 2021
@fcusson
Copy link
Collaborator

fcusson commented Dec 13, 2021

Hi @Mothamoz, can you confirm if bug persist after update to v3.6.22?

@Mothamoz
Copy link
Author

@Darkfull-Dante just tested, exact same issue unfortunately

@Mothamoz
Copy link
Author

If you need more information from me let me know

@fcusson
Copy link
Collaborator

fcusson commented Dec 13, 2021

@Mothamoz, is your HA instance updated also?

@Mothamoz
Copy link
Author

@Mothamoz, is your HA instance updated also?

Correct, running the latest version

@hmmbob
Copy link
Contributor

hmmbob commented Dec 13, 2021

Can you enable debug logging for Spotcast and try again?

https://github.com/fondberg/spotcast#enabling-debug-log

@Mothamoz
Copy link
Author

Mothamoz commented Dec 13, 2021

Below is the result when I try to run it. Especially the last line seems weird as it works fine with Random Song/Offset turned off. Hope this helps.

2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.spotcast_controller] setting up with  account default
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.spotcast_controller] expires: 1639409610 time: 1639406310.729325
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.spotcast_controller] setting up with  account default
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.helpers] get_spotify_devices: media_player.spotify_luuk_borgonjen: Spotify Luuk Borgonjen: [{'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'Nest Hub 2', 'type': 'CastVideo', 'volume_percent': 51}, {'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.helpers] get_spotify_devices: {'devices': [{'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'Nest Hub 2', 'type': 'CastVideo', 'volume_percent': 51}, {'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]}
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.helpers] get_cast_devices: media_player.nesthub7e89_2: Nest Hub 2 cast info: ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.39', 8009)), ServiceInfo(type='mdns', data='Google-Nest-Hub-cb7960f7e27c7cdb448ff26f01640284._googlecast._tcp.local.')}, uuid=UUID('cb7960f7-e27c-7cdb-448f-f26f01640284'), model_name='Google Nest Hub', friendly_name='Nest Hub 2', host='192.168.143.39', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.helpers] get_cast_devices: media_player.tv_slaapkamer: Chromecast Slaapkamer cast info: ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='mdns', data='Chromecast-a45ee2c65ea49ee4c70a49dd8d50a607._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.143.4', 8009))}, uuid=UUID('a45ee2c6-5ea4-9ee4-c70a-49dd8d50a607'), model_name='Chromecast', friendly_name='Chromecast Slaapkamer', host='192.168.143.4', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.helpers] get_cast_devices: media_player.tv_woonkamer: Chromecast Woonkamer cast info: ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='mdns', data='Chromecast-Ultra-9ee4e1dc431df06f4a5d946964a6558e._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.143.21', 8009))}, uuid=UUID('9ee4e1dc-431d-f06f-4a5d-946964a6558e'), model_name='Chromecast Ultra', friendly_name='Chromecast Woonkamer', host='192.168.143.21', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.spotcast_controller] Chromecast devices: [ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.39', 8009)), ServiceInfo(type='mdns', data='Google-Nest-Hub-cb7960f7e27c7cdb448ff26f01640284._googlecast._tcp.local.')}, uuid=UUID('cb7960f7-e27c-7cdb-448f-f26f01640284'), model_name='Google Nest Hub', friendly_name='Nest Hub 2', host='192.168.143.39', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None), ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='mdns', data='Chromecast-a45ee2c65ea49ee4c70a49dd8d50a607._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.143.4', 8009))}, uuid=UUID('a45ee2c6-5ea4-9ee4-c70a-49dd8d50a607'), model_name='Chromecast', friendly_name='Chromecast Slaapkamer', host='192.168.143.4', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None), ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='mdns', data='Chromecast-Ultra-9ee4e1dc431df06f4a5d946964a6558e._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.143.21', 8009))}, uuid=UUID('9ee4e1dc-431d-f06f-4a5d-946964a6558e'), model_name='Chromecast Ultra', friendly_name='Chromecast Woonkamer', host='192.168.143.21', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)]
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.spotcast_controller] cast info: ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.39', 8009)), ServiceInfo(type='mdns', data='Google-Nest-Hub-cb7960f7e27c7cdb448ff26f01640284._googlecast._tcp.local.')}, uuid=UUID('cb7960f7-e27c-7cdb-448f-f26f01640284'), model_name='Google Nest Hub', friendly_name='Nest Hub 2', host='192.168.143.39', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2021-12-13 15:38:30 DEBUG (SyncWorker_3) [custom_components.spotcast.spotcast_controller] Found cast device: Chromecast('unknown', port=8009, cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.39', 8009)), ServiceInfo(type='mdns', data='Google-Nest-Hub-cb7960f7e27c7cdb448ff26f01640284._googlecast._tcp.local.')}, uuid=UUID('cb7960f7-e27c-7cdb-448f-f26f01640284'), model_name='Google Nest Hub', friendly_name='Nest Hub 2', host='192.168.143.39', port=8009, cast_type='cast', manufacturer='Google Inc.'))
2021-12-13 15:38:31 INFO (SyncWorker_3) [pychromecast.controllers] Not launching app CC32E753 - already running
2021-12-13 15:38:31 DEBUG (SyncWorker_3) [custom_components.spotcast.helpers] get_spotify_devices: media_player.spotify_luuk_borgonjen: Spotify Luuk Borgonjen: [{'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'Nest Hub 2', 'type': 'CastVideo', 'volume_percent': 51}, {'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]
2021-12-13 15:38:31 DEBUG (SyncWorker_3) [custom_components.spotcast.helpers] get_spotify_devices: {'devices': [{'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'Nest Hub 2', 'type': 'CastVideo', 'volume_percent': 51}, {'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]}
2021-12-13 15:38:31 DEBUG (SyncWorker_3) [custom_components.spotcast.spotcast_controller] devices_available: {'devices': [{'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'Nest Hub 2', 'type': 'CastVideo', 'volume_percent': 51}, {'id': '[redacted]', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]} 4484a2d82a8e97cd197d6a1a0989a788
2021-12-13 15:38:31 DEBUG (SyncWorker_3) [custom_components.spotcast.spotcast_controller] Playing URI: spotify:playlist:5rAhD02CGReFtSbinTHxkn?si=968337997b194202 on device-id: [redacted]
2021-12-13 15:38:32 ERROR (MainThread) [homeassistant.components.script.spotify] Spotify: Error executing script. Unexpected error for call_service at pos 1: 'total'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 381, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 584, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1534, in _execute_service
    await self._hass.async_add_executor_job(handler.job.target, service_call)
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/spotcast/__init__.py", line 176, in start_casting
    spotcast_controller.play(
  File "/config/custom_components/spotcast/spotcast_controller.py", line 263, in play
    position = random.randint(0, results["total"] - 1)
KeyError: 'total'
2021-12-13 15:38:32 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [281473232017296] 'total'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 185, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 273, in service_handler
    await script_entity.async_turn_on(
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 377, in async_turn_on
    await coro
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 403, in _async_run
    return await self.script.async_run(script_vars, context)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1259, in async_run
    await asyncio.shield(run.async_run())
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 363, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 381, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 584, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1534, in _execute_service
    await self._hass.async_add_executor_job(handler.job.target, service_call)
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/spotcast/__init__.py", line 176, in start_casting
    spotcast_controller.play(
  File "/config/custom_components/spotcast/spotcast_controller.py", line 263, in play
    position = random.randint(0, results["total"] - 1)
KeyError: 'total'
2021-12-13 15:38:42 ERROR (Thread-8) [homeassistant.components.cast.media_player] Failed to cast media . Please make sure the URL is: Reachable from the cast device and either a publicly resolvable hostname or an IP address

@fcusson
Copy link
Collaborator

fcusson commented Dec 16, 2021

@Mothamoz I have finally been able to find the problem. Its the URI you are using spotify:playlist:5rAhD02CGReFtSbinTHxkn?si=968337997b194202

the ?si= is an added parameter that seems to be purely EU based. Spotipy (which is the dependency we use to get track information) doesn't seem to play well with it.

The keys are all wrong when keeping the ?si=...

test result
with ?si= dict_keys(['collaborative', 'description', 'external_urls', 'followers', 'href', 'id', 'images', 'name', 'owner', 'primary_color', 'public', 'sharing_info', 'snapshot_id', 'tracks', 'type', 'uri'])
without ?si= dict_keys(['href', 'items', 'limit', 'next', 'offset', 'previous', 'total'])

Removing everything from the ? in the uri resolves the traceback. I will open a pull request with them regarding making it work with the new parameter.

In the mean time:

  • until an update from us, try removing the parameter from the playlist
  • I'll be working on a portion to clean a uri before sending it to offset songs (temporary fix)
  • we'll revert to standard management of uri when spotipy will be ready to handle the new types of uri

@fcusson fcusson added bug Something isn't working dependency issue issue exist because of dependency not the project itself labels Dec 16, 2021
@Mothamoz
Copy link
Author

@Darkfull-Dante thank you so much for the update, I've removed the parameter from the URI as a temp fix like you suggested and that did the trick!

Glad you managed to figure it out and sorry I caused you the headache in the first place 😄

@fcusson
Copy link
Collaborator

fcusson commented Dec 16, 2021

@Mothamoz don't worry I wouldn't participate in an open source project if I didn't enjoy trying to figure these things. While composing the issue for spotipy, I seem to have figured out something. I tested on my dev env and in the first dictionary I printed, we have a key which is tracks. The value inside that is the actual dictionary we are looking for.

I think I have a way of resolving the issue from our end without modifying the uri itself, which would be ideal. If I have a potential fix, I will update this issue, but I won't close it, because it is still the Spotipy that should make sure to return consistent dictyionaries for valid URIs.

@fcusson
Copy link
Collaborator

fcusson commented Dec 16, 2021

spotipy/#758 has been open to correct this issue

fcusson added a commit to fcusson/spotcast that referenced this issue Dec 16, 2021
fcusson added a commit that referenced this issue Dec 17, 2021
@fcusson
Copy link
Collaborator

fcusson commented Dec 17, 2021

@Mothamoz v3.6.23 is available and should resolve the problem while waiting on Spotipy to accept my PR. Would you be able to confirm it is working on your end even with the get query (the ?si=[...])

@fcusson
Copy link
Collaborator

fcusson commented Dec 17, 2021

Hi @Mothamoz,

Just to fully document this situation, can you confirm how you came about that URI? Did you got it preformatted from the app or was it built from the URL (taking the link and replacing / with :)?

@Mothamoz
Copy link
Author

Mothamoz commented Dec 17, 2021

@Darkfull-Dante I got it the way you've described it :)

In regards to it working with the new update, I can't confirm... getting a different error;

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 245, in _internal_call
    response.raise_for_status()
  File "/usr/local/lib/python3.9/site-packages/requests/models.py", line 953, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 400 Client Error: Bad Request for url: https://api.spotify.com/v1/me/player/play?device_id=4484a2d82a8e97cd197d6a1a0989a788

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 403, in _async_run
    return await self.script.async_run(script_vars, context)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1259, in async_run
    await asyncio.shield(run.async_run())
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 363, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 381, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 584, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1534, in _execute_service
    await self._hass.async_add_executor_job(handler.job.target, service_call)
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/spotcast/__init__.py", line 176, in start_casting
    spotcast_controller.play(
  File "/config/custom_components/spotcast/spotcast_controller.py", line 284, in play
    client.start_playback(**kwargs)
  File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 1767, in start_playback
    return self._put(
  File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 312, in _put
    return self._internal_call("PUT", url, payload, kwargs)
  File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 267, in _internal_call
    raise SpotifyException(
spotipy.exceptions.SpotifyException: http status: 400, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=4484a2d82a8e97cd197d6a1a0989a788:
 Invalid context uri, reason: None

@fcusson
Copy link
Collaborator

fcusson commented Dec 17, 2021

That is very strange, It works on my side. Can you provide a new debug log with the error, it might help to find what is breaking

@Mothamoz
Copy link
Author

Mothamoz commented Dec 17, 2021

My attempt at doing the formatting right:

2021-12-17 15:42:48 INFO (MainThread) [homeassistant.components.script.spotify] Spotify: Running script sequence
2021-12-17 15:42:48 INFO (MainThread) [homeassistant.components.script.spotify] Spotify: Executing step call service
2021-12-17 15:42:48 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] setting up with account default
2021-12-17 15:42:48 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] expires: 1639755468 time: 1639752168.9471467
2021-12-17 15:42:48 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] setting up with account default
2021-12-17 15:42:49 DEBUG (SyncWorker_1) [custom_components.spotcast.helpers] get_spotify_devices: media_player.spotify_luuk_borgonjen: Spotify Luuk Borgonjen: [{'id': '754ecfff437052465eb6d3fcb4f3042178dd17a5', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]
2021-12-17 15:42:49 DEBUG (SyncWorker_1) [custom_components.spotcast.helpers] get_spotify_devices: {'devices': [{'id': '754ecfff437052465eb6d3fcb4f3042178dd17a5', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]}
2021-12-17 15:42:49 DEBUG (SyncWorker_1) [custom_components.spotcast.helpers] get_cast_devices: media_player.tv_woonkamer: Chromecast Woonkamer cast info: ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.21', 8009)), ServiceInfo(type='mdns', data='Chromecast-Ultra-9ee4e1dc431df06f4a5d946964a6558e._googlecast._tcp.local.')}, uuid=UUID('9ee4e1dc-431d-f06f-4a5d-946964a6558e'), model_name='Chromecast Ultra', friendly_name='Chromecast Woonkamer', host='192.168.143.21', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2021-12-17 15:42:49 DEBUG (SyncWorker_1) [custom_components.spotcast.helpers] get_cast_devices: media_player.tv_slaapkamer: Chromecast Slaapkamer cast info: ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.4', 8009)), ServiceInfo(type='mdns', data='Chromecast-a45ee2c65ea49ee4c70a49dd8d50a607._googlecast._tcp.local.')}, uuid=UUID('a45ee2c6-5ea4-9ee4-c70a-49dd8d50a607'), model_name='Chromecast', friendly_name='Chromecast Slaapkamer', host='192.168.143.4', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2021-12-17 15:42:49 DEBUG (SyncWorker_1) [custom_components.spotcast.helpers] get_cast_devices: media_player.nesthub7e89_2: Nest Hub 2 cast info: ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.39', 8009)), ServiceInfo(type='mdns', data='Google-Nest-Hub-cb7960f7e27c7cdb448ff26f01640284._googlecast._tcp.local.')}, uuid=UUID('cb7960f7-e27c-7cdb-448f-f26f01640284'), model_name='Google Nest Hub', friendly_name='Nest Hub 2', host='192.168.143.39', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2021-12-17 15:42:49 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] Chromecast devices: [ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.21', 8009)), ServiceInfo(type='mdns', data='Chromecast-Ultra-9ee4e1dc431df06f4a5d946964a6558e._googlecast._tcp.local.')}, uuid=UUID('9ee4e1dc-431d-f06f-4a5d-946964a6558e'), model_name='Chromecast Ultra', friendly_name='Chromecast Woonkamer', host='192.168.143.21', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None), ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.4', 8009)), ServiceInfo(type='mdns', data='Chromecast-a45ee2c65ea49ee4c70a49dd8d50a607._googlecast._tcp.local.')}, uuid=UUID('a45ee2c6-5ea4-9ee4-c70a-49dd8d50a607'), model_name='Chromecast', friendly_name='Chromecast Slaapkamer', host='192.168.143.4', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None), ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.39', 8009)), ServiceInfo(type='mdns', data='Google-Nest-Hub-cb7960f7e27c7cdb448ff26f01640284._googlecast._tcp.local.')}, uuid=UUID('cb7960f7-e27c-7cdb-448f-f26f01640284'), model_name='Google Nest Hub', friendly_name='Nest Hub 2', host='192.168.143.39', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)]
2021-12-17 15:42:49 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] cast info: ChromecastInfo(cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.39', 8009)), ServiceInfo(type='mdns', data='Google-Nest-Hub-cb7960f7e27c7cdb448ff26f01640284._googlecast._tcp.local.')}, uuid=UUID('cb7960f7-e27c-7cdb-448f-f26f01640284'), model_name='Google Nest Hub', friendly_name='Nest Hub 2', host='192.168.143.39', port=8009, cast_type='cast', manufacturer='Google Inc.'), is_dynamic_group=None)
2021-12-17 15:42:49 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] Found cast device: Chromecast('unknown', port=8009, cast_info=CastInfo(services={ServiceInfo(type='host', data=('192.168.143.39', 8009)), ServiceInfo(type='mdns', data='Google-Nest-Hub-cb7960f7e27c7cdb448ff26f01640284._googlecast._tcp.local.')}, uuid=UUID('cb7960f7-e27c-7cdb-448f-f26f01640284'), model_name='Google Nest Hub', friendly_name='Nest Hub 2', host='192.168.143.39', port=8009, cast_type='cast', manufacturer='Google Inc.'))
2021-12-17 15:42:49 INFO (SyncWorker_1) [pychromecast.controllers] Receiver:Launching app CC32E753
2021-12-17 15:42:54 DEBUG (SyncWorker_1) [custom_components.spotcast.helpers] get_spotify_devices: media_player.spotify_luuk_borgonjen: Spotify Luuk Borgonjen: [{'id': '754ecfff437052465eb6d3fcb4f3042178dd17a5', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]
2021-12-17 15:42:54 DEBUG (SyncWorker_1) [custom_components.spotcast.helpers] get_spotify_devices: {'devices': [{'id': '4484a2d82a8e97cd197d6a1a0989a788', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'Nest Hub 2', 'type': 'CastVideo', 'volume_percent': 44}, {'id': '754ecfff437052465eb6d3fcb4f3042178dd17a5', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]}
2021-12-17 15:42:54 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] devices_available: {'devices': [{'id': '4484a2d82a8e97cd197d6a1a0989a788', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'Nest Hub 2', 'type': 'CastVideo', 'volume_percent': 44}, {'id': '754ecfff437052465eb6d3fcb4f3042178dd17a5', 'is_active': False, 'is_private_session': False, 'is_restricted': False, 'name': 'LUUK-PC', 'type': 'Computer', 'volume_percent': 37}]} 4484a2d82a8e97cd197d6a1a0989a788
2021-12-17 15:42:54 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] Playing URI: 5rAhD02CGReFtSbinTHxkn on device-id: 4484a2d82a8e97cd197d6a1a0989a788
2021-12-17 15:42:54 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] Start playback at random position: 0
2021-12-17 15:42:54 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] Playing context uri using context_uri for uri: "5rAhD02CGReFtSbinTHxkn" (random_song: True)
2021-12-17 15:42:54 ERROR (SyncWorker_1) [spotipy.client] HTTP Error for PUT to https://api.spotify.com/v1/me/player/play?device_id=4484a2d82a8e97cd197d6a1a0989a788 with Params: {} returned 400 due to Invalid context uri
2021-12-17 15:42:54 ERROR (MainThread) [homeassistant.components.script.spotify] Spotify: Error executing script. Unexpected error for call_service at pos 1: http status: 400, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=4484a2d82a8e97cd197d6a1a0989a788:
Invalid context uri, reason: None
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 245, in _internal_call
response.raise_for_status()
File "/usr/local/lib/python3.9/site-packages/requests/models.py", line 953, in raise_for_status
raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 400 Client Error: Bad Request for url: https://api.spotify.com/v1/me/player/play?device_id=4484a2d82a8e97cd197d6a1a0989a788
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 381, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 584, in _async_call_service_step
await service_task
File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1534, in _execute_service
await self._hass.async_add_executor_job(handler.job.target, service_call)
File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
result = self.fn(*self.args, **self.kwargs)
File "/config/custom_components/spotcast/__init__.py", line 176, in start_casting
spotcast_controller.play(
File "/config/custom_components/spotcast/spotcast_controller.py", line 284, in play
client.start_playback(**kwargs)
File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 1767, in start_playback
return self._put(
File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 312, in _put
return self._internal_call("PUT", url, payload, kwargs)
File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 267, in _internal_call
raise SpotifyException(
spotipy.exceptions.SpotifyException: http status: 400, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=4484a2d82a8e97cd197d6a1a0989a788:
Invalid context uri, reason: None
2021-12-17 15:42:54 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 245, in _internal_call
response.raise_for_status()
File "/usr/local/lib/python3.9/site-packages/requests/models.py", line 953, in raise_for_status
raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 400 Client Error: Bad Request for url: https://api.spotify.com/v1/me/player/play?device_id=4484a2d82a8e97cd197d6a1a0989a788
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 403, in _async_run
return await self.script.async_run(script_vars, context)
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1260, in async_run
await asyncio.shield(run.async_run())
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 363, in async_run
await self._async_step(log_exceptions=False)
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 381, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 584, in _async_call_service_step
await service_task
File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1534, in _execute_service
await self._hass.async_add_executor_job(handler.job.target, service_call)
File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
result = self.fn(*self.args, **self.kwargs)
File "/config/custom_components/spotcast/__init__.py", line 176, in start_casting
spotcast_controller.play(
File "/config/custom_components/spotcast/spotcast_controller.py", line 284, in play
client.start_playback(**kwargs)
File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 1767, in start_playback
return self._put(
File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 312, in _put
return self._internal_call("PUT", url, payload, kwargs)
File "/usr/local/lib/python3.9/site-packages/spotipy/client.py", line 267, in _internal_call
raise SpotifyException(
spotipy.exceptions.SpotifyException: http status: 400, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=4484a2d82a8e97cd197d6a1a0989a788:
Invalid context uri, reason: None
2021-12-17 15:43:04 ERROR (Thread-9) [homeassistant.components.cast.media_player] Failed to cast media . Please make sure the URL is: Reachable from the cast device and either a publicly resolvable hostname or an IP address

@fcusson
Copy link
Collaborator

fcusson commented Dec 17, 2021

@Mothamoz, can you confirm the exact URI you used to make the test, because the debug shows:

2021-12-17 15:42:54 DEBUG (SyncWorker_1) [custom_components.spotcast.spotcast_controller] Playing context uri using context_uri for uri: "5rAhD02CGReFtSbinTHxkn" (random_song: True)

What I find strange is that your URI is now just 5rAhD02CGReFtSbinTHxkn. It seems to be missing the app and type call. A Spotify URI should always be Spotify:<type>:<unique id>.

@Mothamoz
Copy link
Author

@Darkfull-Dante errrr... I botched the copy/paste job.

Okay so, on the latest spotcast/home assistant core version spotcast works fine without the '?si=' extension, but with the extension the following error comes up:

grabbing logs, will edit in a minute

@Mothamoz
Copy link
Author

@Darkfull-Dante no logs to show... it works 👯

@fcusson
Copy link
Collaborator

fcusson commented Dec 17, 2021

ok we seem to have found the problem. Also I had some chat with the spotipy team and they seem to be more incline that the dev of the app should manage the user input, not their api.

In the light of that, I'll close the issue, but I'll work on a more robust management of the URI that will do more validation.

@fcusson fcusson closed this as completed Dec 17, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working dependency issue issue exist because of dependency not the project itself
Projects
None yet
Development

No branches or pull requests

3 participants