music-assistant / hass-music-assistant

Turn your Home Assistant instance into a jukebox, hassle free streaming of your favorite media to Home Assistant media players.
Apache License 2.0
1.36k stars 52 forks source link

No sound from Spotify playback, even though track time increments and airplay connection sounds are heard #3092

Open mph070770 opened 3 days ago

mph070770 commented 3 days ago

What version of Music Assistant has the issue?

2.3.1

What version of the Home Assistant Integration have you got installed?

2024.10.1

Have you tried everything in the Troubleshooting FAQ and reviewed the Open and Closed Issues and Discussions to resolve this yourself?

The problem

When I first installed MA (yesterday) this was all working. Now, however, when I try and play any spotify track, it looks like it is going to work (airplay or chromecast connection noise), timecode for song increases, volume control on speaker can be controlled by MA, but there's no sound.

I have tried Airplay, Chromecast and HA media players and they all act the same. I have restarted HA I have restarted MA server. I have deleted and reconnected/authenticated Spotify.

Playing an internet radio stream works from MA. Playing from Spotify on my iphone to the speaker works.

How to reproduce

Not sure how I got into this state, but it's 100% failing in spite of restarts etcs.

Music Providers

Spotify fails Internet radio works.

Player Providers

Chomecast Airplay Home Assistant mediaplayers Sonos (on a Move 2) (only 1 enabled at any one time)

Full log output

log.txt

Additional information

No response

What version of Home Assistant Core are your running

2024.10.4

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Raspberry Pi

mph070770 commented 3 days ago

I reinstalled the server and HA integration and it still fails. In the server log, there is the following error:

`2024-10-27 16:12:35.206 INFO (MainThread) [music_assistant] Loaded music provider Spotify 2024-10-27 16:13:13.473 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Study speaker - crossfade: False 2024-10-27 16:13:14.265 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Study speaker - crossfade: False 2024-10-27 16:13:44.062 ERROR (MainThread) [music_assistant] Error doing task: Task exception was never retrieved Traceback (most recent call last): File "/app/venv/lib/python3.12/site-packages/music_assistant/server/controllers/players.py", line 92, in wrapper await func(self, *args, kwargs) File "/app/venv/lib/python3.12/site-packages/music_assistant/server/controllers/players.py", line 567, in play_media await player_prov.play_media( File "/app/venv/lib/python3.12/site-packages/music_assistant/server/providers/hass_players/init.py", line 264, in play_media await self.hass_prov.hass.call_service( File "/app/venv/lib/python3.12/site-packages/hass_client/client.py", line 184, in call_service return await self.send_command("call_service", params) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/app/venv/lib/python3.12/site-packages/hass_client/client.py", line 225, in send_command return await future ^^^^^^^^^^^^ hass_client.exceptions.FailedCommand: CastMediaPlayerEntity._quick_play Failed: Execution of quick play http://192.168.1.73:8097/flow/media_player.study_le02/b4ec38c637d5436e8732212f00a9fa9c.mp3?ts=1730045593 timed out after 30.0 s.

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

Traceback (most recent call last): File "/app/venv/lib/python3.12/site-packages/music_assistant/server/controllers/players.py", line 94, in wrapper raise PlayerCommandFailed(str(err)) from err music_assistant.common.models.errors.PlayerCommandFailed: CastMediaPlayerEntity._quick_play Failed: Execution of quick play http://192.168.1.73:8097/flow/media_player.study_le02/b4ec38c637d5436e8732212f00a9fa9c.mp3?ts=1730045593 timed out after 30.0 s.`

mph070770 commented 3 days ago

I uploaded an mp3 test file to my truenas server, and can stream that file to my speaker. It suggests there's something wrong with fetching Spotify content?

and I also tried a snapclient:

2024-10-27 19-16-39.061 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2 2024-10-27 19-16-39.061 [Info] (Player) Player name: wasapi, device: default, description: Speakers (Realtek(R) Audio), idx: 0, sharing mode: shared, parameters: 2024-10-27 19-16-39.061 [Info] (Player) Mixer mode: software, parameters: 2024-10-27 19-16-39.061 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2 2024-10-27 19-16-39.063 [Info] (WASAPI) Device accepts format: 48000:32:2 2024-10-27 19-16-39.073 [Info] (WASAPI) Initializing WASAPI in shared mode 2024-10-27 19-16-39.107 [Info] (Stream) No chunks available 2024-10-27 19-16-39.107 [Info] (WASAPI) Failed to get chunk 2024-10-27 19-16-39.212 [Info] (WASAPI) Waiting for chunk 2024-10-27 19-16-39.320 [Info] (WASAPI) Waiting for chunk 2024-10-27 19-16-39.428 [Info] (WASAPI) Waiting for chunk 2024-10-27 19-16-39.537 [Info] (WASAPI) Waiting for chunk 2024-10-27 19-16-39.647 [Info] (WASAPI) Waiting for chunk

philadou commented 2 days ago

same problem. no playback from Spotify :(

OzGav commented 2 days ago

Is there anything unusual about your network setup? Firewalls, ad blockers….?

mph070770 commented 2 days ago

No, nothing. It was working when I first installed on Saturday and when I retested on Sunday, that was when the problem first occurred.

philadou commented 2 days ago

Same here... I've had it installed for months. No changes to the firewall, blockers, etc. Suddenly, I can no longer select any Spotify content. It shows that the track is playing, and the cover art is displayed, but there's absolutely no sound coming from the speakers. Just silence. When I select an internet radio stream, it plays perfectly fine. Only Spotify doesn’t work. A few days earlier, I installed the latest MA update. Maybe that's the issue 🤷‍♂️

OzGav commented 2 days ago

For those +1-ing restart MA, attempt to play Spotify, wait 5 mins and then download and ATTACH the log to your post above (we don’t need more posts)

czubocha commented 2 days ago

I’m experiencing similar issues. When I try to AirPlay to a Sonos speaker or Sony soundbar, there’s no sound, but it shows that the track is playing, and the cover art is displayed. Even the Sonos app indicates that AirPlay is active. However, it works fine when I use the Sonos speaker with the native Sonos provider and the Sony soundbar with the Chromecast provider. My goal, though, is to use them together in a group via AirPlay. Logs after restarting MA and playing 2 songs on Spotify: MA_logs.txt

Music Assistant Server: 2.3.1 Home Assistant: Core 2024.10.3, Supervisor 2024.10.3, HAOS 13.2

philadou commented 2 days ago

Download Log: MA_log_1.txt

2024-10-28 09:17:00.803 INFO (MainThread) [music_assistant] Starting Music Assistant Server (cbc44c86810f4c0a94dd82aad91371be) version 2.3.1 - HA add-on: True - Safe mode: False 2024-10-28 09:17:00.811 INFO (MainThread) [music_assistant.cache] Initializing cache controller... 2024-10-28 09:17:01.946 INFO (MainThread) [music_assistant.music] Using a sync interval of 180 minutes. 2024-10-28 09:17:02.273 INFO (MainThread) [music_assistant.streams] Detected ffmpeg version 6.1.1 with libsoxr support 2024-10-28 09:17:02.274 INFO (MainThread) [music_assistant.streams] Starting server on 0.0.0.0:8097 - base url: http://192.168.188.54:8097 2024-10-28 09:17:02.284 INFO (MainThread) [music_assistant.webserver] Starting server on 172.30.32.1:8095 - base url: http://172.30.32.1:8095 2024-10-28 09:17:06.844 INFO (MainThread) [music_assistant] Loaded metadata provider The Audio DB 2024-10-28 09:17:06.845 INFO (MainThread) [music_assistant] Loaded music provider Music Assistant 2024-10-28 09:17:06.845 INFO (MainThread) [music_assistant] Loaded metadata provider MusicBrainz 2024-10-28 09:17:06.845 INFO (MainThread) [music_assistant] Loaded metadata provider fanart.tv 2024-10-28 09:17:06.850 INFO (MainThread) [music_assistant] Loaded player provider Playergroup 2024-10-28 09:17:06.862 INFO (MainThread) [music_assistant.players] Player registered: ugp_kk7ytzh3/everywhere 2024-10-28 09:17:06.899 INFO (MainThread) [music_assistant] Loaded plugin provider Home Assistant 2024-10-28 09:17:07.018 INFO (MainThread) [music_assistant] Loaded player provider Home Assistant MediaPlayers 2024-10-28 09:17:07.041 INFO (MainThread) [music_assistant] Loaded music provider RadioBrowser 2024-10-28 09:17:07.052 INFO (MainThread) [music_assistant.players] Player registered: media_player.homepod_buro/HomePod Büro 2024-10-28 09:17:07.056 INFO (MainThread) [music_assistant.players] Player registered: media_player.homepod_kuche/HomePod Küche 2024-10-28 09:17:07.061 INFO (MainThread) [music_assistant.players] Player registered: media_player.homepod_wohnzimmer/HomePod Wohnzimmer 2024-10-28 09:17:07.069 INFO (MainThread) [music_assistant.players] Player registered: media_player.homepod_schlafzimmer/HomePod Schlafzimmer 2024-10-28 09:17:07.248 INFO (MainThread) [music_assistant] Loaded player provider Airplay 2024-10-28 09:17:07.291 INFO (MainThread) [music_assistant.players] Player registered: ap8eb66dd2de12/küche 2024-10-28 09:17:07.305 INFO (MainThread) [music_assistant.players] Player registered: ap7a19e50953c9/homepod wohnzimmer 2024-10-28 09:17:07.311 INFO (MainThread) [music_assistant.players] Player registered: ap469ebafe1bf2/homepod schlafzimmer 2024-10-28 09:17:07.392 INFO (MainThread) [music_assistant.players] Player registered: ap164da833c2bc/homepod büro 2024-10-28 09:17:07.536 INFO (MainThread) [music_assistant.spotify] Successfully logged in to Spotify as Phil 2024-10-28 09:17:07.536 INFO (MainThread) [music_assistant] Loaded music provider Spotify 2024-10-28 09:17:07.560 INFO (MainThread) [music_assistant.music] Sync task for RadioBrowser completed 2024-10-28 09:17:07.696 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed 2024-10-28 09:17:13.456 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Spotify Rate Limiter 2024-10-28 09:17:13.456 INFO (MainThread) [music_assistant.spotify] Retrying in 11 seconds... 2024-10-28 09:17:24.478 INFO (MainThread) [music_assistant.spotify] Attempt 2/5 failed: Spotify Rate Limiter 2024-10-28 09:17:24.478 INFO (MainThread) [music_assistant.spotify] Retrying in 1 seconds... 2024-10-28 09:17:43.770 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Spotify Rate Limiter 2024-10-28 09:17:43.770 INFO (MainThread) [music_assistant.spotify] Retrying in 10 seconds... 2024-10-28 09:17:53.794 INFO (MainThread) [music_assistant.spotify] Attempt 2/5 failed: Spotify Rate Limiter 2024-10-28 09:17:53.794 INFO (MainThread) [music_assistant.spotify] Retrying in 1 seconds... 2024-10-28 09:18:12.492 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Spotify Rate Limiter 2024-10-28 09:18:12.492 INFO (MainThread) [music_assistant.spotify] Retrying in 12 seconds... 2024-10-28 09:18:24.515 INFO (MainThread) [music_assistant.spotify] Attempt 2/5 failed: Spotify Rate Limiter 2024-10-28 09:18:24.515 INFO (MainThread) [music_assistant.spotify] Retrying in 1 seconds... 2024-10-28 09:18:34.641 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Phil completed 2024-10-28 09:18:47.196 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Spotify Rate Limiter 2024-10-28 09:18:47.196 INFO (MainThread) [music_assistant.spotify] Retrying in 7 seconds... 2024-10-28 09:18:54.218 INFO (MainThread) [music_assistant.spotify] Attempt 2/5 failed: Spotify Rate Limiter 2024-10-28 09:18:54.218 INFO (MainThread) [music_assistant.spotify] Retrying in 1 seconds... 2024-10-28 09:18:55.646 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue everywhere - crossfade: False 2024-10-28 09:20:11.748 WARNING (MainThread) [music_assistant.audio.media_stream] Stream error on spotify--GTZHLEkb://track/2GhirY1WxwRTIW6R6FowyO 2024-10-28 09:20:12.130 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue everywhere - crossfade: False

OzGav commented 2 days ago

@philadou you have rate limiting. Refer to the Spotify page in the docs for how to fix

OzGav commented 2 days ago

@czubocha you also have rate limiting

philadou commented 2 days ago

@OzGav Do you mean this fix?

img01

I've already done this from the beginning.

img02

Or do you mean something different?

OzGav commented 2 days ago

@philadou so confirming that you added your client id to the MA configuration when you setup the Spotify provider in MA?

philadou commented 2 days ago

Yes, I did that from the beginning. It worked perfectly for weeks.

OzGav commented 2 days ago

@philadou i just wasn’t sure why you were showing me the Spotify dashboard? You are presently the only person to report a rate limit when having added that client id to the MA settings. Have you checked the stats in the dashboard to see what is going on?

philadou commented 2 days ago

@OzGav I just thought it was important. I know I did it, but just to be on the safe side, where can I check if the client ID is entered correctly in MA? Maybe something went wrong after the update 🤷‍♂️ Should I delete the Spotify integration in MA and set it up again?

itsteddyyo commented 2 days ago

@philadou No need to delete the whole Spotify integration. Just head over to Settings → Music Providers → Spotify and click on Clear Authentication.

For me, I noticed that my Client ID had disappeared at some point. I had re-authenticated with Spotify after Marcel set up the new authentication flow, and I’m positive I entered the Client ID back then. But today, while double-checking, I saw on the Spotify Developer Dashboard that my client hadn’t been active for at least a month (unfortunately, that’s as far back as Spotify’s logs go). I went through the re-authentication process again, and now I’m not seeing any more rate limiter messages in the logs 😄

mph070770 commented 1 day ago

ok, so I've done nothing (I've been at work all day) but I came home and thought I'd do some debugging but have found that it's started working - with no reboots or anything.

Could this somehow be a Spotify issue?

OzGav commented 1 day ago

@mph070770 it could be. The stream error in your original report looks like a single track so perhaps that was unavailable for a period? Once you are happy this is resolved you can close this as all other reporters have the different, rate limiting, problem.

mph070770 commented 1 day ago

@OzGav i tried a number of tracks throughout the day yesterday and none of them worked (but looked like they were playing). All very strange but yes, if it continues to work I'll close the issue.

OzGav commented 1 day ago

@mph070770 ok we will keep looking into this