search

home-assistant-libs / pychromecast

Library for Python 3 to communicate with the Google Chromecast.
MIT License
2.54k stars 379 forks source link

Pychromecast fails to start Spotify #520

Open hmmbob opened 3 years ago

hmmbob commented 3 years ago

When using Spotcast, pychromecast fails to start spotify playback. The 'connection tone' on the chosen speaker plays but the item is not started, while the following pychromecast error is thrown:

2021-08-12 16:46:04 ERROR (MainThread) [homeassistant.core] Error executing service: <ServiceCall spotcast.start (c:999e546c4febe44ced7365721538eaee): account=t, entity_id=media_player.slaapkamer, uri=spotify:track:5OoSxUZSbP1p7kb1d0SozG, offset=0, shuffle=False, start_volume=101, ignore_fully_played=False, repeat=off, random_song=False, force_playback=False>
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/core.py", line 1507, in catch_exceptions
await coro_or_task
File "/usr/src/homeassistant/homeassistant/core.py", line 1530, 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 143, in start_casting
spotify_device_id = spotcast_controller.get_spotify_device_id(
File "/config/custom_components/spotcast/spotcast_controller.py", line 202, in get_spotify_device_id
spotify_cast_device.startSpotifyController(access_token, expires)
File "/config/custom_components/spotcast/spotcast_controller.py", line 84, in startSpotifyController
sp.launch_app()
File "/usr/local/lib/python3.9/site-packages/pychromecast/controllers/spotify.py", line 87, in launch_app
raise LaunchError(
pychromecast.error.LaunchError: Timeout when waiting for status response from Spotify app

Based on the error, it appears to be an issue with pychromecast instead of Spotcast, hence why I am raising this here.

More info at Spotcast repo: https://github.com/fondberg/spotcast/issues/241 (including some initial thoughts here: https://github.com/fondberg/spotcast/issues/241#issuecomment-898217089)

edit: Adding logs with pychromecast: debug:

2021-08-13 08:38:32 DEBUG (SyncWorker_2) [custom_components.spotcast.spotcast_controller] setting up with account t
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.spotcast_controller] expires: 1628839525 time: 1628836713.0511932
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.spotcast_controller] setting up with account t
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_spotify_devices: media_player.spotify_t: Spotify T: []
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_spotify_devices: {'devices': []}
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_cast_devices: media_player.woonkamer: Woonkamer cast info: ChromecastInfo(services={ServiceInfo(type='mdns', data='google-nest-hub-4660f5b8aabe10031a93ebd362367256._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.xx.16', 8009))}, uuid='4660f5b8-aabe-1003-1a93-ebd362367256', _manufacturer='Google Inc.', model_name='Google Nest Hub', friendly_name='Woonkamer', is_audio_group=False, is_dynamic_group=None)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_cast_devices: media_player.tv_beneden: TV Beneden cast info: ChromecastInfo(services={ServiceInfo(type='host', data=('192.168.xx.15', 8009)), ServiceInfo(type='mdns', data='TPM191E-bec05970880b9a0a6966437ba87df4fe._googlecast._tcp.local.')}, uuid='bec05970-880b-9a0a-6966-437ba87df4fe', _manufacturer='Google Inc.', model_name='TPM191E', friendly_name='TV Beneden', is_audio_group=False, is_dynamic_group=None)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_cast_devices: media_player.studeerkamer: Studeerkamer cast info: ChromecastInfo(services={ServiceInfo(type='mdns', data='Google-Home-d4063db0253e246c9d66d8f7fda77a6a._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.xx.12', 8009))}, uuid='d4063db0-253e-246c-9d66-d8f7fda77a6a', _manufacturer='Google Inc.', model_name='Google Home', friendly_name='Studeerkamer', is_audio_group=False, is_dynamic_group=None)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_cast_devices: media_player.hele_huis: Hele huis cast info: ChromecastInfo(services={ServiceInfo(type='host', data=('[::ffff:c0a8:5811]', 32059)), ServiceInfo(type='host', data=('192.168.xx.17', 32059)), ServiceInfo(type='mdns', data='Google-Cast-Group-eec4b1d472ec428fad8f291a69a2d97d-2._googlecast._tcp.local.')}, uuid='eec4b1d4-72ec-428f-ad8f-291a69a2d97d', _manufacturer=None, model_name='Google Cast Group', friendly_name='Hele huis', is_audio_group=True, is_dynamic_group=False)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_cast_devices: media_player.boven: Boven cast info: ChromecastInfo(services={ServiceInfo(type='host', data=('[::ffff:c0a8:5811]', 32213)), ServiceInfo(type='host', data=('192.168.xx.17', 32213)), ServiceInfo(type='mdns', data='Google-Cast-Group-e18cddf284be43da9917ddb7d4ceb42c-1._googlecast._tcp.local.')}, uuid='e18cddf2-84be-43da-9917-ddb7d4ceb42c', _manufacturer=None, model_name='Google Cast Group', friendly_name='Boven', is_audio_group=True, is_dynamic_group=False)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_cast_devices: media_player.zolder: Zolder cast info: ChromecastInfo(services={ServiceInfo(type='mdns', data='Google-Home-Mini-71d8c580bbd0166b72f10071a427b6cb._googlecast._tcp.local.'), ServiceInfo(type='host', data=('[::ffff:c0a8:5811]', 8009)), ServiceInfo(type='host', data=('192.168.xx.17', 8009))}, uuid='71d8c580-bbd0-166b-72f1-0071a427b6cb', _manufacturer='Google Inc.', model_name='Google Home Mini', friendly_name='Zolder', is_audio_group=False, is_dynamic_group=None)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_cast_devices: media_player.slaapkamer: Slaapkamer cast info: ChromecastInfo(services={ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.xx.13', 8009))}, uuid='0256c1dd-13b4-4c80-849b-281970d02d11', _manufacturer='Google Inc.', model_name='Google Home Mini', friendly_name='Slaapkamer', is_audio_group=False, is_dynamic_group=None)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.helpers] get_cast_devices: media_player.soundbar: Soundbar cast info: ChromecastInfo(services={ServiceInfo(type='mdns', data='B8805-81704a75fd037a7c38090eb3c5dffea5._googlecast._tcp.local.')}, uuid='81704a75-fd03-7a7c-3809-0eb3c5dffea5', _manufacturer=None, model_name='B8805', friendly_name='Soundbar', is_audio_group=False, is_dynamic_group=None)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.spotcast_controller] Chromecast devices: [ChromecastInfo(services={ServiceInfo(type='mdns', data='google-nest-hub-4660f5b8aabe10031a93ebd362367256._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.xx.16', 8009))}, uuid='4660f5b8-aabe-1003-1a93-ebd362367256', _manufacturer='Google Inc.', model_name='Google Nest Hub', friendly_name='Woonkamer', is_audio_group=False, is_dynamic_group=None), ChromecastInfo(services={ServiceInfo(type='host', data=('192.168.xx.15', 8009)), ServiceInfo(type='mdns', data='TPM191E-bec05970880b9a0a6966437ba87df4fe._googlecast._tcp.local.')}, uuid='bec05970-880b-9a0a-6966-437ba87df4fe', _manufacturer='Google Inc.', model_name='TPM191E', friendly_name='TV Beneden', is_audio_group=False, is_dynamic_group=None), ChromecastInfo(services={ServiceInfo(type='mdns', data='Google-Home-d4063db0253e246c9d66d8f7fda77a6a._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.xx.12', 8009))}, uuid='d4063db0-253e-246c-9d66-d8f7fda77a6a', _manufacturer='Google Inc.', model_name='Google Home', friendly_name='Studeerkamer', is_audio_group=False, is_dynamic_group=None), ChromecastInfo(services={ServiceInfo(type='host', data=('[::ffff:c0a8:5811]', 32059)), ServiceInfo(type='host', data=('192.168.xx.17', 32059)), ServiceInfo(type='mdns', data='Google-Cast-Group-eec4b1d472ec428fad8f291a69a2d97d-2._googlecast._tcp.local.')}, uuid='eec4b1d4-72ec-428f-ad8f-291a69a2d97d', _manufacturer=None, model_name='Google Cast Group', friendly_name='Hele huis', is_audio_group=True, is_dynamic_group=False), ChromecastInfo(services={ServiceInfo(type='host', data=('[::ffff:c0a8:5811]', 32213)), ServiceInfo(type='host', data=('192.168.xx.17', 32213)), ServiceInfo(type='mdns', data='Google-Cast-Group-e18cddf284be43da9917ddb7d4ceb42c-1._googlecast._tcp.local.')}, uuid='e18cddf2-84be-43da-9917-ddb7d4ceb42c', _manufacturer=None, model_name='Google Cast Group', friendly_name='Boven', is_audio_group=True, is_dynamic_group=False), ChromecastInfo(services={ServiceInfo(type='mdns', data='Google-Home-Mini-71d8c580bbd0166b72f10071a427b6cb._googlecast._tcp.local.'), ServiceInfo(type='host', data=('[::ffff:c0a8:5811]', 8009)), ServiceInfo(type='host', data=('192.168.xx.17', 8009))}, uuid='71d8c580-bbd0-166b-72f1-0071a427b6cb', _manufacturer='Google Inc.', model_name='Google Home Mini', friendly_name='Zolder', is_audio_group=False, is_dynamic_group=None), ChromecastInfo(services={ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.xx.13', 8009))}, uuid='0256c1dd-13b4-4c80-849b-281970d02d11', _manufacturer='Google Inc.', model_name='Google Home Mini', friendly_name='Slaapkamer', is_audio_group=False, is_dynamic_group=None), ChromecastInfo(services={ServiceInfo(type='mdns', data='B8805-81704a75fd037a7c38090eb3c5dffea5._googlecast._tcp.local.')}, uuid='81704a75-fd03-7a7c-3809-0eb3c5dffea5', _manufacturer=None, model_name='B8805', friendly_name='Soundbar', is_audio_group=False, is_dynamic_group=None)]
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.spotcast_controller] cast info: ChromecastInfo(services={ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.xx.13', 8009))}, uuid='0256c1dd-13b4-4c80-849b-281970d02d11', _manufacturer='Google Inc.', model_name='Google Home Mini', friendly_name='Slaapkamer', is_audio_group=False, is_dynamic_group=None)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [pychromecast] get_chromecast_from_cast_info {ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.'), ServiceInfo(type='host', data=('192.168.xx.13', 8009))}
2021-08-13 08:38:33 INFO (SyncWorker_2) [pychromecast] Querying device status
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [pychromecast.dial] get_info_from_service resolved service ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.') to service_info ServiceInfo(type='_googlecast._tcp.local.', name='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.', addresses=[b'\xc0\xa8X\r'], port=8009, weight=0, priority=0, server='0256c1dd-13b4-4c80-849b-281970d02d11-1.local.', properties={b'id': b'0256c1dd13b44c80849b281970d02d11', b'cd': b'057A66E6AB886895BE6A8861FFB38BE8', b'rm': b'', b've': b'05', b'md': b'Google Home Mini', b'ic': b'/setup/icon.png', b'fn': b'Slaapkamer', b'ca': b'199172', b'st': b'0', b'bs': b'FA8FCA82B588', b'nf': b'1', b'rs': b''}, interface_index=None)
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [pychromecast.dial] Resolved service ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.') to 192.168.xx.13
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [custom_components.spotcast.spotcast_controller] Found cast device: Chromecast(None, port=8009, device=DeviceStatus(friendly_name='Slaapkamer', model_name='Google Home Mini', manufacturer='Google Inc.', uuid='0256c1dd-13b4-4c80-849b-281970d02d11', cast_type='audio'))
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.dial] get_info_from_service resolved service ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.') to service_info ServiceInfo(type='_googlecast._tcp.local.', name='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.', addresses=[b'\xc0\xa8X\r'], port=8009, weight=0, priority=0, server='0256c1dd-13b4-4c80-849b-281970d02d11-1.local.', properties={b'id': b'0256c1dd13b44c80849b281970d02d11', b'cd': b'057A66E6AB886895BE6A8861FFB38BE8', b'rm': b'', b've': b'05', b'md': b'Google Home Mini', b'ic': b'/setup/icon.png', b'fn': b'Slaapkamer', b'ca': b'199172', b'st': b'0', b'bs': b'FA8FCA82B588', b'nf': b'1', b'rs': b''}, interface_index=None)
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(None):8009] Resolved service ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.') to 192.168.xx.13:8009
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Connecting to 192.168.xx.13:8009
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.controllers] Receiver:Updating status
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to receiver-0: {'type': 'CONNECT', 'origin': {}, 'userAgent': 'PyChromecast', 'senderInfo': {'sdkType': 2, 'version': '15.605.1.3', 'browserVersion': '44.0.2403.30', 'platform': 4, 'systemVersion': 'Macintosh; Intel Mac OS X10_10_3', 'connectionType': 1}}
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'GET_STATUS', 'requestId': 1}
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Connected!
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.socket_client] Thread started...
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to sender-0: {'requestId': 1, 'status': {'userEq': {'high_shelf': {'frequency': 4500.0, 'gain_db': 0.0, 'quality': 0.707}, 'low_shelf': {'frequency': 150.0, 'gain_db': 0.0, 'quality': 0.707}, 'max_peaking_eqs': 0, 'peaking_eqs': []}, 'volume': {'controlType': 'master', 'level': 0.6000000238418579, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2021-08-13 08:38:33 DEBUG (Thread-14) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.6000000238418579, volume_muted=False, app_id=None, display_name=None, namespaces=[], session_id=None, transport_id=None, status_text='', icon_url=None, volume_control_type='master')
2021-08-13 08:38:33 INFO (SyncWorker_2) [pychromecast.controllers] Receiver:Launching app CC32E753
2021-08-13 08:38:33 DEBUG (SyncWorker_2) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'LAUNCH', 'appId': 'CC32E753', 'requestId': 3}
2021-08-13 08:38:35 DEBUG (zeroconf-ServiceBrowser-_googlecast._tcp-332) [pychromecast.discovery] update_service _googlecast._tcp.local., Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.
2021-08-13 08:38:35 DEBUG (zeroconf-ServiceBrowser-_googlecast._tcp-332) [pychromecast.dial] get_info_from_service resolved service ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.') to service_info ServiceInfo(type='_googlecast._tcp.local.', name='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.', addresses=[b'\xc0\xa8X\r'], port=8009, weight=0, priority=0, server='0256c1dd-13b4-4c80-849b-281970d02d11-1.local.', properties={b'id': b'0256c1dd13b44c80849b281970d02d11', b'cd': b'057A66E6AB886895BE6A8861FFB38BE8', b'rm': b'', b've': b'05', b'md': b'Google Home Mini', b'ic': b'/setup/icon.png', b'fn': b'Slaapkamer', b'ca': b'199172', b'st': b'1', b'bs': b'FA8FCA82B588', b'nf': b'1', b'rs': b'Spotify Cast Receiver 5.0.0-13b762f'}, interface_index=None)
2021-08-13 08:38:35 DEBUG (zeroconf-ServiceBrowser-_googlecast._tcp-332) [pychromecast.dial] Resolved service ServiceInfo(type='mdns', data='Google-Home-Mini-0256c1dd13b44c80849b281970d02d11-1._googlecast._tcp.local.') to 192.168.xx.13
2021-08-13 08:38:38 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 3, 'status': {'applications': [{'appId': 'CC32E753', 'appType': 'WEB', 'displayName': 'Spotify', 'iconUrl': 'https://lh3.googleusercontent.com/HOX9yqNu6y87Chb1lHYqhKVTQW43oFAFFe2ojx94yCLh0yMzgygTrM0RweAexApRWqq6UahgrWYimVgK', 'isIdleScreen': False, 'launchedFromCloud': False, 'namespaces': [{'name': 'urn:x-cast:com.google.cast.cac'}, {'name': 'urn:x-cast:com.google.cast.debugoverlay'}, {'name': 'urn:x-cast:com.spotify.chromecast.secure.v1'}, {'name': 'urn:x-cast:com.google.cast.broadcast'}, {'name': 'urn:x-cast:com.google.cast.media'}], 'sessionId': '7c4ff835-7f4a-43e5-b817-d978d830c6da', 'statusText': 'Spotify', 'transportId': '7c4ff835-7f4a-43e5-b817-d978d830c6da', 'universalAppId': 'CC32E753'}], 'userEq': {'high_shelf': {'frequency': 4500.0, 'gain_db': 0.0, 'quality': 0.707}, 'low_shelf': {'frequency': 150.0, 'gain_db': 0.0, 'quality': 0.707}, 'max_peaking_eqs': 0, 'peaking_eqs': []}, 'volume': {'controlType': 'master', 'level': 0.6000000238418579, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2021-08-13 08:38:38 DEBUG (Thread-14) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.6000000238418579, volume_muted=False, app_id='CC32E753', display_name='Spotify', namespaces=['urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.spotify.chromecast.secure.v1', 'urn:x-cast:com.google.cast.broadcast', 'urn:x-cast:com.google.cast.media'], session_id='7c4ff835-7f4a-43e5-b817-d978d830c6da', transport_id='7c4ff835-7f4a-43e5-b817-d978d830c6da', status_text='Spotify', icon_url='https://lh3.googleusercontent.com/HOX9yqNu6y87Chb1lHYqhKVTQW43oFAFFe2ojx94yCLh0yMzgygTrM0RweAexApRWqq6UahgrWYimVgK', volume_control_type='master')
2021-08-13 08:38:38 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to 7c4ff835-7f4a-43e5-b817-d978d830c6da: {'type': 'CONNECT', 'origin': {}, 'userAgent': 'PyChromecast', 'senderInfo': {'sdkType': 2, 'version': '15.605.1.3', 'browserVersion': '44.0.2403.30', 'platform': 4, 'systemVersion': 'Macintosh; Intel Mac OS X10_10_3', 'connectionType': 1}}
2021-08-13 08:38:38 DEBUG (Thread-12) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 3, 'status': {'applications': [{'appId': 'CC32E753', 'appType': 'WEB', 'displayName': 'Spotify', 'iconUrl': 'https://lh3.googleusercontent.com/HOX9yqNu6y87Chb1lHYqhKVTQW43oFAFFe2ojx94yCLh0yMzgygTrM0RweAexApRWqq6UahgrWYimVgK', 'isIdleScreen': False, 'launchedFromCloud': False, 'namespaces': [{'name': 'urn:x-cast:com.google.cast.cac'}, {'name': 'urn:x-cast:com.google.cast.debugoverlay'}, {'name': 'urn:x-cast:com.spotify.chromecast.secure.v1'}, {'name': 'urn:x-cast:com.google.cast.broadcast'}, {'name': 'urn:x-cast:com.google.cast.media'}], 'sessionId': '7c4ff835-7f4a-43e5-b817-d978d830c6da', 'statusText': 'Spotify', 'transportId': '7c4ff835-7f4a-43e5-b817-d978d830c6da', 'universalAppId': 'CC32E753'}], 'userEq': {'high_shelf': {'frequency': 4500.0, 'gain_db': 0.0, 'quality': 0.707}, 'low_shelf': {'frequency': 150.0, 'gain_db': 0.0, 'quality': 0.707}, 'max_peaking_eqs': 0, 'peaking_eqs': []}, 'volume': {'controlType': 'master', 'level': 0.6000000238418579, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2021-08-13 08:38:38 DEBUG (Thread-12) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.6000000238418579, volume_muted=False, app_id='CC32E753', display_name='Spotify', namespaces=['urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.spotify.chromecast.secure.v1', 'urn:x-cast:com.google.cast.broadcast', 'urn:x-cast:com.google.cast.media'], session_id='7c4ff835-7f4a-43e5-b817-d978d830c6da', transport_id='7c4ff835-7f4a-43e5-b817-d978d830c6da', status_text='Spotify', icon_url='https://lh3.googleusercontent.com/HOX9yqNu6y87Chb1lHYqhKVTQW43oFAFFe2ojx94yCLh0yMzgygTrM0RweAexApRWqq6UahgrWYimVgK', volume_control_type='master')
2021-08-13 08:38:38 DEBUG (Thread-12) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.google.cast.tp.connection from sender-0 to 7c4ff835-7f4a-43e5-b817-d978d830c6da: {'type': 'CONNECT', 'origin': {}, 'userAgent': 'PyChromecast', 'senderInfo': {'sdkType': 2, 'version': '15.605.1.3', 'browserVersion': '44.0.2403.30', 'platform': 4, 'systemVersion': 'Macintosh; Intel Mac OS X10_10_3', 'connectionType': 1}}
2021-08-13 08:38:38 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.google.cast.media from sender-0 to 7c4ff835-7f4a-43e5-b817-d978d830c6da: {'type': 'GET_STATUS', 'requestId': 4}
2021-08-13 08:38:38 DEBUG (Thread-12) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.google.cast.media from sender-0 to 7c4ff835-7f4a-43e5-b817-d978d830c6da: {'type': 'GET_STATUS', 'requestId': 13}
2021-08-13 08:38:38 DEBUG (Thread-14) [pychromecast.controllers] Start app_launch_event_function...
2021-08-13 08:38:38 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.spotify.chromecast.secure.v1 from sender-0 to 7c4ff835-7f4a-43e5-b817-d978d830c6da: {'type': 'setCredentials', 'credentials': 'BQAJAf0dL54419HUWGvBpd-s4FdywPlsF0M3JPjaofXe7dwyCzBtsUp7KPO5aaN413YTIktQNcetOQePMwySlRVrX_EUjWGN2PfJ6GBIbbEw3gby0TRIxZU6aeCSIVbnKbMWey6k3SertZPXcCuNP5t38XT3zRYqn1vG7MbJvcvHqsLxAOYOoWKsAT3APxlJiOA7mD18wKhptXK6oqlWxZL3brBbQYlYCG-x-53WdZwfV-YILywNJEGKFUwgEy2Oc9BvFUr6oNxPAVKR49OFnDvIMQXJRkUnGrG7d0qtIp74E5TGCGLwKGxYBC0G', 'expiresIn': 2812, 'requestId': 5}
2021-08-13 08:38:39 DEBUG (Thread-12) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.media from 7c4ff835-7f4a-43e5-b817-d978d830c6da to *: {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 0}
2021-08-13 08:38:39 DEBUG (Thread-12) [pychromecast.controllers] Media:Received status {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 0}
2021-08-13 08:38:39 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.media from 7c4ff835-7f4a-43e5-b817-d978d830c6da to *: {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 0}
2021-08-13 08:38:39 DEBUG (Thread-14) [pychromecast.controllers] Media:Received status {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 0}
2021-08-13 08:38:39 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.media from 7c4ff835-7f4a-43e5-b817-d978d830c6da to sender-0: {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 4}
2021-08-13 08:38:39 DEBUG (Thread-14) [pychromecast.controllers] Media:Received status {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 4}
2021-08-13 08:38:39 DEBUG (Thread-12) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.media from 7c4ff835-7f4a-43e5-b817-d978d830c6da to sender-0: {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 13}
2021-08-13 08:38:39 DEBUG (Thread-12) [pychromecast.controllers] Media:Received status {'type': 'MEDIA_STATUS', 'status': [], 'requestId': 13}
2021-08-13 08:38:42 INFO (SyncWorker_3) [pychromecast.controllers] Receiver:setting volume to 0.4
2021-08-13 08:38:42 DEBUG (SyncWorker_3) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Sending: Message urn:x-cast:com.google.cast.receiver from sender-0 to receiver-0: {'type': 'SET_VOLUME', 'volume': {'level': 0.4}, 'requestId': 14}
2021-08-13 08:38:43 DEBUG (Thread-12) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received unknown namespace: Message urn:x-cast:com.google.cast.multizone from receiver-0 to *: {'device': {'capabilities': 196612, 'deviceId': '0256c1dd-13b4-4c80-849b-281970d02d11', 'name': 'Slaapkamer', 'volume': {'level': 0.4000000059604645, 'muted': False}}, 'requestId': 0, 'type': 'DEVICE_UPDATED'}
2021-08-13 08:38:43 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received unknown namespace: Message urn:x-cast:com.google.cast.multizone from receiver-0 to *: {'device': {'capabilities': 196612, 'deviceId': '0256c1dd-13b4-4c80-849b-281970d02d11', 'name': 'Slaapkamer', 'volume': {'level': 0.4000000059604645, 'muted': False}}, 'requestId': 0, 'type': 'DEVICE_UPDATED'}
2021-08-13 08:38:43 DEBUG (Thread-14) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 14, 'status': {'applications': [{'appId': 'CC32E753', 'appType': 'WEB', 'displayName': 'Spotify', 'iconUrl': 'https://lh3.googleusercontent.com/HOX9yqNu6y87Chb1lHYqhKVTQW43oFAFFe2ojx94yCLh0yMzgygTrM0RweAexApRWqq6UahgrWYimVgK', 'isIdleScreen': False, 'launchedFromCloud': False, 'namespaces': [{'name': 'urn:x-cast:com.google.cast.cac'}, {'name': 'urn:x-cast:com.google.cast.debugoverlay'}, {'name': 'urn:x-cast:com.spotify.chromecast.secure.v1'}, {'name': 'urn:x-cast:com.google.cast.broadcast'}, {'name': 'urn:x-cast:com.google.cast.media'}], 'sessionId': '7c4ff835-7f4a-43e5-b817-d978d830c6da', 'statusText': 'Spotify', 'transportId': '7c4ff835-7f4a-43e5-b817-d978d830c6da', 'universalAppId': 'CC32E753'}], 'userEq': {'high_shelf': {'frequency': 4500.0, 'gain_db': 0.0, 'quality': 0.707}, 'low_shelf': {'frequency': 150.0, 'gain_db': 0.0, 'quality': 0.707}, 'max_peaking_eqs': 0, 'peaking_eqs': []}, 'volume': {'controlType': 'master', 'level': 0.4000000059604645, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2021-08-13 08:38:43 DEBUG (Thread-14) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.4000000059604645, volume_muted=False, app_id='CC32E753', display_name='Spotify', namespaces=['urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.spotify.chromecast.secure.v1', 'urn:x-cast:com.google.cast.broadcast', 'urn:x-cast:com.google.cast.media'], session_id='7c4ff835-7f4a-43e5-b817-d978d830c6da', transport_id='7c4ff835-7f4a-43e5-b817-d978d830c6da', status_text='Spotify', icon_url='https://lh3.googleusercontent.com/HOX9yqNu6y87Chb1lHYqhKVTQW43oFAFFe2ojx94yCLh0yMzgygTrM0RweAexApRWqq6UahgrWYimVgK', volume_control_type='master')
2021-08-13 08:38:43 DEBUG (Thread-12) [pychromecast.socket_client] [Slaapkamer(192.168.xx.13):8009] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 14, 'status': {'applications': [{'appId': 'CC32E753', 'appType': 'WEB', 'displayName': 'Spotify', 'iconUrl': 'https://lh3.googleusercontent.com/HOX9yqNu6y87Chb1lHYqhKVTQW43oFAFFe2ojx94yCLh0yMzgygTrM0RweAexApRWqq6UahgrWYimVgK', 'isIdleScreen': False, 'launchedFromCloud': False, 'namespaces': [{'name': 'urn:x-cast:com.google.cast.cac'}, {'name': 'urn:x-cast:com.google.cast.debugoverlay'}, {'name': 'urn:x-cast:com.spotify.chromecast.secure.v1'}, {'name': 'urn:x-cast:com.google.cast.broadcast'}, {'name': 'urn:x-cast:com.google.cast.media'}], 'sessionId': '7c4ff835-7f4a-43e5-b817-d978d830c6da', 'statusText': 'Spotify', 'transportId': '7c4ff835-7f4a-43e5-b817-d978d830c6da', 'universalAppId': 'CC32E753'}], 'userEq': {'high_shelf': {'frequency': 4500.0, 'gain_db': 0.0, 'quality': 0.707}, 'low_shelf': {'frequency': 150.0, 'gain_db': 0.0, 'quality': 0.707}, 'max_peaking_eqs': 0, 'peaking_eqs': []}, 'volume': {'controlType': 'master', 'level': 0.4000000059604645, 'muted': False, 'stepInterval': 0.019999999552965164}}, 'type': 'RECEIVER_STATUS'}
2021-08-13 08:38:43 DEBUG (Thread-12) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.4000000059604645, volume_muted=False, app_id='CC32E753', display_name='Spotify', namespaces=['urn:x-cast:com.google.cast.cac', 'urn:x-cast:com.google.cast.debugoverlay', 'urn:x-cast:com.spotify.chromecast.secure.v1', 'urn:x-cast:com.google.cast.broadcast', 'urn:x-cast:com.google.cast.media'], session_id='7c4ff835-7f4a-43e5-b817-d978d830c6da', transport_id='7c4ff835-7f4a-43e5-b817-d978d830c6da', status_text='Spotify', icon_url='https://lh3.googleusercontent.com/HOX9yqNu6y87Chb1lHYqhKVTQW43oFAFFe2ojx94yCLh0yMzgygTrM0RweAexApRWqq6UahgrWYimVgK', volume_control_type='master')
2021-08-13 08:38:43 DEBUG (Thread-10) [pychromecast.socket_client] [Boven(192.168.xx.17):32213] Received: Message urn:x-cast:com.google.cast.multizone from receiver-0 to *: {'device': {'capabilities': 196612, 'deviceId': '0256c1dd-13b4-4c80-849b-281970d02d11', 'name': 'Slaapkamer', 'volume': {'level': 0.4000000059604645, 'muted': False}}, 'requestId': 0, 'type': 'DEVICE_UPDATED'}
2021-08-13 08:38:43 DEBUG (Thread-10) [pychromecast.socket_client] [Boven(192.168.xx.17):32213] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 0, 'status': {'userEq': {'high_shelf': {'frequency': 4500.0, 'gain_db': 0.0, 'quality': 0.707}, 'low_shelf': {'frequency': 150.0, 'gain_db': 0.0, 'quality': 0.707}, 'max_peaking_eqs': 0, 'peaking_eqs': []}, 'volume': {'controlType': 'master', 'level': 0.46666666865348816, 'muted': False, 'stepInterval': 0.05000000074505806}}, 'type': 'RECEIVER_STATUS'}
2021-08-13 08:38:43 DEBUG (Thread-10) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.46666666865348816, volume_muted=False, app_id=None, display_name=None, namespaces=[], session_id=None, transport_id=None, status_text='', icon_url=None, volume_control_type='master')
2021-08-13 08:38:43 DEBUG (Thread-9) [pychromecast.socket_client] [Hele huis(192.168.xx.17):32059] Received: Message urn:x-cast:com.google.cast.multizone from receiver-0 to *: {'device': {'capabilities': 196612, 'deviceId': '0256c1dd-13b4-4c80-849b-281970d02d11', 'name': 'Slaapkamer', 'volume': {'level': 0.4000000059604645, 'muted': False}}, 'requestId': 0, 'type': 'DEVICE_UPDATED'}
2021-08-13 08:38:43 DEBUG (Thread-9) [pychromecast.socket_client] [Hele huis(192.168.xx.17):32059] Received: Message urn:x-cast:com.google.cast.receiver from receiver-0 to *: {'requestId': 0, 'status': {'userEq': {'high_shelf': {'frequency': 4500.0, 'gain_db': 0.0, 'quality': 0.707}, 'low_shelf': {'frequency': 150.0, 'gain_db': 0.0, 'quality': 0.707}, 'max_peaking_eqs': 0, 'peaking_eqs': []}, 'volume': {'controlType': 'master', 'level': 0.5, 'muted': False, 'stepInterval': 0.05000000074505806}}, 'type': 'RECEIVER_STATUS'}
2021-08-13 08:38:43 DEBUG (Thread-9) [pychromecast.controllers] Received status: CastStatus(is_active_input=None, is_stand_by=None, volume_level=0.5, volume_muted=False, app_id=None, display_name=None, namespaces=[], session_id=None, transport_id=None, status_text='', icon_url=None, volume_control_type='master')
2021-08-13 08:38:44 ERROR (MainThread) [homeassistant.core] Error executing service: <ServiceCall spotcast.start (c:07b8cddbec9f29feda3f3d8f6ebeae15): account=t, entity_id=media_player.slaapkamer, uri=spotify:track:5OoSxUZSbP1p7kb1d0SozG, shuffle=False, repeat=off, start_volume=101, force_playback=False, random_song=False, offset=0, ignore_fully_played=False>
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/core.py", line 1507, in catch_exceptions
await coro_or_task
File "/usr/src/homeassistant/homeassistant/core.py", line 1530, 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 143, in start_casting
spotify_device_id = spotcast_controller.get_spotify_device_id(
File "/config/custom_components/spotcast/spotcast_controller.py", line 202, in get_spotify_device_id
spotify_cast_device.startSpotifyController(access_token, expires)
File "/config/custom_components/spotcast/spotcast_controller.py", line 84, in startSpotifyController
sp.launch_app()
File "/usr/local/lib/python3.9/site-packages/pychromecast/controllers/spotify.py", line 87, in launch_app
raise LaunchError(
pychromecast.error.LaunchError: Timeout when waiting for status response from Spotify app
XalaTheShepard commented 3 years ago

Further to the issue above, this issue does not only occur with Spotcast, but also with custom scripts to stream webradio streams to Google cast devices. The error log and outcome is identical as above. The only service that does not seem to be affected is the custom Youtube Music player.

Kind regards

Electronlibre2012 commented 3 years ago

Hello,

when spotify it start from my smartphone, and a googlehome selected, all works and the information of playing in HA works, can control volume and see what song is played, the problem is only to start cast, it doesnt work anymore. Hope developper will find a solution in the next update ;)

kylepotts commented 3 years ago

I could be wrong here, but it looks like maybe the spotify chromecast protocol might have changed?

I get this log

Sending: Message urn:x-cast:com.spotify.chromecast.secure.v1 from sender-0 to f658741b-e343-47be-b186-3e87fa255537: {'type': 'setCredentials' ...}

But do not seem to see any logs with the response the code is expecting https://github.com/home-assistant-libs/pychromecast/blob/master/pychromecast/controllers/spotify.py#L42

kylepotts commented 3 years ago

Put a pr together that seems to work for me.

https://github.com/home-assistant-libs/pychromecast/pull/521

emontnemery commented 3 years ago

Are there maybe two separate things going on here:

@XalaTheShepard could you please open a new issue and share your script which previously worked but no longer doesn't?

GSzabados commented 1 year ago

@emontnemery, this issue surfaced again recently.

hmmbob commented 1 year ago

Yes, indeed it did.

2023-09-03 20:35:06.439 ERROR (Thread-15) [pychromecast.socket_client] [(192.168.88.113):8009] Exception caught while sending message to controller SpotifyController: Message urn:x-cast:com.spotify.chromecast.secure.v1 from 540d6d97-a77a-4043-a45b-42cf5ba5f411 to sender-0: {'type': 'getInfoResponse', 'payload': {'version': '2.9.0', 'publicKey': 'empty', 'remoteName': 'Spotify on Cast', 'deviceType': 'cast_audio', 'brandDisplayName': 'google', 'modelDisplayName': 'Google_Home', 'libraryVersion': '5.30.3', 'resolverVersion': '1', 'groupStatus': 'NONE', 'deviceAPI_isGroup': False, 'tokenType': 'accesstoken', 'clientID': 'd7df0887fb71494ea994202cb473eae7', 'productID': 0, 'scope': 'streaming', 'availability': '', 'spotifyError': 0, 'status': 101, 'statusString': 'OK'}}
Traceback (most recent call last):
File "/usr/local/lib/python3.11/site-packages/pychromecast/socket_client.py", line 719, in _route_message
handled = handler.receive_message(message, data)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/spotify_controller.py", line 47, in receive_message
self.device = data["payload"]["deviceID"]
~~~~~~~~~~~~~~~^^^^^^^^^^^^
KeyError: 'deviceID'

2023-09-03 20:35:15.157 ERROR (MainThread) [homeassistant.components.script.start_music_t] Slaaptijd: Error executing script. Unexpected error for call_service at pos 2: Timeout when waiting for status response from Spotify app
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 467, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 703, in _async_call_service_step
response_data = await self._async_run_long_action(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 665, in _async_run_long_action
return long_task.result()
^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 1963, in async_call
response_data = await coro
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2007, in _execute_service
return await self._hass.async_add_executor_job(target, service_call)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/__init__.py", line 221, in start_casting
spotify_device_id = spotcast_controller.get_spotify_device_id(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/spotcast_controller.py", line 250, in get_spotify_device_id
spotify_cast_device.startSpotifyController(access_token, expires)
File "/config/custom_components/spotcast/spotcast_controller.py", line 95, in startSpotifyController
sp.launch_app()
File "/config/custom_components/spotcast/spotify_controller.py", line 104, in launch_app
raise LaunchError(
pychromecast.error.LaunchError: Timeout when waiting for status response from Spotify app

2023-09-03 20:35:15.165 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 596, in _async_run
return await self.script.async_run(script_vars, context)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1570, in async_run
return await asyncio.shield(run.async_run())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 419, in async_run
await self._async_step(log_exceptions=False)
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 469, in _async_step
self._handle_exception(
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 492, in _handle_exception
raise exception
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 467, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 703, in _async_call_service_step
response_data = await self._async_run_long_action(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 665, in _async_run_long_action
return long_task.result()
^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 1963, in async_call
response_data = await coro
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2007, in _execute_service
return await self._hass.async_add_executor_job(target, service_call)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/__init__.py", line 221, in start_casting
spotify_device_id = spotcast_controller.get_spotify_device_id(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/spotcast_controller.py", line 250, in get_spotify_device_id
spotify_cast_device.startSpotifyController(access_token, expires)
File "/config/custom_components/spotcast/spotcast_controller.py", line 95, in startSpotifyController
sp.launch_app()
File "/config/custom_components/spotcast/spotify_controller.py", line 104, in launch_app
raise LaunchError(
pychromecast.error.LaunchError: Timeout when waiting for status response from Spotify app

2023-09-03 20:35:40.585 ERROR (Thread-16) [pychromecast.socket_client] [(192.168.88.113):8009] Exception caught while sending message to controller SpotifyController: Message urn:x-cast:com.spotify.chromecast.secure.v1 from 31288e75-ec9c-42e9-bd9b-008994b003c7 to sender-0: {'type': 'getInfoResponse', 'payload': {'version': '2.9.0', 'publicKey': 'empty', 'remoteName': 'Spotify on Cast', 'deviceType': 'cast_audio', 'brandDisplayName': 'google', 'modelDisplayName': 'Google_Home', 'libraryVersion': '5.30.3', 'resolverVersion': '1', 'groupStatus': 'NONE', 'deviceAPI_isGroup': False, 'tokenType': 'accesstoken', 'clientID': 'd7df0887fb71494ea994202cb473eae7', 'productID': 0, 'scope': 'streaming', 'availability': '', 'spotifyError': 0, 'status': 101, 'statusString': 'OK'}}
Traceback (most recent call last):
File "/usr/local/lib/python3.11/site-packages/pychromecast/socket_client.py", line 719, in _route_message
handled = handler.receive_message(message, data)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/spotify_controller.py", line 47, in receive_message
self.device = data["payload"]["deviceID"]
~~~~~~~~~~~~~~~^^^^^^^^^^^^
KeyError: 'deviceID'

2023-09-03 20:35:46.751 ERROR (MainThread) [homeassistant.components.script.start_music_t] Slaaptijd: Error executing script. Unexpected error for call_service at pos 2: Timeout when waiting for status response from Spotify app
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 467, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 703, in _async_call_service_step
response_data = await self._async_run_long_action(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 665, in _async_run_long_action
return long_task.result()
^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 1963, in async_call
response_data = await coro
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2007, in _execute_service
return await self._hass.async_add_executor_job(target, service_call)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/__init__.py", line 221, in start_casting
spotify_device_id = spotcast_controller.get_spotify_device_id(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/spotcast_controller.py", line 250, in get_spotify_device_id
spotify_cast_device.startSpotifyController(access_token, expires)
File "/config/custom_components/spotcast/spotcast_controller.py", line 95, in startSpotifyController
sp.launch_app()
File "/config/custom_components/spotcast/spotify_controller.py", line 104, in launch_app
raise LaunchError(
pychromecast.error.LaunchError: Timeout when waiting for status response from Spotify app

2023-09-03 20:35:46.757 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 596, in _async_run
return await self.script.async_run(script_vars, context)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1570, in async_run
return await asyncio.shield(run.async_run())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 419, in async_run
await self._async_step(log_exceptions=False)
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 469, in _async_step
self._handle_exception(
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 492, in _handle_exception
raise exception
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 467, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 703, in _async_call_service_step
response_data = await self._async_run_long_action(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 665, in _async_run_long_action
return long_task.result()
^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 1963, in async_call
response_data = await coro
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2007, in _execute_service
return await self._hass.async_add_executor_job(target, service_call)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/__init__.py", line 221, in start_casting
spotify_device_id = spotcast_controller.get_spotify_device_id(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/spotcast/spotcast_controller.py", line 250, in get_spotify_device_id
spotify_cast_device.startSpotifyController(access_token, expires)
File "/config/custom_components/spotcast/spotcast_controller.py", line 95, in startSpotifyController
sp.launch_app()
File "/config/custom_components/spotcast/spotify_controller.py", line 104, in launch_app
raise LaunchError(
pychromecast.error.LaunchError: Timeout when waiting for status response from Spotify app
GSzabados commented 1 year ago

Actually the one surfaced now is different from the old one. The response from the Spotify app on the cast device does not contain the deviceID what Spotcast utilising to get the accesstoken from the desktop player API, so Spotcast is unable to take control of the Spotify cast, so pychromecast times out. It is the case when the device is idle. If the device is already playing something, then the response from the Spotify app contains the deviceID and there isn't any error.

My guess it is an upstream change in how the Spotify app behaves on the cast device, as it used to provide the deviceID, but not anymore.

As it is beyond my understanding, I am not sure, why the deviceID is not provided anymore. Is it pychromecast initiating the Spotify app incorrectly, or what is causing it? But what is sure, that the Spotify app starts on the cast device, as it sends an info response, but why isn't any deviceID assigned is a good question.