As of yesterday, I’ve started experiencing an issue with mopidy-spotify on all of my devices that prevents the initialization to be completed.
Even if I leave the program running for several hours, spotify will never finalize its initialization and therefore mopidy never starts.
I see several messages like these when running mopidy with -vvvv, might be related:
libspotify log message: 06:22:22.808 E [ap:4172] ChannelError(0, 1, playlist)
And then it forever hangs on the eventloop messages:
DEBUG 2017-08-16 08:32:17,610 [20314:SpotifyEventLoop] spotify.eventloop Waiting 0.066s for new events DEBUG 2017-08-16 08:32:17,676 [20314:SpotifyEventLoop] spotify.eventloop Timeout reached; processing events DEBUG 2017-08-16 08:32:17,677 [20314:SpotifyEventLoop] spotify.session Notify main thread
Has anything changed on Spotify side as far as you know? Everything worked fine until 2 days ago.
I do not see this issue, works as usual. When you say it “hangs forever”, you mean it’s just the last message you see, or it actually hangs? i.e. if you do a spotify search do you see that in the log?
When I say “hang forever” I mean that the last messages from the Spotify event loop (waiting for events - timeout - notify main thread) are repeated forever, and the actual mopidy main loop never starts - I get “connection refused” when I try to connect through any client.
This means that I can’t even perform a Spotify search on the server.
Please provide your full debug log.
Nothing stands out there. Can you disable all the other backends so it’s just Spotify?
Could you update to the latest version. You have Mopidy-Spotify-Web 0.2.0 which is from 2015.
I’ve updated to 0.3.0 but the problem remains.
Logs (with only spotify and spotify-web enabled): https://pastebin.com/FnLehkH2
Are you sure you require mopidy-spotify enabled for this problem to manifest?
It looks like you have a lot of tracks in the My Music collection which seems to be causing the problem. The last request doesn’t seem to get issued. If i had to guess I’d say the way this code is written it’s generating some very large lists, it’s not ideal. Or is might be being rate-limited by Spotify, although I’d expect to see a bunch of “retrying …” messages in that case. The spotipy retrying code used here needs work but it doesn’t look like that’s the issue as it’d throw a python exception. Is this the output from the console or the file produced from --save-debug-log?
Did the number of tracks in your My Music collection increase recently?
Spotipy has some tracing support, you could enable that to see more.
If I only enable mopidy-spotify everything seems to run quite smoothly, but once I enable mopidy-spotify-web as well it gets into that nasty loop.
I generated the logs through mopidy -vvvv > file 2>&1, shall I try with --save-debug-log as well?
I have actually a big collection, but no recent steep increase has occurred to justify this behaviour, unless I’m suddenly hitting some Spotify quota limits.
I’ll try to debug it more to understand if there are any weird big loops in mopidy-spotify-web that can cause this behaviour.
Thanks,
Fabio
Hmm I didn’t think they interacted at all.
No, that debug log method should get everything.
There’s no loop but there’s a fun bit of recursion that looks highly suspicious.
The issue is solved.
It seemed to be caused by the presence of two spurious playlists in my account - they had no name and no content, and the UI client was simply showing their name as “Loading…”. I could not remove them manually, nor open them, nor do any action on them.
After contacting the Spotify support I got them manually removed, and few minutes later mopidy started working again.
I confirm however that mopidy only hanged when mopidy-spotify-web was enabled, while it didn’t when only mopidy-spotify was on.
Debugging it a bit, it seems that the loop happened in the spotipy logic that populates the library (only mopidy-spotify-web uses spotipy afaik).
Taking a look at the logs I pasted a few days ago, you can see a sequence of spotipy traces that goes like:
DEBUG 2017-08-16 16:52:22,329 [785:SpotifyWebBackend-6] mopidy_spotify_web.library
Going to get spotify tracks, with limit 50 with offset 0
DEBUG 2017-08-16 16:52:22,791 [785:SpotifyWebBackend-6] mopidy_spotify_web.library
Going to get spotify tracks, with limit 50 with offset 50
DEBUG 2017-08-16 16:52:23,116 [785:SpotifyWebBackend-6] mopidy_spotify_web.library
Going to get spotify tracks, with limit 50 with offset 100
# [...]
DEBUG 2017-08-16 16:52:36,137 [785:SpotifyWebBackend-6] mopidy_spotify_web.library
Going to get spotify tracks, with limit 50 with offset 1300
DEBUG 2017-08-16 16:52:38,385 [785:SpotifyWebBackend-6] mopidy_spotify_web.library
Going to get spotify tracks, with limit 50 with offset 1350
DEBUG 2017-08-16 16:52:38,812 [785:SpotifyWebBackend-6] mopidy_spotify_web.library
Going to get spotify tracks, with limit 50 with offset 1400
# [...]
# No more events till logs terminated few minutes later on
DEBUG 2017-08-16 16:54:17,729 [785:SpotifyEventLoop] spotify.eventloop
Waiting 4.314s for new events
I haven’t investigated much what exactly happened inside of that loop to understand where things were getting stuck though.