Mopidy randomly fails to add Spotify tracks

General
1

We have mopidy running on a Pi which will run find for an hour then we start seeing drops when playing (just sudden drops in sound but carries on playing) then we struggle to queue up songs. If we reboot it will work fine with the same songs but then after a little while happens again. We’re on V2.2.3.

Here’s what we see in the logs.
Sep 23 11:42:30 spotmop mopidy[943]: INFO Failed to lookup “spotify:track:1OtuQOXXwUlVtANl1FeYZg”: Operation did not complete in 2.000s
Sep 23 11:42:32 spotmop mopidy[943]: INFO Failed to lookup “spotify:track:1KcZRMyC2tSs3CMIsng9wx”: Operation did not complete in 2.000s
Sep 23 11:42:34 spotmop mopidy[943]: INFO Failed to lookup “spotify:track:6HadZejJaG1KfJkXC4HAbv”: Operation did not complete in 2.000s
Sep 23 11:42:51 spotmop mopidy[943]: INFO Failed to lookup “spotify:track:1i7tKveM6Wo3dG31c5OwAL”: Operation did not complete in 2.000s
Sep 23 11:42:59 spotmop mopidy[943]: INFO Failed to lookup “spotify:track:1i7tKveM6Wo3dG31c5OwAL”: Operation did not complete in 2.000s
Sep 23 11:44:11 spotmop mopidy[943]: INFO Failed to lookup “spotify:track:1i7tKveM6Wo3dG31c5OwAL”: Operation did not complete in 2.000s

Any ideas what could be causing this?

2

Isn’t the default 5 seconds, does it still timeout when using the default value? This is more likely to be an Internet connection issue. How are you providing Internet connectivity, is it a USB WiFi dongle? Have you tried using an ethernet cable?

3

Sorry I should have said it happened with the default timeout, I increased it to 15 but that just caused it to hang so I changed it back down to 2 to time out quicker. It’s via ethernet and it’s 80 meg down FTTC for the broadband.

4

Can you provide your mopidy deps.

The reason I ask about the WiFi dongle is that some of them go into a low-power mode after a while and then take a while to start working again properly (if at all), after which a bunch of things have already failed. The Pi itself also has a similar mechanism, can you try changing that:

echo performance | sudo tee /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor

If you can run Mopidy with TRACE logging (mopidy -vvv) you might find something but I’m not hopefull about that since libspotify handles these lookups and it’s a black-box.

5

I ran the command you suggested. Not sure if this helps:

mopidy -vvv

/usr/local/lib/python2.7/dist-packages/mopidy/ext.py:202: PkgResourcesDeprecationWarning: Parameters to load are deprecated.  Call .resolve and .require separately.
  extension_class = entry_point.load(require=False)
INFO     2019-09-23 15:15:16,908 [1544:MainThread] mopidy.__main__
  Starting Mopidy 2.2.3
DEBUG    2019-09-23 15:15:16,926 [1544:MainThread] mopidy.ext
  Loading entry point: mpd = mopidy.mpd:Extension
DEBUG    2019-09-23 15:15:16,929 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-MPD 2.2.3
DEBUG    2019-09-23 15:15:16,929 [1544:MainThread] mopidy.ext
  Loading entry point: http = mopidy.http:Extension
DEBUG    2019-09-23 15:15:16,930 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-HTTP 2.2.3
DEBUG    2019-09-23 15:15:16,930 [1544:MainThread] mopidy.ext
  Loading entry point: stream = mopidy.stream:Extension
DEBUG    2019-09-23 15:15:16,931 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Stream 2.2.3
DEBUG    2019-09-23 15:15:16,931 [1544:MainThread] mopidy.ext
  Loading entry point: m3u = mopidy.m3u:Extension
DEBUG    2019-09-23 15:15:16,932 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-M3U 2.2.3
DEBUG    2019-09-23 15:15:16,932 [1544:MainThread] mopidy.ext
  Loading entry point: softwaremixer = mopidy.softwaremixer:Extension
DEBUG    2019-09-23 15:15:16,934 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-SoftwareMixer 2.2.3
DEBUG    2019-09-23 15:15:16,934 [1544:MainThread] mopidy.ext
  Loading entry point: file = mopidy.file:Extension
DEBUG    2019-09-23 15:15:16,935 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-File 2.2.3
DEBUG    2019-09-23 15:15:16,935 [1544:MainThread] mopidy.ext
  Loading entry point: local = mopidy.local:Extension
DEBUG    2019-09-23 15:15:16,942 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Local 2.2.3
DEBUG    2019-09-23 15:15:16,943 [1544:MainThread] mopidy.ext
  Loading entry point: tunein = mopidy_tunein:Extension
DEBUG    2019-09-23 15:15:16,944 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-TuneIn 0.4.1
DEBUG    2019-09-23 15:15:16,945 [1544:MainThread] mopidy.ext
  Loading entry point: mixcloud = mopidy_mixcloud:Extension
DEBUG    2019-09-23 15:15:16,946 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Mixcloud 3.1.4
DEBUG    2019-09-23 15:15:16,947 [1544:MainThread] mopidy.ext
  Loading entry point: local-images = mopidy_local_images:Extension
DEBUG    2019-09-23 15:15:16,948 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Local-Images 1.0.0
DEBUG    2019-09-23 15:15:16,949 [1544:MainThread] mopidy.ext
  Loading entry point: iris = mopidy_iris:Extension
DEBUG    2019-09-23 15:15:17,903 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Iris 3.40.0
DEBUG    2019-09-23 15:15:17,906 [1544:MainThread] mopidy.ext
  Loading entry point: spotify = mopidy_spotify:Extension
DEBUG    2019-09-23 15:15:17,909 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Spotify 3.1.0
DEBUG    2019-09-23 15:15:17,909 [1544:MainThread] mopidy.ext
  Loading entry point: soundcloud = mopidy_soundcloud:SoundCloudExtension
DEBUG    2019-09-23 15:15:17,911 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-SoundCloud 2.1.0
DEBUG    2019-09-23 15:15:17,911 [1544:MainThread] mopidy.ext
  Loading entry point: podcast = mopidy_podcast:Extension
DEBUG    2019-09-23 15:15:17,913 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Podcast 2.0.3
DEBUG    2019-09-23 15:15:17,917 [1544:MainThread] mopidy.ext
  Discovered extensions: mpd, http, stream, m3u, softwaremixer, file, local, tunein, mixcloud, local-images, iris, spotify, soundcloud, podcast
DEBUG    2019-09-23 15:15:17,924 [1544:MainThread] mopidy.config.keyring
  Fetching passwords from your keyring failed. Any passwords stored in the keyring will not be available. (org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11)
INFO     2019-09-23 15:15:17,924 [1544:MainThread] mopidy.config
  Loading config from builtin defaults
DEBUG    2019-09-23 15:15:17,937 [1544:MainThread] mopidy.config
  Loading config from /etc/xdg/mopidy/mopidy.conf failed; it does not exist
INFO     2019-09-23 15:15:17,941 [1544:MainThread] mopidy.config
  Loading config from /root/.config/mopidy/mopidy.conf
INFO     2019-09-23 15:15:17,948 [1544:MainThread] mopidy.config
  Loading config from command line options
DEBUG    2019-09-23 15:15:17,967 [1544:MainThread] mopidy.ext
  Validating extension: mpd
DEBUG    2019-09-23 15:15:18,259 [1544:MainThread] mopidy.ext
  Validating extension: http
DEBUG    2019-09-23 15:15:18,268 [1544:MainThread] mopidy.ext
  Validating extension: stream
DEBUG    2019-09-23 15:15:18,277 [1544:MainThread] mopidy.ext
  Validating extension: m3u
DEBUG    2019-09-23 15:15:18,287 [1544:MainThread] mopidy.ext
  Validating extension: softwaremixer
DEBUG    2019-09-23 15:15:18,296 [1544:MainThread] mopidy.ext
  Validating extension: file
DEBUG    2019-09-23 15:15:18,306 [1544:MainThread] mopidy.ext
  Validating extension: local
DEBUG    2019-09-23 15:15:18,315 [1544:MainThread] mopidy.ext
  Validating extension: tunein
DEBUG    2019-09-23 15:15:18,339 [1544:MainThread] mopidy.ext
  Validating extension: mixcloud
DEBUG    2019-09-23 15:15:18,358 [1544:MainThread] mopidy.ext
  Validating extension: local-images
DEBUG    2019-09-23 15:15:18,393 [1544:MainThread] mopidy.ext
  Validating extension: iris
DEBUG    2019-09-23 15:15:18,432 [1544:MainThread] mopidy.ext
  Validating extension: spotify
DEBUG    2019-09-23 15:15:18,459 [1544:MainThread] mopidy.ext
  Validating extension: soundcloud
DEBUG    2019-09-23 15:15:18,461 [1544:MainThread] mopidy.ext
  Validating extension: podcast
INFO     2019-09-23 15:15:18,462 [1544:MainThread] mopidy.__main__
  Enabled extensions: iris, mpd, http, stream, mixcloud, m3u, softwaremixer, file, local-images, podcast, tunein
INFO     2019-09-23 15:15:18,463 [1544:MainThread] mopidy.__main__
  Disabled extensions: spotify, local, soundcloud
WARNING  2019-09-23 15:15:18,463 [1544:MainThread] mopidy.__main__
  Found local configuration errors, the extension has been automatically disabled:
WARNING  2019-09-23 15:15:18,464 [1544:MainThread] mopidy.__main__
    local/media_dir must be set.
WARNING  2019-09-23 15:15:18,465 [1544:MainThread] mopidy.__main__
  Found soundcloud configuration errors, the extension has been automatically disabled:
WARNING  2019-09-23 15:15:18,465 [1544:MainThread] mopidy.__main__
    soundcloud/auth_token must be set.
WARNING  2019-09-23 15:15:18,466 [1544:MainThread] mopidy.__main__
  Found spotify configuration errors, the extension has been automatically disabled:
WARNING  2019-09-23 15:15:18,466 [1544:MainThread] mopidy.__main__
    spotify/username must be set.
WARNING  2019-09-23 15:15:18,467 [1544:MainThread] mopidy.__main__
    spotify/client_secret must be set.
WARNING  2019-09-23 15:15:18,467 [1544:MainThread] mopidy.__main__
    spotify/password must be set.
WARNING  2019-09-23 15:15:18,468 [1544:MainThread] mopidy.__main__
    spotify/client_id must be set.
WARNING  2019-09-23 15:15:18,468 [1544:MainThread] mopidy.__main__
  Please fix the extension configuration errors or disable the extensions to silence these messages.
DEBUG    2019-09-23 15:15:18,587 [1544:MainThread] mopidy.commands
  Available Mopidy mixers: SoftwareMixer
INFO     2019-09-23 15:15:18,589 [1544:MainThread] mopidy.commands
  Starting Mopidy mixer: SoftwareMixer
DEBUG    2019-09-23 15:15:18,591 [1544:MainThread] pykka
  Registered SoftwareMixer (urn:uuid:fc2ceecb-858e-46e5-9233-9b828c8c54f3)
DEBUG    2019-09-23 15:15:18,591 [1544:MainThread] pykka
  Starting SoftwareMixer (urn:uuid:fc2ceecb-858e-46e5-9233-9b828c8c54f3)
DEBUG    2019-09-23 15:15:18,597 [1544:MainThread] mopidy.commands
  Mixer volume left unchanged
INFO     2019-09-23 15:15:18,598 [1544:MainThread] mopidy.commands
  Starting Mopidy audio
DEBUG    2019-09-23 15:15:18,599 [1544:MainThread] pykka
  Registered Audio (urn:uuid:fe8a0c1d-dc56-4a29-9927-6cec484f2390)
DEBUG    2019-09-23 15:15:18,600 [1544:MainThread] pykka
  Starting Audio (urn:uuid:fe8a0c1d-dc56-4a29-9927-6cec484f2390)
INFO     2019-09-23 15:15:18,606 [1544:MainThread] mopidy.commands
  Starting Mopidy backends: StreamBackend, M3UBackend, FileBackend, TuneInBackend, MopidyMixcloud, PodcastBackend
INFO     2019-09-23 15:15:18,631 [1544:Audio-2] mopidy.audio.actor
  Audio output set to "autoaudiosink"
DEBUG    2019-09-23 15:15:18,633 [1544:MainThread] pykka
  Registered StreamBackend (urn:uuid:a0a6c247-1e0e-4ab0-9d36-1b2a2a197279)
DEBUG    2019-09-23 15:15:18,634 [1544:MainThread] pykka
  Starting StreamBackend (urn:uuid:a0a6c247-1e0e-4ab0-9d36-1b2a2a197279)
INFO     2019-09-23 15:15:18,668 [1544:MainThread] mopidy.internal.path
  Creating dir /root/.local/share/mopidy/m3u
DEBUG    2019-09-23 15:15:18,669 [1544:MainThread] pykka
  Registered M3UBackend (urn:uuid:98419d57-16fe-40a3-9b29-e8afb39c6e54)
DEBUG    2019-09-23 15:15:18,669 [1544:MainThread] pykka
  Starting M3UBackend (urn:uuid:98419d57-16fe-40a3-9b29-e8afb39c6e54)
DEBUG    2019-09-23 15:15:18,675 [1544:MainThread] mopidy.file.library
  Failed expanding path ($XDG_MUSIC_DIR) from file/media_dirs config value.
DEBUG    2019-09-23 15:15:18,676 [1544:MainThread] pykka
  Registered FileBackend (urn:uuid:2b507e7c-1142-44e0-8170-27b12db77309)
DEBUG    2019-09-23 15:15:18,677 [1544:MainThread] pykka
  Starting FileBackend (urn:uuid:2b507e7c-1142-44e0-8170-27b12db77309)
DEBUG    2019-09-23 15:15:18,694 [1544:MainThread] pykka
  Registered TuneInBackend (urn:uuid:aa085147-b3c6-4855-98b9-2fbb516f3e33)
DEBUG    2019-09-23 15:15:18,695 [1544:MainThread] pykka
  Starting TuneInBackend (urn:uuid:aa085147-b3c6-4855-98b9-2fbb516f3e33)
DEBUG    2019-09-23 15:15:18,712 [1544:MainThread] pykka
  Registered MopidyMixcloud (urn:uuid:a4f089ac-1a91-49a7-b65a-9639d8a52a5c)
DEBUG    2019-09-23 15:15:18,713 [1544:MainThread] pykka
  Starting MopidyMixcloud (urn:uuid:a4f089ac-1a91-49a7-b65a-9639d8a52a5c)
INFO     2019-09-23 15:15:18,732 [1544:MainThread] mopidy.internal.path
  Creating dir /root/.config/mopidy/podcast
DEBUG    2019-09-23 15:15:18,733 [1544:MainThread] pykka
  Registered PodcastBackend (urn:uuid:bad7c86a-1f31-4e1c-8c66-37d0404fc6f8)
DEBUG    2019-09-23 15:15:18,733 [1544:MainThread] pykka
  Starting PodcastBackend (urn:uuid:bad7c86a-1f31-4e1c-8c66-37d0404fc6f8)
INFO     2019-09-23 15:15:18,758 [1544:MainThread] mopidy.commands
  Starting Mopidy core
DEBUG    2019-09-23 15:15:18,775 [1544:MainThread] pykka
  Registered Core (urn:uuid:655b7aab-e6a5-4d82-b62b-9c2923e6a203)
DEBUG    2019-09-23 15:15:18,776 [1544:MainThread] pykka
  Starting Core (urn:uuid:655b7aab-e6a5-4d82-b62b-9c2923e6a203)
INFO     2019-09-23 15:15:18,804 [1544:MainThread] mopidy.commands
  Starting Mopidy frontends: MpdFrontend, HttpFrontend, IrisFrontend
ERROR    2019-09-23 15:15:18,807 [1544:MainThread] mopidy.commands
  Frontend (MpdFrontend) initialization error: MPD server startup failed: [Errno 98] Address already in use
DEBUG    2019-09-23 15:15:18,814 [1544:MainThread] mopidy.http.actor
  Starting HTTP server
ERROR    2019-09-23 15:15:18,815 [1544:MainThread] mopidy.commands
  Frontend (HttpFrontend) initialization error: HTTP server startup failed: [Errno 98] Address already in use
DEBUG    2019-09-23 15:15:18,816 [1544:MainThread] pykka
  Registered IrisFrontend (urn:uuid:4f96ad9e-de32-47e3-9630-e4d07d6115fa)
DEBUG    2019-09-23 15:15:18,817 [1544:MainThread] pykka
  Starting IrisFrontend (urn:uuid:4f96ad9e-de32-47e3-9630-e4d07d6115fa)
INFO     2019-09-23 15:15:18,818 [1544:IrisFrontend-10] mopidy_iris.core
  Starting Iris 3.40.0
INFO     2019-09-23 15:15:18,819 [1544:MainThread] mopidy.commands
 Starting GLib mainloop
 mopidy -vvv
/usr/local/lib/python2.7/dist-packages/mopidy/ext.py:202: PkgResourcesDeprecationWarning: Parameters to load are deprecated.  Call .resolve and .require separately.
  extension_class = entry_point.load(require=False)
INFO     2019-09-23 15:15:16,908 [1544:MainThread] mopidy.__main__
  Starting Mopidy 2.2.3
DEBUG    2019-09-23 15:15:16,926 [1544:MainThread] mopidy.ext
  Loading entry point: mpd = mopidy.mpd:Extension
DEBUG    2019-09-23 15:15:16,929 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-MPD 2.2.3
DEBUG    2019-09-23 15:15:16,929 [1544:MainThread] mopidy.ext
  Loading entry point: http = mopidy.http:Extension
DEBUG    2019-09-23 15:15:16,930 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-HTTP 2.2.3
DEBUG    2019-09-23 15:15:16,930 [1544:MainThread] mopidy.ext
  Loading entry point: stream = mopidy.stream:Extension
DEBUG    2019-09-23 15:15:16,931 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Stream 2.2.3
DEBUG    2019-09-23 15:15:16,931 [1544:MainThread] mopidy.ext
  Loading entry point: m3u = mopidy.m3u:Extension
DEBUG    2019-09-23 15:15:16,932 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-M3U 2.2.3
DEBUG    2019-09-23 15:15:16,932 [1544:MainThread] mopidy.ext
  Loading entry point: softwaremixer = mopidy.softwaremixer:Extension
DEBUG    2019-09-23 15:15:16,934 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-SoftwareMixer 2.2.3
DEBUG    2019-09-23 15:15:16,934 [1544:MainThread] mopidy.ext
  Loading entry point: file = mopidy.file:Extension
DEBUG    2019-09-23 15:15:16,935 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-File 2.2.3
DEBUG    2019-09-23 15:15:16,935 [1544:MainThread] mopidy.ext
  Loading entry point: local = mopidy.local:Extension
DEBUG    2019-09-23 15:15:16,942 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Local 2.2.3
DEBUG    2019-09-23 15:15:16,943 [1544:MainThread] mopidy.ext
  Loading entry point: tunein = mopidy_tunein:Extension
DEBUG    2019-09-23 15:15:16,944 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-TuneIn 0.4.1
DEBUG    2019-09-23 15:15:16,945 [1544:MainThread] mopidy.ext
  Loading entry point: mixcloud = mopidy_mixcloud:Extension
DEBUG    2019-09-23 15:15:16,946 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Mixcloud 3.1.4
DEBUG    2019-09-23 15:15:16,947 [1544:MainThread] mopidy.ext
  Loading entry point: local-images = mopidy_local_images:Extension
DEBUG    2019-09-23 15:15:16,948 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Local-Images 1.0.0
DEBUG    2019-09-23 15:15:16,949 [1544:MainThread] mopidy.ext
  Loading entry point: iris = mopidy_iris:Extension
DEBUG    2019-09-23 15:15:17,903 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Iris 3.40.0
DEBUG    2019-09-23 15:15:17,906 [1544:MainThread] mopidy.ext
  Loading entry point: spotify = mopidy_spotify:Extension
DEBUG    2019-09-23 15:15:17,909 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Spotify 3.1.0
DEBUG    2019-09-23 15:15:17,909 [1544:MainThread] mopidy.ext
  Loading entry point: soundcloud = mopidy_soundcloud:SoundCloudExtension
DEBUG    2019-09-23 15:15:17,911 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-SoundCloud 2.1.0
DEBUG    2019-09-23 15:15:17,911 [1544:MainThread] mopidy.ext
  Loading entry point: podcast = mopidy_podcast:Extension
DEBUG    2019-09-23 15:15:17,913 [1544:MainThread] mopidy.ext
  Loaded extension: Mopidy-Podcast 2.0.3
DEBUG    2019-09-23 15:15:17,917 [1544:MainThread] mopidy.ext
  Discovered extensions: mpd, http, stream, m3u, softwaremixer, file, local, tunein, mixcloud, local-images, iris, spotify, soundcloud, podcast
DEBUG    2019-09-23 15:15:17,924 [1544:MainThread] mopidy.config.keyring
  Fetching passwords from your keyring failed. Any passwords stored in the keyring will not be available. (org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11)
INFO     2019-09-23 15:15:17,924 [1544:MainThread] mopidy.config
  Loading config from builtin defaults
DEBUG    2019-09-23 15:15:17,937 [1544:MainThread] mopidy.config
6

Sorry, I should have said you would need to reproduce the failure with the debug logging. So that would involve copying the config over to /root/.config/mopidy/mopidy.conf, stopping any other running instance of Mopidy (i.e. the service) and then leaving it running for an hour or so until the lookups start to fail like usual.

7

This happened when I was trying to queue some tracks. It said queued but nothing in the queue. These tracks have worked previously:

INFO     2019-09-24 11:12:19,495 [1512:SpotifyBackend-9] mopidy_spotify.lookup
  Failed to lookup "spotify:track:6sqTapK2MJhUSrbW6MniB8": Operation did not complete in 2.000s
DEBUG    2019-09-24 11:12:19,496 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,498 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,500 [1512:HttpServer] mopidy.http.handlers
  Sent WebSocket message to 192.168.25.182: '{"jsonrpc": "2.0", "id": 42, "result": []}'
DEBUG    2019-09-24 11:12:19,502 [1512:HttpServer] mopidy.http.handlers
  Received WebSocket message from 192.168.25.30: u'{"method":"core.playback.get_time_position","params":{},"jsonrpc":"2.0","id":36344}'
DEBUG    2019-09-24 11:12:19,503 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,507 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,508 [1512:HttpServer] mopidy.http.handlers
  Sent WebSocket message to 192.168.25.30: '{"jsonrpc": "2.0", "id": 36344, "result": 31990}'
DEBUG    2019-09-24 11:12:19,510 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,511 [1512:HttpServer] mopidy.http.handlers
  Received WebSocket message from 192.168.25.76: u'{"method":"core.playback.get_time_position","params":{},"jsonrpc":"2.0","id":46686}'
DEBUG    2019-09-24 11:12:19,515 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,519 [1512:HttpServer] mopidy.http.handlers
  Sent WebSocket message to 192.168.25.76: '{"jsonrpc": "2.0", "id": 46686, "result": 32000}'
DEBUG    2019-09-24 11:12:19,520 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,522 [1512:HttpServer] mopidy_iris.handlers
  Iris websocket message received: {"jsonrpc":"2.0","id":15693199351094,"method":"broadcast","params":{"method":"notification","params":{"notification":{"content":"safetynet1 is adding 1 URIs to queue","icon":null}}}}
DEBUG    2019-09-24 11:12:19,525 [1512:HttpServer] mopidy_iris.core
  {u'params': {u'notification': {u'content': u'safetynet1 is adding 1 URIs to queue', u'icon': None}}, u'method': u'notification', u'connection_id': u'asotioydcbzo'}
DEBUG    2019-09-24 11:12:19,526 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,528 [1512:HttpServer] mopidy_iris.core
  {u'result': {u'message': u'Broadcast to 3 connections'}, u'recipient': u'asotioydcbzo', u'jsonrpc': u'2.0', u'id': 15693199351094L, u'method': u'broadcast'}
DEBUG    2019-09-24 11:12:19,532 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,534 [1512:HttpServer] mopidy.http.handlers
  Received WebSocket message from 192.168.25.182: u'{"method":"core.playback.get_time_position","params":{},"jsonrpc":"2.0","id":43}'
DEBUG    2019-09-24 11:12:19,537 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,541 [1512:HttpServer] mopidy.http.handlers
  Sent WebSocket message to 192.168.25.182: '{"jsonrpc": "2.0", "id": 43, "result": 32024}'
DEBUG    2019-09-24 11:12:19,544 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,546 [1512:HttpServer] mopidy_iris.handlers
  Iris websocket message received: {"jsonrpc":"2.0","id":156931993749415,"method":"add_queue_metadata","params":{"tlids":[],"added_from":"spotify:album:0z0JtBRlABbJfRKOICEn4m","added_by":"safetynet1"}}
DEBUG    2019-09-24 11:12:19,549 [1512:HttpServer] mopidy_iris.core
  {u'params': {u'queue_metadata': {u'tlid_4': {u'tlid': 4, u'added_by': u'safetynet1', u'added_from': u'spotify:album:0z0JtBRlABbJfRKOICEn4m'}}}, u'method': u'queue_metadata_changed'}
DEBUG    2019-09-24 11:12:19,550 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,553 [1512:HttpServer] mopidy_iris.core
  {u'result': {u'message': u'Added queue metadata'}, u'recipient': u'asotioydcbzo', u'jsonrpc': u'2.0', u'id': 156931993749415L, u'method': u'add_queue_metadata'}
DEBUG    2019-09-24 11:12:19,555 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,557 [1512:HttpServer] mopidy_iris.handlers
  Iris websocket message received: {"jsonrpc":"2.0","id":156931993950741,"method":"add_queue_metadata","params":{"tlids":[],"added_from":"spotify:album:0z0JtBRlABbJfRKOICEn4m","added_by":"safetynet1"}}
DEBUG    2019-09-24 11:12:19,560 [1512:HttpServer] mopidy_iris.core
  {u'params': {u'queue_metadata': {u'tlid_4': {u'tlid': 4, u'added_by': u'safetynet1', u'added_from': u'spotify:album:0z0JtBRlABbJfRKOICEn4m'}}}, u'method': u'queue_metadata_changed'}
DEBUG    2019-09-24 11:12:19,562 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:19,564 [1512:HttpServer] mopidy_iris.core
  {u'result': {u'message': u'Added queue metadata'}, u'recipient': u'asotioydcbzo', u'jsonrpc': u'2.0', u'id': 156931993950741L, u'method': u'add_queue_metadata'}
8

I now the sound is dropping and this is in the log:

TRACE    2019-09-24 11:25:10,992 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
DEBUG    2019-09-24 11:25:10,993 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
TRACE    2019-09-24 11:25:10,994 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
TRACE    2019-09-24 11:25:10,996 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
DEBUG    2019-09-24 11:25:10,997 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
TRACE    2019-09-24 11:25:10,998 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
TRACE    2019-09-24 11:25:11,000 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
DEBUG    2019-09-24 11:25:11,001 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
TRACE    2019-09-24 11:25:11,002 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
TRACE    2019-09-24 11:25:11,005 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
DEBUG    2019-09-24 11:25:11,005 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
TRACE    2019-09-24 11:25:11,007 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
TRACE    2019-09-24 11:25:11,009 [1512:Dummy-24] mopidy_spotify.playback
  Audio requested more data (hint=0); accepting deliveries
DEBUG    2019-09-24 11:25:11,010 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
9

Sorry and now this

TRACE 2019-09-24 11:29:29,985 [1512:Audio-2] mopidy_spotify.playback
Audio has enough data; rejecting deliveries

10

After that last one does the audio starting working again?

11

It’s hard to tell. The track carries on playing and then the audio drops but seconds later it will come back for 5 seconds and gone again. It’s in and out. I move it back 5 seconds when the audio drops it plays fine again for a few more seconds.

12

I have a very remote possible explanation for this but I need to be able to reproduce this first. What model Pi are you running on, what version of Raspbian, and can you provide the output of mopidy deps ? The minute or so before it "Failed to lookup “spotify:track:6sqTapK2MJhUSrbW6MniB8” from the first log might also be useful.

Were you able to try changing the scaling_governor setting ?

13

Here you go, hope this helps:

It’s a Pi 3 model B

PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
ID=raspbian
ID_LIKE=debian

mopidy deps

/usr/local/lib/python2.7/dist-packages/mopidy/ext.py:202: PkgResourcesDeprecationWarning: Parameters to load are deprecated.  Call .resolve and .require separately.
  extension_class = entry_point.load(require=False)
Executable: /usr/local/bin/mopidy
Platform: Linux-4.14.98-v7+-armv7l-with-debian-9.8
Python: CPython 2.7.13 from /usr/lib/python2.7
Mopidy: 2.2.3 from /usr/local/lib/python2.7/dist-packages
  requests>=2.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
    idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
    chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
    certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
    urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
  setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
  Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
  tornado<5,>=4.4: 4.5.3 from /usr/local/lib/python2.7/dist-packages
    singledispatch: 3.4.0.3 from /usr/local/lib/python2.7/dist-packages
      six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
    certifi: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
    backports-abc>=0.4: 0.5 from /usr/local/lib/python2.7/dist-packages
Mopidy-Iris: 3.40.0 from /usr/local/lib/python2.7/dist-packages
  tornado<5.0,>=3.2: 4.5.3 from /usr/local/lib/python2.7/dist-packages
    singledispatch: 3.4.0.3 from /usr/local/lib/python2.7/dist-packages
      six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
    certifi: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
    backports-abc>=0.4: 0.5 from /usr/local/lib/python2.7/dist-packages
  setuptools>=3.3: 41.2.0 from /usr/local/lib/python2.7/dist-packages
  ConfigObj>=5.0.6: 5.0.6 from /usr/local/lib/python2.7/dist-packages
    six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
  requests>=2.0.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
    idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
    chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
    certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
    urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
  Mopidy>=2.0: 2.2.3 from /usr/local/lib/python2.7/dist-packages
    requests>=2.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
      idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
      chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
      certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
    setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
    tornado<5,>=4.4: 4.5.3 from /usr/local/lib/python2.7/dist-packages
      singledispatch: 3.4.0.3 from /usr/local/lib/python2.7/dist-packages
        six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
      certifi: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      backports-abc>=0.4: 0.5 from /usr/local/lib/python2.7/dist-packages
  Mopidy-Local-Images>=1.0: 1.0.0 from /usr/local/lib/python2.7/dist-packages
    Mopidy>=1.1: 2.2.3 from /usr/local/lib/python2.7/dist-packages
      requests>=2.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
        idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
        chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
        certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
        urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
      setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
      Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
      tornado<5,>=4.4: 4.5.3 from /usr/local/lib/python2.7/dist-packages
        singledispatch: 3.4.0.3 from /usr/local/lib/python2.7/dist-packages
          six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
        certifi: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
        backports-abc>=0.4: 0.5 from /usr/local/lib/python2.7/dist-packages
    setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
    uritools>=1.0: 2.2.0 from /usr/local/lib/python2.7/dist-packages
      ipaddress; python_version == "2.7": 1.0.22 from /usr/local/lib/python2.7/dist-packages
Mopidy-SoundCloud: 2.1.0 from /usr/lib/python2.7/dist-packages
Mopidy-TuneIn: 0.4.1 from /usr/local/lib/python2.7/dist-packages
  Mopidy>=1.1: 2.2.3 from /usr/local/lib/python2.7/dist-packages
    requests>=2.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
      idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
      chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
      certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
    setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
    tornado<5,>=4.4: 4.5.3 from /usr/local/lib/python2.7/dist-packages
      singledispatch: 3.4.0.3 from /usr/local/lib/python2.7/dist-packages
        six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
      certifi: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      backports-abc>=0.4: 0.5 from /usr/local/lib/python2.7/dist-packages
  setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
  requests>=2.0.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
    idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
    chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
    certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
    urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
  Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
Mopidy-Local-Images: 1.0.0 from /usr/local/lib/python2.7/dist-packages
  Mopidy>=1.1: 2.2.3 from /usr/local/lib/python2.7/dist-packages
    requests>=2.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
      idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
      chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
      certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
    setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
    tornado<5,>=4.4: 4.5.3 from /usr/local/lib/python2.7/dist-packages
      singledispatch: 3.4.0.3 from /usr/local/lib/python2.7/dist-packages
        six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
      certifi: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      backports-abc>=0.4: 0.5 from /usr/local/lib/python2.7/dist-packages
  setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
  Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
  uritools>=1.0: 2.2.0 from /usr/local/lib/python2.7/dist-packages
    ipaddress; python_version == "2.7": 1.0.22 from /usr/local/lib/python2.7/dist-packages
Mopidy-Spotify: 3.1.0 from /usr/lib/python2.7/dist-packages
  Mopidy>=2.0: 2.2.3 from /usr/local/lib/python2.7/dist-packages
    requests>=2.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
      idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
      chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
      certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
    setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
    tornado<5,>=4.4: 4.5.3 from /usr/local/lib/python2.7/dist-packages
      singledispatch: 3.4.0.3 from /usr/local/lib/python2.7/dist-packages
        six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
      certifi: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      backports-abc>=0.4: 0.5 from /usr/local/lib/python2.7/dist-packages
  Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
  pyspotify>=2.0.5: 2.0.5 from /usr/lib/python2.7/dist-packages
    cffi>=1.0.0: 1.9.1 from /usr/lib/python2.7/dist-packages
  requests>=2.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
    idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
    chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
    certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
    urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
Mopidy-Podcast: 2.0.3 from /usr/lib/python2.7/dist-packages
Mopidy-Mixcloud: 3.1.4 from /usr/local/lib/python2.7/dist-packages
  Mopidy>=1.0: 2.2.3 from /usr/local/lib/python2.7/dist-packages
    requests>=2.0: 2.22.0 from /usr/local/lib/python2.7/dist-packages
      idna<2.9,>=2.5: 2.8 from /usr/local/lib/python2.7/dist-packages
      chardet<3.1.0,>=3.0.2: 3.0.4 from /usr/local/lib/python2.7/dist-packages
      certifi>=2017.4.17: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      urllib3!=1.25.0,!=1.25.1,<1.26,>=1.21.1: 1.25.3 from /usr/local/lib/python2.7/dist-packages
    setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
    tornado<5,>=4.4: 4.5.3 from /usr/local/lib/python2.7/dist-packages
      singledispatch: 3.4.0.3 from /usr/local/lib/python2.7/dist-packages
        six: 1.12.0 from /usr/local/lib/python2.7/dist-packages
      certifi: 2019.6.16 from /usr/local/lib/python2.7/dist-packages
      backports-abc>=0.4: 0.5 from /usr/local/lib/python2.7/dist-packages
  setuptools: 41.2.0 from /usr/local/lib/python2.7/dist-packages
  Pykka>=1.1: 2.0.0 from /usr/local/lib/python2.7/dist-packages
GStreamer: 1.10.4.0 from /usr/lib/python2.7/dist-packages/gi
  Detailed information:
    Python wrapper: python-gi 3.22.0
    Relevant elements:
      Found:
        uridecodebin
        souphttpsrc
        appsrc
        alsasink
        osssink
        oss4sink
        pulsesink
        id3demux
        id3v2mux
        lamemp3enc
        mad
        mpegaudioparse
        mpg123audiodec
        vorbisdec
        vorbisenc
        vorbisparse
        oggdemux
        oggmux
        oggparse
        flacdec
        flacparse
        shout2send
      Not found:
        flump3dec

scaling_governor

echo performance | sudo tee /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
performance

Before the failed lookups

DEBUG    2019-09-24 11:12:18,119 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,122 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,125 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,127 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,131 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,132 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,133 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,135 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,259 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,260 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,262 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,263 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,264 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,265 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,465 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,467 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,468 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,469 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,470 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,472 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,659 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,661 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,662 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,663 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,664 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,665 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,703 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,705 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,708 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,710 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,711 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,713 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,715 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,717 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,719 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,720 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,722 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,724 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,726 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,728 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,730 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,732 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,733 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,735 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,737 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,739 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,740 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,859 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,860 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,861 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,864 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,866 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,869 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,871 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,874 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,876 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,879 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,881 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,884 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,886 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,889 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,892 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,895 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,897 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,900 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,902 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,905 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,907 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,910 [1512:Dummy-13] spotify.session
  Music delivery of 2048 frames, 2048 consumed
DEBUG    2019-09-24 11:12:18,911 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,912 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:18,913 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,063 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,064 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,065 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,066 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,067 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,069 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,259 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,260 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,262 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,263 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,264 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,265 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,458 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,461 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,463 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,465 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,467 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,470 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,472 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,474 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,475 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,478 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,480 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,482 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,484 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,486 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,488 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,490 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,492 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2019-09-24 11:12:19,494 [1512:Dummy-13] spotify.session
  Audio buffer stats requested, but no listener
INFO     2019-09-24 11:12:19,495 [1512:SpotifyBackend-9] mopidy_spotify.lookup
  Failed to lookup "spotify:track:6sqTapK2MJhUSrbW6MniB8": Operation did not complete in 2.000s
14

Hello everyone,

Same issue here whith latest Mopidy, same logs.
Have you solved your problem?