Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Error opening source from spotify #1803

Closed
beaudett opened this issue Sep 3, 2024 · 17 comments
Closed

Error opening source from spotify #1803

beaudett opened this issue Sep 3, 2024 · 17 comments
Labels
bug priority High priority issue

Comments

@beaudett
Copy link

beaudett commented Sep 3, 2024

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.
Screenshot 2024-09-03 at 20 13 38
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
Copy link

theclive commented Sep 3, 2024 •
edited
Loading

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
Copy link
Member

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.

@ejurgensen ejurgensen added bug priority High priority issue labels Sep 3, 2024
ejurgensen added a commit that referenced this issue Sep 5, 2024
@ejurgensen
[docs] Add note to README about Spotify being broken
e823402 
Ref #1803
@beaudett
Copy link
Author

beaudett commented Sep 5, 2024

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

@ejurgensen
Copy link
Member

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
Copy link

Awesome! Thank you @ejurgensen & @beaudett

@beaudett
Copy link
Author

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
Copy link
Member

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

@ejurgensen ejurgensen reopened this Sep 19, 2024
@hacketiwack
Copy link
Collaborator

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
Copy link

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:
Screenshot from 2024-09-19 10-18-29

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
Copy link
Author

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
Copy link
Member

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
Copy link

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
Copy link

@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
Copy link
Member

@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
Copy link
Member

@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
Copy link
Author

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
Copy link
Member

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug priority High priority issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@ejurgensen @beaudett @alesrosina @hacketiwack @theclive @cmunro-godaddy