home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
74.06k stars 31.08k forks source link

Spotify media_player entity gets unavailable, Max Retries Reached #98413

Closed rafareusch closed 1 year ago

rafareusch commented 1 year ago

The problem

Spotify media player entity goes unavailable out of nowhere.

My use-case: I use the spotify app to launch and control music, and only use HA to see what's currently playing and to go to the next music. Sometimes, out of nowhere (without any input), the entity gets unavailable . I'm getting this behavior since I started using HA, July/22 but always tought it was a config issue.

Sometimes reloading the integration solves the issue. Sometimes not.

The logs here are one of the times that a integration reload wont work. (If I wait some hours, it will solve on it's own)

Cheers!

What version of Home Assistant Core has the issue?

2023.08.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Spotify

Link to integration documentation on our website

https://www.home-assistant.io/integrations/spotify/

Diagnostics information

spotify_logs.txt

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

I have about 6 running instances of HA, and all of them have this issue in random times. The logs I annexed is one specific instance in which this error is more recurrent. This HA instance is a restoration of the backup of another instance (which is also running) I deleted core.uuid and .cloud directory to prevent issues in other integrations and certificates. But this issue also happened in the other instance before even generating the backup.

home-assistant[bot] commented 1 year ago

Hey there @frenck, mind taking a look at this issue as it has been labeled with an integration (spotify) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `spotify` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign spotify` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)


spotify documentation spotify source (message by IssueLinks)

joostlek commented 1 year ago

Are you using your Spotify application credentials for more than just HA?

rafareusch commented 1 year ago

Are you using your Spotify application credentials for more than just HA?

No, each instance has it's own spotify account

Also I forgot to mention that I use nabucasa.

joostlek commented 1 year ago

Oh wait I now reread your last line.

I mean application credentials you got from Spotify. It could be that you're not hitting the account api rate limit, but the one for the application

rafareusch commented 1 year ago

Oh wait I now reread your last line.

I mean application credentials you got from Spotify. It could be that you're not hitting the account api rate limit, but the one for the application

Pardon my ignorance, but if i use two different accounts, isn't two completely different credentials? Or this could be brought together with the restore process?

joostlek commented 1 year ago

Right,

When you setup Spotify in HA, you register a new application in Spotify. This gives you an app id and an app secret. You fill this in HA and then you log in with your account.

What I am suspecting is that you use the same application credentials (for that Spotify application) for every instance, and that an application also has a different rate limit.

Check the Spotify docs for how to setup to maybe get a clearer image what I mean

rafareusch commented 1 year ago

Yeah, I don't think that's the case, because I set up completely different accounts, in Spotify and followed the process just per doc intructions (Creating one spotify application per spotify account), consequently, both HAs have completely different app id/secret.

joostlek commented 1 year ago

Right, this is good to know.

I'll be able to try to reproduce this later this week or next week and checkout what's happening.

rafareusch commented 1 year ago

Could a repeated update_entity and/or integration reload cause this issue?

I've seen this issue for so much time that I have an automation to auto-reload spotify if the entity gets in Unavailable state. It also uses the update_entity service to update the current state.

Obviously I observed the issue before creating this automation, but who knows...

joostlek commented 1 year ago

Well, in your logs I see that the whole chain starts with a 429, which means that you hit the rate limit. Since you say you only use it for observation, it couldn't be because of spamming controls or something.

Can you share the update entity service?

rafareusch commented 1 year ago

Well, in your logs I see that the whole chain starts with a 429, which means that you hit the rate limit. Since you say you only use it for observation, it couldn't be because of spamming controls or something.

Can you share the update entity service?

It's an watchdog automation that updates the entity each 3 seconds if the music is currently paused/playing (not in idle)

But it's important to say this also happens when nothing is playing, in this case no pooling is done. (outside HA core)

joostlek commented 1 year ago

I think this could be a reason you get this as you're polling 10 times as much

rafareusch commented 1 year ago

Unfortunately, in the other instance nothing is being played, and the same behavior, I was just checking if the watchdog was running, but it was not.

In which frequency HA updates the entity on it's own?

joostlek commented 1 year ago

30 seconds

rafareusch commented 1 year ago

I'll disable this watchdog and verify if something changes. I'll also play some random music on the other Instance for some hours to see if something changes!

If you could, try to reproduce at your end.

joostlek commented 1 year ago

Now that I think of it, HA updates once every 30s but for one update it does 1-2(?) Requests, one for the current playing, and the playlist it's listening to (if different from the last time something got played).

Once every 15 minutes it also collects device info.

Can you send a screenshot of your Spotify dashboard with the request graph?

rafareusch commented 1 year ago

(This HA instance was created Aug 11) image

rafareusch commented 1 year ago

at 18:00 (brt) My automation reloaded the integration and now it's back on idle.

I'm currently running a 1s update_entity on another instance to test if this can cause the issue I reported.

joostlek commented 1 year ago

Screenshot_20230814-231314.png

I think it settles down at 3k idle and the spikes are the extra requests. I'll try to read up on the rate limiting tomorrow!

joostlek commented 1 year ago

While you're at it, can you also test slowing it down?

rafareusch commented 1 year ago

I think it settles down at 3k idle and the spikes are the extra requests. I'll try to read up on the rate limiting tomorrow!

Awesome!

While you're at it, can you also test slowing it down?

Of course, what frequency you want?

rafareusch commented 1 year ago

I think it settles down at 3k idle and the spikes are the extra requests. I'll try to read up on the rate limiting tomorrow!

Makes sense... you said it is 30s for two requests, that's 2880 per day. Am I right?

joostlek commented 1 year ago

Yep. Maybe just try a minute.

I'm also curious, why do you have 6 Spotify instances if I may ask

rafareusch commented 1 year ago

Yep. Maybe just try a minute.

I'm also curious, why do you have 6 Spotify instances if I may ask

I'm currently testing a market niche for HA installs 😁

So i'm trying to contribute as much as I can to this fantastic system

Just to make things clearer, its 6 HA instances each one with it's own spotify instance

rafareusch commented 1 year ago

@joostlek I'm running a 1 second update_entity automation for 5 hours now, no logged errors.

joostlek commented 1 year ago

Can you share the spotlight graph of them?

rafareusch commented 1 year ago

Is there an issue with the spotify dashboard? The app isn't showing in this specific account's app

But still connected to HA.. 16h constant 1s pooling

rafareusch commented 1 year ago

I'm still getting this error, in the first instance without doing any type of extra pooling: When this message appears, the media_player goes unavailable, reloading the integration brings the entity back.

2023-08-15 12:12:43.337 ERROR (MainThread) [homeassistant.components.spotify] Error fetching ARQFORMA Devices data: 2023-08-15 12:22:43.337 ERROR (MainThread) [homeassistant.components.spotify] Error fetching ARQFORMA Devices data: 2023-08-15 12:42:43.336 ERROR (MainThread) [homeassistant.components.spotify] Error fetching ARQFORMA Devices data: 2023-08-15 12:52:43.338 ERROR (MainThread) [homeassistant.components.spotify] Error fetching ARQFORMA Devices data:

I'm seeing this exact error on another two instances, on 2023.7.1 and 2023.6.1

joostlek commented 1 year ago

Is there an issue with the spotify dashboard? The app isn't showing in this specific account's app

But still connected to HA.. 16h constant 1s pooling

Maybe check the other accounts? I would expect they would show it. Maybe you did have some applications with more logins.

joostlek commented 1 year ago

Does ARQFARMA say anything to you?

rafareusch commented 1 year ago

Does ARQFARMA say anything to you?

It's the integration handler name, set by HA, or the spotify account name, both are the same.

Here are the logs from today, (I believe is the same errors, but whatever) newlogs.txt No entity update is being done

rafareusch commented 1 year ago

I'll delete the integration, create a new app and readd the integration to see if something changes. But this spotify/ha instance seems more unstable than the others.

joostlek commented 1 year ago

This looks interesting, I think I'll continue this investigation when I'm back home later this week

rafareusch commented 1 year ago

Adding more info: On the second instance, after 48 hours of constant 1s pooling (update_entity) + about 6h of music playing, I'm stopping this test. Some errors "Error fetching XX devices data" was thrown, but always recovered reloading the integration.

The first instance (the one I mentioned in the first post), I removed all pooling done by my automations. and the issue still persist, logs from today: newlogs.txt

I'll try to reinstall the integration and recreate the app soon.

rafareusch commented 1 year ago

@joostlek Another information:

I created another spotfy dashboard app (deleted the old one) in the ARQFORMA account, and readded the integration to the first and second instance, and I saw that both instances have the same error in the logs at the same time. Funny that the second ha instance has another spotify account, which works perfectly fine. Seems that this account is problematic in some way...

rafareusch commented 1 year ago

Okay... so this doesn't make any sense.

I created another HA instance and new premium spotify account (account_x), on a completely different ISP and location. The only thing that's the same it's derived from the same instance's backup (which work fine) Same issue with this newer account, same error, unavailable in random and most of the time. At this time it even wont recognize any entity from this account. Adding a second (old which works) spotify account (user management in spotify app dashboard) and including in the same HA works perfectly fine

This "account_x" wont work in any instance I have. Maybe I could disseminate auth id's so you can take a better look. Same behavior of the account I mentioned with the post.

What's going on spotify? lol

joostlek commented 1 year ago

I mean after that one bug I told before, I am not even surprised at this point. Since you're stacked with spotify accounts, can you maybe contact me on Discord to exchange account credentials so I can also take a look from my dev machine?

rafareusch commented 1 year ago

Of course, my Discord: (deleted)

rafareusch commented 1 year ago

After many tests across two separate HA/Spotify instances, and many discussions with @joostlek, here are our findings:

Instance 1: The instance which I was refering when I opened this issue:

Instance 2: A second instance in which have the same configuration and was also having the same exact error

I've also tried to add other (much older) spotify accounts to these instances and all of them work perfectly fine! Adding these two problematic spotify accounts to other HA instances also present the same issue, seems that these newer accounts have a problematic behavior.

From now on I'll let the skill enabled in the second instance to see if this issue will also solve by itself, because, having the spotify skill in alexa enables the account to play in alexa speakers natively, making much easier the usage.