search

fondberg / spotcast

Home assistant custom component to start Spotify playback on an idle chromecast device as well as control spotify connect devices
Apache License 2.0
640 stars 94 forks source link

Only as task: HTTP status 403, restriction violated, reason: UNKNOWN #412

Closed TheMrDec closed 9 months ago

TheMrDec commented 9 months ago

Bug Ticket

Describe the bug

Over the past few weeks, Spotify has been returning a 403 when trying to start playback on my Google Home Mini using a time based automation. Curiously, running the automation manually at an arbitrary time does not return this error. As such, troubleshooting has been nearly impossible.

Troubleshooting

Versions; Spotcast and HA are up to date Spotcast v3.7.1

Spotify Integration in home assistant is working Secrets are valid, though I did redo the setup process completely with no change I have Spotify Premium and am using only one account in HA I am using Entity ID in the service call. I have tried Device ID and Device Name with no change

Environment

HAOS - 10.5 HA Supervisor - 2023.09.2 HA Core - 2023.9.3 Frontend - 2023.09.11.0 - latest

Configuration


spotcast:
    sp_dc: !secret sp_dc
    sp_key: !secret sp_key
    country: US

input_select:
  spotcast_audio:
    name: Spotcast Audio
    options:
      - "Josh PC"
      - "Speaker"
      - "Spike"
    icon: mdi:cast-audio

sensor:
    - platform: time_date
      display_options:
        - 'time'
        - 'date'
        - 'date_time'
        - 'date_time_utc'
        - 'date_time_iso'
        - 'time_date'
        - 'time_utc'
        - 'beat'

automation: !include automations.yaml
script: !include scripts.yaml
scene: !include scenes.yaml

Service Call

If relevant, provide a yaml of the service call or explain the action taken to replicate the issue.


alias: 06:30 Spotcast Start
description: ""
trigger:
  - platform: time
    at: "06:30:00"
condition:
  - condition: time
    after: "00:00:00"
    before: "00:00:00"
    weekday:
      - fri
      - thu
      - wed
      - tue
      - mon
action:
  - service: spotcast.start
    data:
      force_playback: true
      random_song: true
      repeat: "off"
      shuffle: true
      offset: 0
      uri: spotify:playlist:37i9dQZEVXcRSAC5fQ0ZfP
      start_volume: 20
      entity_id: media_player.bedroom_speaker
      limit: 20
mode: restart

Logs

normal, debug has been enabled going forward


2023-10-04 05:30:26.702 WARNING (Thread-683) [pychromecast.socket_client] [(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:26.705 WARNING (Thread-173) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:26.887 WARNING (Thread-261) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:26.894 WARNING (Thread-5) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.847 WARNING (Thread-682) [pychromecast.socket_client] [(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.857 WARNING (Thread-262) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.870 WARNING (Thread-679) [pychromecast.socket_client] [(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.877 WARNING (Thread-596) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.880 WARNING (Thread-88) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.880 WARNING (Thread-347) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.880 WARNING (Thread-85) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.886 WARNING (Thread-91) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:31.886 WARNING (Thread-346) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Heartbeat timeout, resetting connection
2023-10-04 05:30:38.970 ERROR (Thread-596) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:38.971 ERROR (Thread-682) [pychromecast.socket_client] [(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:38.974 ERROR (Thread-679) [pychromecast.socket_client] [(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:38.974 ERROR (Thread-262) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:39.034 ERROR (Thread-347) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:39.035 ERROR (Thread-88) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:39.036 ERROR (Thread-85) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:39.037 ERROR (Thread-346) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:42.168 ERROR (Thread-173) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:42.170 ERROR (Thread-261) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:42.171 ERROR (Thread-683) [pychromecast.socket_client] [(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:42.172 ERROR (Thread-5) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 05:30:47.322 ERROR (Thread-91) [pychromecast.socket_client] [Bedroom speaker(192.168.207.29):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.207.29', 8009)), retrying in 5.0s
2023-10-04 06:30:10.049 ERROR (SyncWorker_0) [spotipy.client] HTTP Error for PUT to https://api.spotify.com/v1/me/player/play?device_id=<DEV UUID> with Params: {} returned 403 due to Player command failed: Restriction violated
2023-10-04 06:30:10.053 ERROR (MainThread) [homeassistant.components.automation.06_30_spotcast_start] 06:30 Spotcast Start: Error executing script. Unexpected error for call_service at pos 1: http status: 403, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=<DEV UUID>:
 Player command failed: Restriction violated, reason: UNKNOWN
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/spotipy/client.py", line 271, in _internal_call
    response.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 403 Client Error: Forbidden for url: https://api.spotify.com/v1/me/player/play?device_id=<DEV UUID>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 704, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 666, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 1969, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2013, 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 256, in start_casting
    spotcast_controller.play(
  File "/config/custom_components/spotcast/spotcast_controller.py", line 384, in play
    client.start_playback(**kwargs)
  File "/usr/local/lib/python3.11/site-packages/spotipy/client.py", line 1821, in start_playback
    return self._put(
           ^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/spotipy/client.py", line 338, in _put
    return self._internal_call("PUT", url, payload, kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/spotipy/client.py", line 293, in _internal_call
    raise SpotifyException(
spotipy.exceptions.SpotifyException: http status: 403, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=<DEV UUID>:
 Player command failed: Restriction violated, reason: UNKNOWN
2023-10-04 06:30:10.071 ERROR (MainThread) [homeassistant.components.automation.06_30_spotcast_start] While executing automation automation.06_30_spotcast_start
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/spotipy/client.py", line 271, in _internal_call
    response.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 403 Client Error: Forbidden for url: https://api.spotify.com/v1/me/player/play?device_id=<DEV UUID>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 659, in async_trigger
    await self.action_script.async_run(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1579, in async_run
    return await asyncio.shield(run.async_run())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 420, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 470, in _async_step
    self._handle_exception(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 493, in _handle_exception
    raise exception
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 704, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 666, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 1969, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2013, 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 256, in start_casting
    spotcast_controller.play(
  File "/config/custom_components/spotcast/spotcast_controller.py", line 384, in play
    client.start_playback(**kwargs)
  File "/usr/local/lib/python3.11/site-packages/spotipy/client.py", line 1821, in start_playback
    return self._put(
           ^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/spotipy/client.py", line 338, in _put
    return self._internal_call("PUT", url, payload, kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/spotipy/client.py", line 293, in _internal_call
    raise SpotifyException(
spotipy.exceptions.SpotifyException: http status: 403, code:-1 - https://api.spotify.com/v1/me/player/play?device_id=<DEV UUID>:
 Player command failed: Restriction violated, reason: UNKNOWN

Additional context

As I said in the open, if I run the task manually at an arbitrary time, it works flawlessly. The only conflict I could think of is that I use the same speaker to play some ambience to fall asleep using Google's built in functions but I have this set up to stop at 05:30. This wasnt an issue prior but I do see entries in the logs when trying to stop the playback in HA now. I am going to try rolling that action back to 04:00 to give more airgap between that and spotcast.

Henk72 commented 9 months ago

I have the same problem for quite a while now. Timed start fails, doing a manual restart works.

My errors vary between a 403 and 502:

http status: 403, code:-1 - https://api.spotify.com/v1/me/player/volume?volume_percent=50&device_id=xxxxx: Player command failed: Restriction violated, reason: UNKNOWN

http status: 429, code:-1 - /v1/me/player: Max Retries, reason: too many 502 error responses

fcusson commented 9 months ago

Try removing the force playback command, it might clause problem if the player is already in an activity.

fcusson commented 9 months ago

Basically restriction violated means your query to spotify api is impossible. Since spotcast only has one service, if your options are not set correctly you can make the service call fail

TheMrDec commented 9 months ago

Well, I did two things that fixed the issue. First, I moved the automation to cut playback of the ambiance sounds to Google Home.

Second, I moved the automation to cut playback to 04:00

So this is not a Spotcast issue, and is like not even a Spotify issue. Its either a Google software limitation, or a hardware bug of some sort.

I really ought to just get SIP addressing fixed on my network and get these damn Google devices out of my house . . .