Error opening source from spotify

[beaudett]

Hi, I am currently unable to play any track from spotify with owntone Version 28.9 running on RPi 4 with bullseye. In the web interface, the search in spotify works. On a restart, the spotify playlists are correctly read and appear in the library. When it comes to play the tracks that I get an error. On the web interface, it appears as follows.

In the log file I see such errors:

[2024-09-03 20:10:19] [  LOG]  spotify: Error opening source: Cannot connect to access point, cooldown after disconnect is in effect
[2024-09-03 20:10:19] [DEBUG]  spotify: stop()

A longer part of the logfile can be found here I am wondering if it can be a temporary problem on the spotify side ? Thanks Florian

[theclive]

I’m currently having exactly the same problem.

sample error from the logs:

[2024-09-03 20:45:18] [  LOG]  spotify: Error opening source: Cannot connect to access point, cooldown after disconnect is in effect
[2024-09-03 20:45:18] [  LOG]      web: JSON api request failed with error code 500 (/api/queue/items/add?clear=true&playback=start&shuffle=false&uris=library:track:469)

And yet startup works fine:

[2024-09-03 20:44:42] [  LOG]     main: mDNS deinit
[2024-09-03 20:44:42] [  LOG]     main: Remote pairing deinit
[2024-09-03 20:44:42] [  LOG]     main: MPD deinit
[2024-09-03 20:44:42] [  LOG]     main: HTTPd deinit
[2024-09-03 20:44:42] [  LOG]     main: Player deinit
[2024-09-03 20:44:42] [  LOG]     main: Library scanner deinit
[2024-09-03 20:44:42] [  LOG]     main: Cache deinit
[2024-09-03 20:44:42] [  LOG]     main: Worker deinit
[2024-09-03 20:44:42] [  LOG]     main: Database deinit
[2024-09-03 20:44:42] [  LOG]     main: Exiting.
[2024-09-03 20:44:42] [  LOG]     main: OwnTone version 28.9 taking off
[2024-09-03 20:44:42] [  LOG]     main: Built with:
[2024-09-03 20:44:42] [  LOG]     main: - ffmpeg
[2024-09-03 20:44:42] [  LOG]     main: - Spotify
[2024-09-03 20:44:42] [  LOG]     main: - librespot-c
[2024-09-03 20:44:42] [  LOG]     main: - LastFM
[2024-09-03 20:44:42] [  LOG]     main: - Chromecast
[2024-09-03 20:44:42] [  LOG]     main: - MPD
[2024-09-03 20:44:42] [  LOG]     main: - Websockets
[2024-09-03 20:44:42] [  LOG]     main: - ALSA
[2024-09-03 20:44:42] [  LOG]     main: - Pulseaudio
[2024-09-03 20:44:42] [  LOG]     main: - Webinterface
[2024-09-03 20:44:42] [  LOG]     main: - Regex
[2024-09-03 20:44:42] [  LOG]     main: mDNS init
[2024-09-03 20:44:42] [  LOG]     mdns: Avahi state change: Client running
[2024-09-03 20:44:42] [  LOG]       db: Now vacuuming database, this may take some time...
[2024-09-03 20:44:44] [  LOG]       db: Database OK with 264 active files and 12 active playlists
[2024-09-03 20:44:44] [  LOG]   laudio: Pulseaudio failed with error: Connection refused
[2024-09-03 20:44:44] [  LOG]   laudio: Error initializing Pulseaudio: Connection refused
[2024-09-03 20:44:45] [  LOG]     scan: Scanned 200 files...
[2024-09-03 20:44:45] [  LOG]     scan: Scanned 400 files...
[2024-09-03 20:44:47] [  LOG]     scan: Bulk library scan completed in 3 sec
[2024-09-03 20:44:50] [  LOG]  spotify: Logged into Spotify succesfully with username {redacted}
[2024-09-03 20:44:51] [  LOG]  spotify: Scanned 1 of 5 saved playlists
[2024-09-03 20:44:52] [  LOG]  spotify: Scanned 2 of 5 saved playlists
[2024-09-03 20:44:53] [  LOG]  spotify: Scanned 3 of 5 saved playlists
[2024-09-03 20:44:54] [  LOG]  spotify: Scanned 4 of 5 saved playlists
[2024-09-03 20:44:55] [  LOG]  spotify: Scanned 5 of 5 saved playlists
[2024-09-03 20:44:55] [  LOG]  spotify: Spotify scan completed in 5 sec
[2024-09-03 20:44:56] [  LOG]      lib: Library init scan completed in 12 sec (271 changes)

[ejurgensen]

Yes, looks like Spotify has made a change, possibly deprecating the interface OwnTone was using. It looks like librespot is also affected (see their issue 1322), but that they have a fix in their dev branch. I will have to port that fix to OwnTone. If it's a major protocol change it might take some time, so I'm hoping Spotify at least temporarily rolls the change back. I imagine their change affects a lot more than just OwnTone.

[beaudett]

Playing tracks from spotify within Owntone is working again (without changing anything).

[ejurgensen]

Thanks for the update, that's good to hear. I guess they rolled back. The question is for how long. They never announced anything, and it was just one request in the old protocol that was broken, so I'm thinking it might actually have been a mistake on their side. Maybe being too optimistic :-)

I'll keep this issue open for a while, and also prioritize work on the new protocol.

[cmunro-godaddy]

Awesome! Thank you @ejurgensen & @beaudett

[beaudett]

I am sorry to say that the problem is back with the same errors in the log [2024-09-18 20:36:38] [ LOG] spotify: Error opening source: Cannot connect to access point, cooldown after disconnect is in effect

[ejurgensen]

Bummer, I would have hoped that they kept it working for longer. I will reopen.

[hacketiwack]

Do you guys listen to specific tracks? I can't reproduce the problem. Maybe I don't have the same version of Spotify from where I live.

[alesrosina]

For me it's also pretty wierd - sometimes i want to play sth from spotify - eg search works fine, stored playlists are shown, but when i click on a song, it doesnt do anything - also no entry in log. If I refresh web UI, it loads half of it, but with error in JS console:

Uncaught (in promise) 
Object { stack: "Me@http://owntone.local:3689/assets/index.js:21:30263
Xx</</d.onabort@http://owntone.local:3689/assets/index.js:23:6131
EventHandlerNonNull*Xx</<@http://owntone.local:3689/assets/index.js:23:6104
Xx<@http://owntone.local:3689/assets/index.js:23:5343
Gf@http://owntone.local:3689/assets/index.js:25:512
_request@http://owntone.local:3689/assets/index.js:26:1216
request@http://owntone.local:3689/assets/index.js:25:1879
vs.prototype[t]@http://owntone.local:3689/assets/index.js:26:1520
uy/<@http://owntone.local:3689/assets/index.js:21:24860
lastfm@http://owntone.local:3689/assets/index.js:46:147676
update_lastfm@http://owntone.local:3689/assets/index.js:46:185534
o@http://owntone.local:3689/assets/index.js:46:184092
EventListener.handleEvent*open_ws@http://owntone.local:3689/assets/index.js:46:184167
connect/<@http://owntone.local:3689/assets/index.js:46:183048
promise callback*connect@http://owntone.local:3689/assets/index.js:46:182932
created@http://owntone.local:3689/assets/index.js:46:182592
br@http://owntone.local:3689/assets/index.js:13:1352
zn@http://owntone.local:3689/assets/index.js:13:1417
sf@http://owntone.local:3689/assets/index.js:13:17721
d0@http://owntone.local:3689/assets/index.js:13:16996
Ng@http://owntone.local:3689/assets/index.js:13:57701
J0@http://owntone.local:3689/assets/index.js:13:57149
Lg@http://owntone.local:3689/assets/index.js:13:56785
X@http://owntone.local:3689/assets/index.js:13:35132
j@http://owntone.local:3689/assets/index.js:13:35016
_@http://owntone.local:3689/assets/index.js:13:31753
ae@http://owntone.local:3689/assets/index.js:13:40650
mount@http://owntone.local:3689/assets/index.js:13:20370
oy/t.mount@http://owntone.local:3689/assets/index.js:17:18457
@http://owntone.local:3689/assets/index.js:60:77078
", message: "Request aborted", name: "AxiosError", code: "ECONNABORTED", config: {…}, request: XMLHttpRequest }
6

And here's how UI looks like:

The only solution is to restart the server (since i'm running it with docker compose, i just restart it). Is there anything else where I can take a look (like logs or sth)? In owntone log file there's nothing.

[beaudett]

Do you guys listen to specific tracks? I can't reproduce the problem. Maybe I don't have the same version of Spotify from where I live.

The problem has reappeared when I tried to play a podcast through spotify. Then I tried with one of the tracks of the same album as two weeks ago and got the same error. I will test tonight with random spotify tracks and let you know. In case the location is important, I am living in France.

[ejurgensen]

I don't think there is any reason to test with specific tracks, it is more likely that it depends on the Spotify access point being used. When they roll out changes they deploy them gradually across access points. I am listening to Spotify right now with OwnTone, so there is one that works, but I can produce errors from others.

As I recall, OwnTone will try an access point, and if it fails try another one. If that fails too it will give up and you will see an error.

@alesrosina the errors you observe seem unrelated to this.

[alesrosina]

Do you guys listen to specific tracks? I can't reproduce the problem. Maybe I don't have the same version of Spotify from where I live.

Sometimes I do get an entry in log, eg:

spotify: Track not available for playback: 'Globi' - 'Italianità - Lied' (spotify:track:3aKQJ22gVqbSu3h09suSNu) (restrictions: { "reason": "market" })

But that's fine, this song is just not shown in UI and I cannot play it.

For me bigger issue is above mentioned error, which from my point of view suggest, that probably spotify implementation crashes and this is somehow not handeled in the code. But I cannot debug it.

[alesrosina]

@alesrosina the errors you observe seem unrelated to this.

I think it's related, since it's connected to spotify - and it also happens randomly. There are weeks that this works without issues and then there are some days, where this happens. And always only for spotify tracks.

So my guess here is, that there is some exception handling missing and spotify thing is crashing.

But if you think it's not related, i can open another issue.

[ejurgensen]

@alesrosina what does OwnTone's log say when it fails to start playback? If it says "Error opening source: Cannot connect to access point..." then it's related. If not, then please open another issue.

[ejurgensen]

@beaudett do you still experience this? It's been working fine for me the last few days.

I did start working on the new protocol, though.

[beaudett]

Hi @ejurgensen 4 days ago, the behavior was very random: some tracks were playing, some others weren't. Since then, it has been running just fine.

[ejurgensen]

Ok, I will close the issue for now, let's see for how long