Unhandled exception when playlist loading times out (MPD list command)

[ErraticFox]

Hello, I just reinstalled Arch today and it must be on my end because I just installed mopidy-spotify on my old installation about 5 days ago and it was working. As of now, everything looks fine and then it throws a bunch of errors. This is my output:

INFO     Starting Mopidy 2.0.1
INFO     Loading config from builtin defaults
INFO     Loading config from /home/fox/.config/mopidy/mopidy.conf
INFO     Loading config from command line options
INFO     Enabled extensions: spotify, mpd, http, stream, m3u, softwaremixer, file, local
INFO     Disabled extensions: none
INFO     Starting Mopidy mixer: SoftwareMixer
INFO     Starting Mopidy audio
INFO     Starting Mopidy backends: StreamBackend, M3UBackend, FileBackend, LocalBackend, SpotifyBackend
INFO     No local library metadata cache found at /home/fox/.local/share/mopidy/local/library.json.gz. Please run `mopidy local scan` to index your local music library. If you do not have a local music collection, you can disable the local backend to hide this message.
INFO     Loaded 0 local tracks using json
INFO     Audio output set to "autoaudiosink"
INFO     Starting Mopidy core
INFO     Logged in to Spotify in offline mode
INFO     Logged in to Spotify in online mode
INFO     Starting Mopidy frontends: MpdFrontend, HttpFrontend
INFO     MPD server running at [::]:6600
INFO     HTTP server running at [::ffff:127.0.0.1]:6680
INFO     Starting GLib mainloop
INFO     New MPD connection from [::1]:39242
INFO     New MPD connection from [::1]:39244
ERROR    SpotifyBackend backend caused an exception.
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/mopidy/core/library.py", line 19, in _backend_error_handling
    yield
  File "/usr/lib/python2.7/site-packages/mopidy/core/library.py", line 142, in get_distinct
    values = future.get()
  File "/usr/lib/python2.7/site-packages/pykka/future.py", line 299, in get
    exec('raise exc_info[0], exc_info[1], exc_info[2]')
  File "/usr/lib/python2.7/site-packages/pykka/actor.py", line 200, in _actor_loop
    response = self._handle_receive(message)
  File "/usr/lib/python2.7/site-packages/pykka/actor.py", line 294, in _handle_receive
    return callee(*message['args'], **message['kwargs'])
  File "/usr/lib/python2.7/site-packages/mopidy_spotify/library.py", line 32, in get_distinct
    field, query)
  File "/usr/lib/python2.7/site-packages/mopidy_spotify/distinct.py", line 20, in get_distinct
    config, session, requests_session, query)
  File "/usr/lib/python2.7/site-packages/mopidy_spotify/distinct.py", line 45, in _get_distinct_artists
    for track in _get_playlist_tracks(config, session)
  File "/usr/lib/python2.7/site-packages/mopidy_spotify/distinct.py", line 44, in <setcomp>
    artist.name
  File "/usr/lib/python2.7/site-packages/mopidy_spotify/distinct.py", line 119, in _get_playlist_tracks
    playlist.load()
  File "/usr/lib/python2.7/site-packages/spotify/playlist.py", line 118, in load
    return utils.load(self._session, self, timeout=timeout)
  File "/usr/lib/python2.7/site-packages/spotify/utils.py", line 246, in load
    raise spotify.Timeout(timeout)
Timeout: Operation did not complete in 10.000s

[ErraticFox]

Anyone? There's realatively the same errors with the soundcloud plugin as well...

[kingosticks]

Doesn't timeouts in multiple backends point to your network access being the issue. Are you using a proxy? A firewall maybe?

[ErraticFox]

Neither. This was like right after installing vanilla Arch. When it was working fine and flawlessly before, but that was with Antergos. This seems to only happen with certain playlists now. Also, my playlists used to be all using colors from my terminal (termite). Now they're all just gray with 'playlist' at the beginning i.e. my Starred playlist is now 'playlistStarred'

[kingosticks]

I don't understand what you mean when you talk about colours, if it's in the logs then that's a the responsibility of your terminal to get right. Otherwise it's the responsibility of whatever frontend you are using.

Anything special about these broken playlists? Many entries? Followed rather than your own?

[ErraticFox]

The only one that has tons of entries is my starred, which has 1,000+ songs edit: and my actual song library which is a lot higher. The reason I bring up colors with the playlist is because I feel like they're some how broken with Mopidy-Spotify because when the colors went away (this is for only the playlists list), the "playlistList" error was introduced.

[ErraticFox]

Alright, so I uninstalled and deleted the configs of ncmpcpp, mopidy, and mopidy-spotify then reinstalled them all. Colors and playlists are back (mind you without changing my terminal at all).

Though, number 4, show media library seems to be the culprit throwing the error I initally mentioned at the beginning. It continues to throw these errors and saying New MPD connection ... aswell. This also makes ncmpcpp timeout for a couple seconds.

[kingosticks]

Right, so you are using ncmpcpp. I should have asked which client you were using, I assumed it was the just the initial playlist loading on startup. I don't know what mpd commands 'show media library' does. I think a debug log showing what's going on is required.

[ErraticFox]

Debug log for what? Mopidy, Ncmpcpp, or MPD?

[spenserw]

Experiencing the same issue, haven't had time to look into it. Using ncmpcpp as well, fwiw. Not a clean install either, worked fine in the past.

[ErraticFox]

@spenserw I ended up uninstalling and reinstalling Mopidy, Mopidy-Spotify, and Ncmpcpp and it seemed to have fixed it.

[ErraticFox]

Reopened as you might still get the error. Please report back if it does fix it.

[spenserw]

@ErraticFox No, unfortunately didn't solve the issue for me.

[kingosticks]

A debug log for Mopidy.

[spenserw]

@kingosticks Can do. Let me know what else you might need.

In the following log, I connect via ncmpcpp. I then switch to the "Media Library" page, as Fox mentioned before. This is when the error occurs. Thanks for taking the time.
mopidy-log.txt

[kingosticks]

Can you confirm what system you are running on?

Has it ever worked for you? Have you tried to delete your Spotify cache files and then restart mopidy and wait a few minutes before trying to connect with ncmpcpp?

Do you have a particularly large number of playlists or any playlists with a large number of tracks?

[kingosticks]

Also, once you get the error, if you disconnect ncmpcpp and then reconnect, does it then work?

[mattnotmitt]

I'm getting this error as well. Whenever opening the media library tab, the SpotifyBackend backend caused an exception. error appears, exactly like Fox's above. I've wiped the my cache, restarted mopidy and waited 10 minutes before reconnecting. I have to force quit my terminal to "disconnect" ncmpcpp, and reconnecting gives the exact same error.

[kingosticks]

What system?

Do you have a particularly large number of playlists or any playlists with a large number of tracks?

[mattnotmitt]

Not particularly. I have 11 playlists, the max having 366 songs. My library has ~1100 songs.

[kingosticks]

Ok, thanks, what system are you using? Raspberrypi? Some other slow cpu?

[mattnotmitt]

CPU: Intel i5-6600K (4) @ 4.5GHz
Memory: 1964MB / 7906MB
Arch Linux
So no, not really!

[spenserw]

Same situation as @artemisbot, almost exactly the same specs.

[kingosticks]

Yeh, that blows that theory out the water.

Are you also using Arch Linux, @spenserw? We saw something weird with Arch before, I think it was a problem in the particular version of libc/pthreads in that case.

[mattnotmitt]

@kingosticks so was there any solution found for that problem?

[kingosticks]

Yes there was (mopidy/mopidy#933) but it sounds quite different to what you guys are seeing here. My point is only that problems with Arch's cutting edge versions are not unheard of.

Maybe we could try to get a trace level debug log (-vvvv) to see if pyspotify can tell us anything else?

[spenserw]

@kingosticks Yes, Arch as well.

[mattnotmitt]

This is my log from when I open the Media Library tab. Perhaps it's the ChannelError(s) causing the timeout?

[mattnotmitt]

I find it odd that I can only not look at the Media Library option, searching Spotify and playing from playlists work perfectly.

[kingosticks]

Channel errors are one of libspotify's great mysteries. You'll have seen that all code does is loop through all the tracks of all your playlists and pull out the artists. Nothing special. The same that happens when you load any playlist. I suppose you could try and load each one in turn manually in your client and see if that throws any errors. But sounds like you might have already tried that.

[geirawsm]

Just to chip in, I'm experiencing the same issue running Manjaro i3 (Linux manjaro-i3 4.8.17-1-MANJARO x86_64 GNU/Linux, ncmpcpp 0.7.7 and Mopidy 2.1.0).

Here's the traceback when I try to access Media Library

I can still search the spotify library as @artemisbot describes without issues.

I will be happy to test any patches you throw my way to see if this can be fixed.

[findus]

Hi, I tried to track down the problem and may have found something: The extension goes throufh all user playlists and fills the library with artists that are found in the playlist. One of my playlist was corrupt, eg. the Name of the Playlist was null/none. When the extension tries to call playlist.load() on a corrupted playlist an exception gets thrown. I tried to fix the problem by adding a null check in the method and it seems to work pretty fine, no more timeouts.

findus@75b7b17

[kingosticks]

Playlists without names are not necessarily corrupt, they may just not have finished loaded yet. if you are going to do this you probably want to skip those that have not finished loading rather than specifically checking for a valid name.

It might make more sense to just catch the timeout exception for each playlist, log it, then continue. But the problem with that is once you've waited for a couple of playlists to time out, your MPD client's connection will probably have timed out and your back to square one. So maybe we should specify a smaller timeout for these get_distinct loads?.

[kingosticks]

@f1ndus Out of interest which playlist is corrupt for you? If I change code slightly to get the index I can match that up with what at play.spotify.com and it corresponds to the Discover Weekly playlist.

def _get_playlist_tracks(config, session):
    if not config['allow_playlists']:
        return

    for i, playlist in enumerate(session.playlist_container):
        if not isinstance(playlist, spotify.Playlist):
            continue
        try:
            playlist.load()
        except spotify.Error:
            logger.error("Failed to load playlist %s (%d)", playlist.name, i)
            continue
        for track in playlist.tracks:
            try:
                track.load()
                yield track
            except spotify.Error:  # TODO Why did we get "General error"?
                continue

[findus]

Hi, yes it was the discover weekly playlist, I and for me it was the second playlist in the array. Also it is the only playlist which fails to load.

[adamcik]

From https://developer.spotify.com/technologies/libspotify/faq/

Playlist start to load data from Spotify servers as soon as the object (sp_playlist) representing the playlist is created in libspotify. Playlist objects can be created as a direct result of an API call or implicitly created because they are part of a playlistcontainer.

With this in mind might it be faster to call .load() on the container or do something like the following?

playlists = [p for p in session.playlist_container if isinstance(p, spotify.Playlist)]

for playlist in playlists:
    ...

My theory is that it might be better to queue up the fetches more in parallel instead of risking 10 sec. timeouts on each one. Of course testing such an optimization would be best, instead of just going on a hunch.

[adamcik]

With implicitly created because they are part of a playlistcontainer. in mind it might actually not make a difference, or only the load would be enough?

[kingosticks]

The exact same behaviour also occurs with the 'Release Radar' playlist (https://play.spotify.com/user/spotify/playlist/37i9dQZEVXbwCefoosMjb7). The problem goes away when I unfollow both 'Release Radar' and 'Discover weekly'. Spotify must have changed something in these special playlists which poor old libspotify just doesn't understand.

@adamcik: As soon as you login the playlistcontainer starts loading, as well as all the implicitly created playlists it contains, and even the tracks within those. All the loads have already been triggered, us calling .load() just enforces a time limit. Maybe we should look at sharing the timeout between all the playlists, similar to how _unwrap_stream works? Once it expires we just loop around and only collect tracks from those playlists that have finished loading by that point.

[TomasItu]

For me, it seems that any playlist that I followed that caused the issue, not just the Spotify ones. By unfollowing every playlist, I was able to get the library view to work.

[nic0machus]

Hello all,
Getting the same issue on Ubuntu 16.04 with ncmpcpp 0.7 and mopidy-spotify.
I have other issues as well, but this exception is thrown before ncmpcpp locks up.

[weidtn]

I also got this issue. I have no local files, only spotify. 39 Playlists, some even in folders. Some are my own, some are public ones. Im also using ncmpcpp on manjaro (thats close to Arch). All the get functions seem to timeout. ncmpcpp also shows "connected 127.0.0.1" and "timeout" for at least 5 minutes until my playlists show up. I changed the timeout in the config to 2 seconds, its still way too long.