search

mopidy / mopidy

Mopidy is an extensible music server written in Python
https://mopidy.com
Apache License 2.0
8.05k stars 686 forks source link

Unpredictable playback and incorrect frontend reports #2036

Closed InanisOmnia closed 2 years ago

InanisOmnia commented 2 years ago

Describe the bug The mopidy frontend does not match what is actually being played. The scrub bar runs faster than the actual time in seconds (randomly jumping large amounts of time), the pause/play buttons appear to have no affect. However, finding a track and clikcing "play now" make that track play but then all mentioned issues immediately re-occur.

I've been listening to the output whilst writing this issue and it has now randomly started at the beginning of the same song (without allowing it to finish) and it now just looping over that specific section of the song.

How to reproduce Have mopidy output to a file, in my case "/tmp/snapfifo" Snapserver and snapclient running, reading from this file

Expected behaviour A clear and concise description of what you expected to happen.

Environment Please complete the following information:

Running "/usr/bin/mopidy --config /usr/share/mopidy/conf.d:/etc/mopidy/mopidy.conf config" as user mopidy
[core]
cache_dir = /var/cache/mopidy
config_dir = /etc/mopidy
data_dir = /var/lib/mopidy
max_tracklist_length = 10000
restore_state = false

[logging]
verbosity = 0
format = %(levelname)-8s [%(threadName)s] %(name)s %(message)s
color = false
config_file =

[audio]
mixer = software
mixer_volume = 100
output = audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo
buffer_time = 

[proxy]
scheme = 
hostname = 
port = 
username = 
password = 

[spotify_web]
enabled = true
client_id = 4bc6da24-7ae8-4239-9538-01fef997d73b
client_secret = 6RiMC7-lSTdvnVPzdSQXrWXVnD-0_23tg5_qHYfVCzo=
mopidy_token_url = https://auth.mopidy.com/spotify/token
spotify_token_url = https://accounts.spotify.com/api/token
use_mopidy_oauth_bridge = true
refresh_token = please configure if you want to use spotify auth instead of mopidy swap service

[mpd]
enabled = true
hostname = 0.0.0.0
port = 6600
password = 
max_connections = 20
connection_timeout = 60
zeroconf = Mopidy MPD server on $hostname
command_blacklist = 
  listall
  listallinfo
default_playlist_scheme = m3u

[iris]
enabled = true
country = NZ
locale = en_NZ
snapcast_enabled = true
snapcast_host = localhost
snapcast_port = 1780
snapcast_ssl = false
snapcast_stream = Default
spotify_authorization_url = https://jamesbarnsley.co.nz/iris/auth_spotify.php
lastfm_authorization_url = https://jamesbarnsley.co.nz/iris/auth_lastfm.php
genius_authorization_url = https://jamesbarnsley.co.nz/iris/auth_genius.php
data_dir = $XDG_DATA_DIR/iris

[file]
enabled = true
media_dirs = 
  $XDG_MUSIC_DIR|Music
  ~/|Home
excluded_file_extensions = 
  .directory
  .html
  .jpeg
  .jpg
  .log
  .nfo
  .pdf
  .png
  .txt
  .zip
show_dotfiles = false
follow_symlinks = false
metadata_timeout = 1000

[http]
enabled = true
hostname = 0.0.0.0
port = 6680
zeroconf = Mopidy HTTP server on $hostname
allowed_origins = 
csrf_protection = true
default_app = mopidy

[m3u]
enabled = true
base_dir =
default_encoding = latin-1
default_extension = .m3u8
playlists_dir =

[softwaremixer]
enabled = true

[stream]
enabled = true
protocols = 
  http
  https
  mms
  rtmp
  rtmps
  rtsp
metadata_blacklist = 
timeout = 5000

[spotify]
enabled = true
username = farqs76
password = ********
client_id = 4bc6da24-7ae8-4239-9538-01fef997d73b
client_secret = ********
bitrate = 160
volume_normalization = true
private_session = false
timeout = 10
allow_cache = true
allow_network = true
allow_playlists = true
search_album_count = 20
search_artist_count = 10
search_track_count = 50
toplist_countries = 

[podcast]
enabled = true
browse_root = Podcasts.opml
browse_order = desc
lookup_order = asc
cache_size = 64
cache_ttl = 86400
timeout = 10
Running "/usr/bin/mopidy --config /usr/share/mopidy/conf.d:/etc/mopidy/mopidy.conf deps" as user mopidy
Executable: /usr/bin/mopidy
Platform: Linux-5.10.63-v7l+-armv7l-with-glibc2.31
Python: CPython 3.9.2 from /usr/lib/python3.9
Mopidy: 3.2.0 from /usr/lib/python3/dist-packages
Mopidy-Iris: 3.60.1 from /usr/local/lib/python3.9/dist-packages
  setuptools: 52.0.0 from /usr/lib/python3/dist-packages
  Mopidy: 3.2.0 from /usr/lib/python3/dist-packages
  Pykka: 2.0.3 from /usr/lib/python3/dist-packages
Mopidy-Spotify-Web: 0.3.0 from /usr/local/lib/python3.9/dist-packages
  Mopidy-Spotify: 4.1.1 from /usr/lib/python3/dist-packages
  Pykka: 2.0.3 from /usr/lib/python3/dist-packages
  spotipy: 2.19.0 from /usr/local/lib/python3.9/dist-packages
    requests: 2.25.1 from /usr/lib/python3/dist-packages
    urllib3: 1.26.5 from /usr/lib/python3/dist-packages
    six: 1.16.0 from /usr/lib/python3/dist-packages
  Mopidy: 3.2.0 from /usr/lib/python3/dist-packages
  requests: 2.25.1 from /usr/lib/python3/dist-packages
  setuptools: 52.0.0 from /usr/lib/python3/dist-packages
Mopidy-Spotify: 4.1.1 from /usr/lib/python3/dist-packages
Mopidy-Podcast: 3.0.0 from /usr/lib/python3/dist-packages
Mopidy-MPD: 3.2.0 from /usr/local/lib/python3.9/dist-packages
  setuptools: 52.0.0 from /usr/lib/python3/dist-packages
  Mopidy: 3.2.0 from /usr/lib/python3/dist-packages
  Pykka: 2.0.3 from /usr/lib/python3/dist-packages
GStreamer: 1.18.4.0 from /usr/lib/python3/dist-packages/gi
  Detailed information: 
    Python wrapper: python-gi 3.38.0
    Relevant elements:
      Found:
        uridecodebin
        souphttpsrc
        appsrc
        alsasink
        osssink
        oss4sink
        pulsesink
        id3demux
        id3v2mux
        lamemp3enc
        mpegaudioparse
        mpg123audiodec
        vorbisdec
        vorbisenc
        vorbisparse
        oggdemux
        oggmux
        oggparse
        flacdec
        flacparse
        shout2send
      Not found:
        flump3dec
        mad

Additional context The music still plays syncrhonised across all devices (using snapcast) and all frontends state incorrect timings and incorrect tracks (slowly getting more and more out of time and further away from current song in the queue) including ncmcpp in terminal and mopidy mobile

If appropriate, upload an appropriately verbose log file showing the bug.

INFO     2021-12-31 14:33:42,567 [2365:MainThread] mopidy.__main__
  Starting Mopidy 3.2.0
DEBUG    2021-12-31 14:33:42,595 [2365:MainThread] mopidy.ext
  Loading entry point: spotify_web = mopidy_spotify_web:Extension
DEBUG    2021-12-31 14:33:42,597 [2365:MainThread] mopidy_spotify_web
  loading mopidy-web extension
DEBUG    2021-12-31 14:33:42,598 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-Spotify-Web 0.3.0
DEBUG    2021-12-31 14:33:42,598 [2365:MainThread] mopidy.ext
  Loading entry point: mpd = mopidy_mpd:Extension
DEBUG    2021-12-31 14:33:42,601 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-MPD 3.2.0
DEBUG    2021-12-31 14:33:42,601 [2365:MainThread] mopidy.ext
  Loading entry point: iris = mopidy_iris:Extension
DEBUG    2021-12-31 14:33:42,603 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-Iris 3.60.1
DEBUG    2021-12-31 14:33:42,606 [2365:MainThread] mopidy.ext
  Loading entry point: file = mopidy.file:Extension
DEBUG    2021-12-31 14:33:42,607 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-File 3.2.0
DEBUG    2021-12-31 14:33:42,607 [2365:MainThread] mopidy.ext
  Loading entry point: http = mopidy.http:Extension
DEBUG    2021-12-31 14:33:42,608 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-HTTP 3.2.0
DEBUG    2021-12-31 14:33:42,608 [2365:MainThread] mopidy.ext
  Loading entry point: m3u = mopidy.m3u:Extension
DEBUG    2021-12-31 14:33:42,609 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-M3U 3.2.0
DEBUG    2021-12-31 14:33:42,609 [2365:MainThread] mopidy.ext
  Loading entry point: softwaremixer = mopidy.softwaremixer:Extension
DEBUG    2021-12-31 14:33:42,610 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-SoftwareMixer 3.2.0
DEBUG    2021-12-31 14:33:42,610 [2365:MainThread] mopidy.ext
  Loading entry point: stream = mopidy.stream:Extension
DEBUG    2021-12-31 14:33:42,611 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-Stream 3.2.0
DEBUG    2021-12-31 14:33:42,612 [2365:MainThread] mopidy.ext
  Loading entry point: spotify = mopidy_spotify:Extension
DEBUG    2021-12-31 14:33:42,615 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-Spotify 4.1.1
DEBUG    2021-12-31 14:33:42,616 [2365:MainThread] mopidy.ext
  Loading entry point: podcast = mopidy_podcast:Extension
DEBUG    2021-12-31 14:33:42,619 [2365:MainThread] mopidy.ext
  Loaded extension: Mopidy-Podcast 3.0.0
DEBUG    2021-12-31 14:33:42,620 [2365:MainThread] mopidy.ext
  Discovered extensions: spotify_web, mpd, iris, file, http, m3u, softwaremixer, stream, spotify, podcast
DEBUG    2021-12-31 14:33:42,624 [2365:MainThread] mopidy.config.keyring
  Fetching passwords from your keyring failed. Any passwords stored in the keyring will not be available. (dbus not installed)
INFO     2021-12-31 14:33:42,625 [2365:MainThread] mopidy.config
  Loading config from builtin defaults
DEBUG    2021-12-31 14:33:42,629 [2365:MainThread] mopidy.config
  Loading config from file:///etc/xdg/mopidy/mopidy.conf failed; it does not exist
INFO     2021-12-31 14:33:42,629 [2365:MainThread] mopidy.config
  Loading config from file:///home/pi/.config/mopidy/mopidy.conf
INFO     2021-12-31 14:33:42,635 [2365:MainThread] mopidy.config
  Loading config from command line options
DEBUG    2021-12-31 14:33:42,650 [2365:MainThread] mopidy.ext
  Validating extension: spotify_web
DEBUG    2021-12-31 14:33:42,734 [2365:MainThread] mopidy.ext
  Validating extension: mpd
DEBUG    2021-12-31 14:33:42,788 [2365:MainThread] mopidy.ext
  Validating extension: iris
DEBUG    2021-12-31 14:33:42,848 [2365:MainThread] mopidy.ext
  Validating extension: file
DEBUG    2021-12-31 14:33:42,848 [2365:MainThread] mopidy.ext
  Validating extension: http
DEBUG    2021-12-31 14:33:42,989 [2365:MainThread] mopidy.ext
  Validating extension: m3u
DEBUG    2021-12-31 14:33:42,989 [2365:MainThread] mopidy.ext
  Validating extension: softwaremixer
DEBUG    2021-12-31 14:33:42,990 [2365:MainThread] mopidy.ext
  Validating extension: stream
DEBUG    2021-12-31 14:33:42,990 [2365:MainThread] mopidy.ext
  Validating extension: spotify
DEBUG    2021-12-31 14:33:42,990 [2365:MainThread] mopidy.ext
  Validating extension: podcast
INFO     2021-12-31 14:33:43,037 [2365:MainThread] mopidy.__main__
  Enabled extensions: file, m3u, http, iris, stream, podcast, mpd, spotify_web, spotify, softwaremixer
INFO     2021-12-31 14:33:43,037 [2365:MainThread] mopidy.__main__
  Disabled extensions: none
DEBUG    2021-12-31 14:33:43,037 [2365:MainThread] mopidy_spotify_web
  registering mopidy-web backend
ERROR    2021-12-31 14:33:43,203 [2365:MainThread] mopidy.__main__
  Extension spotify_web failed during setup. This might have left the registry in a bad state.
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/mopidy/__main__.py", line 129, in main
    extension.setup(registry)
  File "/usr/local/lib/python3.9/dist-packages/mopidy_spotify_web/__init__.py", line 37, in setup
    from .backend import SpotifyWebBackend
  File "/usr/local/lib/python3.9/dist-packages/mopidy_spotify_web/backend.py", line 7, in <module>
    from mopidy_spotify_web.library import SpotifyWebLibraryProvider
  File "/usr/local/lib/python3.9/dist-packages/mopidy_spotify_web/library.py", line 17, in <module>
    from translator import to_mopidy_track
ImportError: cannot import name 'to_mopidy_track' from 'translator' (/home/pi/.local/lib/python3.9/site-packages/translator/__init__.py)
DEBUG    2021-12-31 14:33:43,358 [2365:MainThread] mopidy.commands
  Available Mopidy mixers: SoftwareMixer
INFO     2021-12-31 14:33:43,358 [2365:MainThread] mopidy.commands
  Starting Mopidy mixer: SoftwareMixer
DEBUG    2021-12-31 14:33:43,359 [2365:MainThread] pykka
  Registered SoftwareMixer (urn:uuid:a7fa1408-be48-4a04-9c66-4deb423dfeac)
DEBUG    2021-12-31 14:33:43,359 [2365:MainThread] pykka
  Starting SoftwareMixer (urn:uuid:a7fa1408-be48-4a04-9c66-4deb423dfeac)
INFO     2021-12-31 14:33:43,362 [2365:MainThread] mopidy.commands
  Mixer volume set to 100
INFO     2021-12-31 14:33:43,362 [2365:MainThread] mopidy.commands
  Starting Mopidy audio
DEBUG    2021-12-31 14:33:43,363 [2365:MainThread] pykka
  Registered Audio (urn:uuid:00765297-e9bc-4f43-a7db-52b5495ee883)
DEBUG    2021-12-31 14:33:43,363 [2365:MainThread] pykka
  Starting Audio (urn:uuid:00765297-e9bc-4f43-a7db-52b5495ee883)
INFO     2021-12-31 14:33:43,366 [2365:MainThread] mopidy.commands
  Starting Mopidy backends: FileBackend, M3UBackend, StreamBackend, SpotifyBackend, PodcastBackend
DEBUG    2021-12-31 14:33:43,367 [2365:MainThread] mopidy.file.library
  Failed expanding path ($XDG_MUSIC_DIR) from file/media_dirs config value.
DEBUG    2021-12-31 14:33:43,368 [2365:MainThread] pykka
  Registered FileBackend (urn:uuid:7bfda384-4ea6-44ba-a063-72d5863df967)
DEBUG    2021-12-31 14:33:43,370 [2365:MainThread] pykka
  Starting FileBackend (urn:uuid:7bfda384-4ea6-44ba-a063-72d5863df967)
DEBUG    2021-12-31 14:33:43,382 [2365:MainThread] pykka
  Registered M3UBackend (urn:uuid:b78d506b-99be-4f79-bb35-38dd70fdd85c)
DEBUG    2021-12-31 14:33:43,382 [2365:MainThread] pykka
  Starting M3UBackend (urn:uuid:b78d506b-99be-4f79-bb35-38dd70fdd85c)
INFO     2021-12-31 14:33:43,388 [2365:Audio-2] mopidy.audio.actor
  Audio output set to "audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo"
DEBUG    2021-12-31 14:33:43,393 [2365:MainThread] pykka
  Registered StreamBackend (urn:uuid:0273a1e1-6155-45fe-a42a-85caa7789658)
DEBUG    2021-12-31 14:33:43,393 [2365:MainThread] pykka
  Starting StreamBackend (urn:uuid:0273a1e1-6155-45fe-a42a-85caa7789658)
DEBUG    2021-12-31 14:33:43,403 [2365:MainThread] pykka
  Registered SpotifyBackend (urn:uuid:99a19fbe-341f-4958-bda2-0d2b13b8cb1b)
DEBUG    2021-12-31 14:33:43,403 [2365:MainThread] pykka
  Starting SpotifyBackend (urn:uuid:99a19fbe-341f-4958-bda2-0d2b13b8cb1b)
DEBUG    2021-12-31 14:33:43,404 [2365:SoftwareMixer-1] mopidy.mixer
  Mixer event: volume_changed(volume=100)
DEBUG    2021-12-31 14:33:43,420 [2365:SoftwareMixer-1] mopidy.listener
  Sending volume_changed to MixerListener: {'volume': 100}
DEBUG    2021-12-31 14:33:43,420 [2365:MainThread] pykka
  Registered PodcastBackend (urn:uuid:ab285ea6-d9af-4672-9a4d-4dabe25adb2f)
DEBUG    2021-12-31 14:33:43,421 [2365:MainThread] pykka
  Starting PodcastBackend (urn:uuid:ab285ea6-d9af-4672-9a4d-4dabe25adb2f)
DEBUG    2021-12-31 14:33:43,439 [2365:SpotifyEventLoop] spotify.eventloop
  Spotify event loop started
DEBUG    2021-12-31 14:33:43,567 [2365:SpotifyBackend-6] mopidy_spotify.web
  Fetching OAuth token from https://auth.mopidy.com/spotify/token
DEBUG    2021-12-31 14:33:43,567 [2365:Dummy-9] spotify.session
  libspotify log message: 14:33:43.566 I [ap:1752] Connecting to AP ap.spotify.com:4070
DEBUG    2021-12-31 14:33:43,567 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 300.702s for new events
DEBUG    2021-12-31 14:33:43,571 [2365:SpotifyBackend-6] urllib3.connectionpool
  Starting new HTTPS connection (1): auth.mopidy.com:443
DEBUG    2021-12-31 14:33:43,594 [2365:Dummy-9] spotify.session
  libspotify log message: 14:33:43.594 I [ap:1226] Connected to AP: 104.199.64.241:4070
DEBUG    2021-12-31 14:33:43,704 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:43,704 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:43,705 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 300.565s for new events
DEBUG    2021-12-31 14:33:43,731 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:43,732 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:43,733 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:43,834 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://auth.mopidy.com:443 "POST /spotify/token HTTP/1.1" 200 556
DEBUG    2021-12-31 14:33:43,836 [2365:SpotifyBackend-6] mopidy_spotify.web
  Token expires in 3600 seconds.
DEBUG    2021-12-31 14:33:43,836 [2365:SpotifyBackend-6] mopidy_spotify.web
  Token scopes: playlist-read-private playlist-read-collaborative streaming user-library-read user-follow-read user-library-modify playlist-modify-private playlist-modify-public user-read-recently-played user-read-private user-top-read
DEBUG    2021-12-31 14:33:43,840 [2365:SpotifyBackend-6] urllib3.connectionpool
  Starting new HTTPS connection (1): api.spotify.com:443
INFO     2021-12-31 14:33:43,873 [2365:SpotifyEventLoop] spotify.session
  Spotify logged in
DEBUG    2021-12-31 14:33:43,874 [2365:SpotifyEventLoop] spotify.session
  Credentials blob updated: b'+VbzAVxQ1Br61sXoZcpAgHZWAobh86cbDJkG57LTBrrwGjX6r51iiLQTcbO57PTA+Tl7FIoZNue/E6LBWoRrxmeY3wxEI+A7senuCn7EBWW3OZZMlh/xnCpCteH0Shpz/vmK+F8qlDFg5Ni31DJTN9v4uxR1/qSa1rxjEl9nPZXfDP8dX+Z9s6vqIWQUOxriW15t5bwde3h5HsFV4b54hw=='
DEBUG    2021-12-31 14:33:43,875 [2365:SpotifyEventLoop] spotify.session
  Connection state updated
INFO     2021-12-31 14:33:43,876 [2365:SpotifyEventLoop] mopidy_spotify.backend
  Logged in to Spotify in online mode
DEBUG    2021-12-31 14:33:43,876 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.141s for new events
DEBUG    2021-12-31 14:33:43,877 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:43,877 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:43,878 [2365:SpotifyEventLoop] spotify.session
  libspotify log message: 14:33:43.878 I [offline-mgr:2082] Storage has been cleaned
DEBUG    2021-12-31 14:33:43,879 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.860s for new events
DEBUG    2021-12-31 14:33:43,880 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:43,880 [2365:SpotifyEventLoop] spotify.session
  User info updated
DEBUG    2021-12-31 14:33:43,880 [2365:SpotifyEventLoop] spotify.session
  User info updated
DEBUG    2021-12-31 14:33:43,880 [2365:SpotifyEventLoop] spotify.session
  User info updated
DEBUG    2021-12-31 14:33:43,881 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.858s for new events
DEBUG    2021-12-31 14:33:43,883 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:43,883 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:43,884 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:43,884 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.854s for new events
DEBUG    2021-12-31 14:33:43,885 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:43,885 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.853s for new events
DEBUG    2021-12-31 14:33:43,928 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/me HTTP/1.1" 200 None
INFO     2021-12-31 14:33:43,932 [2365:SpotifyBackend-6] mopidy_spotify.web
  Logged into Spotify Web API as [REDACTED]
DEBUG    2021-12-31 14:33:44,106 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/me/playlists?limit=50 HTTP/1.1" 200 None
DEBUG    2021-12-31 14:33:44,123 [2365:SpotifyBackend-6] mopidy_spotify.playlists
  Fetching Spotify playlist "'spotify:playlist:37i9dQZF1EUMDoJuT8yJsl'"
DEBUG    2021-12-31 14:33:44,239 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/playlists/37i9dQZF1EUMDoJuT8yJsl?fields=name%2Cowner.id%2Ctype%2Curi%2Csnapshot_id%2Ctracks%28next%2Citems%28track%28type%2Curi%2Cname%2Cduration_ms%2Cdisc_number%2Ctrack_number%2Cartists%2Calbum%2Cis_playable%2Clinked_from.uri%29%29%29%2C&market=from_token HTTP/1.1" 200 None
DEBUG    2021-12-31 14:33:44,340 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,341 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,341 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.396s for new events
DEBUG    2021-12-31 14:33:44,342 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,342 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,343 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.395s for new events
DEBUG    2021-12-31 14:33:44,343 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,344 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,344 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.394s for new events
DEBUG    2021-12-31 14:33:44,345 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,345 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,345 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.392s for new events
DEBUG    2021-12-31 14:33:44,346 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,346 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,347 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.391s for new events
DEBUG    2021-12-31 14:33:44,347 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,348 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,348 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.390s for new events
DEBUG    2021-12-31 14:33:44,348 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,349 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,350 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.388s for new events
DEBUG    2021-12-31 14:33:44,350 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,350 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,351 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.387s for new events
DEBUG    2021-12-31 14:33:44,351 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,351 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,352 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.386s for new events
DEBUG    2021-12-31 14:33:44,352 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,353 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,353 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.384s for new events
DEBUG    2021-12-31 14:33:44,354 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,355 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,355 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.383s for new events
DEBUG    2021-12-31 14:33:44,355 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,356 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,356 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.382s for new events
DEBUG    2021-12-31 14:33:44,357 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,357 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,358 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.380s for new events
DEBUG    2021-12-31 14:33:44,358 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,359 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,359 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.379s for new events
DEBUG    2021-12-31 14:33:44,360 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,360 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,360 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.377s for new events
DEBUG    2021-12-31 14:33:44,361 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,361 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,362 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,363 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.375s for new events
DEBUG    2021-12-31 14:33:44,363 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,364 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,365 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.001s for new events
DEBUG    2021-12-31 14:33:44,367 [2365:SpotifyBackend-6] mopidy_spotify.playlists
  Fetching Spotify playlist "'spotify:playlist:37i9dQZF1EJDRghfshEKFI'"
DEBUG    2021-12-31 14:33:44,368 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,373 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,374 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.365s for new events
DEBUG    2021-12-31 14:33:44,386 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,386 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,387 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,387 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.351s for new events
DEBUG    2021-12-31 14:33:44,388 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,389 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,389 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.349s for new events
DEBUG    2021-12-31 14:33:44,390 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,390 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,390 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.348s for new events
DEBUG    2021-12-31 14:33:44,402 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,402 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,402 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,407 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.335s for new events
DEBUG    2021-12-31 14:33:44,408 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,408 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,408 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.330s for new events
DEBUG    2021-12-31 14:33:44,409 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,409 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,409 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.329s for new events
DEBUG    2021-12-31 14:33:44,418 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,419 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,419 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,424 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.319s for new events
DEBUG    2021-12-31 14:33:44,424 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,425 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,425 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.313s for new events
DEBUG    2021-12-31 14:33:44,425 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,425 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,425 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.313s for new events
DEBUG    2021-12-31 14:33:44,429 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,429 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,429 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,430 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.308s for new events
DEBUG    2021-12-31 14:33:44,430 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,431 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,431 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.307s for new events
DEBUG    2021-12-31 14:33:44,431 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,431 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,432 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.306s for new events
DEBUG    2021-12-31 14:33:44,479 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/playlists/37i9dQZF1EJDRghfshEKFI?fields=name%2Cowner.id%2Ctype%2Curi%2Csnapshot_id%2Ctracks%28next%2Citems%28track%28type%2Curi%2Cname%2Cduration_ms%2Cdisc_number%2Ctrack_number%2Cartists%2Calbum%2Cis_playable%2Clinked_from.uri%29%29%29%2C&market=from_token HTTP/1.1" 200 None
DEBUG    2021-12-31 14:33:44,484 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,485 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,490 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,506 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.253s for new events
DEBUG    2021-12-31 14:33:44,517 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,523 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,523 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.215s for new events
DEBUG    2021-12-31 14:33:44,525 [2365:SpotifyBackend-6] mopidy_spotify.playlists
  Fetching Spotify playlist "'spotify:playlist:2l31eEOzbUkMHJLhKWd0Fm'"
DEBUG    2021-12-31 14:33:44,525 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,530 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,532 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.208s for new events
DEBUG    2021-12-31 14:33:44,538 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,539 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,539 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,541 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.199s for new events
DEBUG    2021-12-31 14:33:44,541 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,542 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,542 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.196s for new events
DEBUG    2021-12-31 14:33:44,542 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,543 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,543 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.195s for new events
DEBUG    2021-12-31 14:33:44,564 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,565 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,565 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,568 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.173s for new events
DEBUG    2021-12-31 14:33:44,569 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,569 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,569 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.001s for new events
DEBUG    2021-12-31 14:33:44,570 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,570 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,570 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.168s for new events
DEBUG    2021-12-31 14:33:44,594 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,595 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,595 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,595 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.143s for new events
DEBUG    2021-12-31 14:33:44,596 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,596 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,596 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.142s for new events
DEBUG    2021-12-31 14:33:44,597 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,597 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:44,597 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.141s for new events
DEBUG    2021-12-31 14:33:44,738 [2365:SpotifyEventLoop] spotify.eventloop
  Timeout reached; processing events
DEBUG    2021-12-31 14:33:44,739 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:44,739 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.001s for new events
DEBUG    2021-12-31 14:33:44,739 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:44,739 [2365:SpotifyEventLoop] spotify.session
  User info updated
DEBUG    2021-12-31 14:33:44,740 [2365:SpotifyEventLoop] spotify.session
  libspotify log message: 14:33:44.740 I [offline-mgr:2030] 0 files are locked. 0 images are locked
DEBUG    2021-12-31 14:33:44,740 [2365:SpotifyEventLoop] spotify.session
  libspotify log message: 14:33:44.740 I [offline-mgr:2056] 0 files unlocked. 0 images unlocked
DEBUG    2021-12-31 14:33:44,740 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.144s for new events
DEBUG    2021-12-31 14:33:44,773 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/playlists/2l31eEOzbUkMHJLhKWd0Fm?fields=name%2Cowner.id%2Ctype%2Curi%2Csnapshot_id%2Ctracks%28next%2Citems%28track%28type%2Curi%2Cname%2Cduration_ms%2Cdisc_number%2Ctrack_number%2Cartists%2Calbum%2Cis_playable%2Clinked_from.uri%29%29%29%2C&market=from_token HTTP/1.1" 200 None
DEBUG    2021-12-31 14:33:44,885 [2365:SpotifyEventLoop] spotify.eventloop
  Timeout reached; processing events
DEBUG    2021-12-31 14:33:44,885 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.993s for new events
DEBUG    2021-12-31 14:33:44,900 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/playlists/2l31eEOzbUkMHJLhKWd0Fm/tracks?fields=next%2Citems%28track%28type%2Curi%2Cname%2Cduration_ms%2Cdisc_number%2Ctrack_number%2Cartists%2Calbum%2Cis_playable%2Clinked_from.uri%29%29&limit=100&market=from_token&offset=100 HTTP/1.1" 200 None
DEBUG    2021-12-31 14:33:45,022 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/playlists/2l31eEOzbUkMHJLhKWd0Fm/tracks?fields=next%2Citems%28track%28type%2Curi%2Cname%2Cduration_ms%2Cdisc_number%2Ctrack_number%2Cartists%2Calbum%2Cis_playable%2Clinked_from.uri%29%29&limit=100&market=from_token&offset=200 HTTP/1.1" 200 None
DEBUG    2021-12-31 14:33:45,180 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/playlists/2l31eEOzbUkMHJLhKWd0Fm/tracks?fields=next%2Citems%28track%28type%2Curi%2Cname%2Cduration_ms%2Cdisc_number%2Ctrack_number%2Cartists%2Calbum%2Cis_playable%2Clinked_from.uri%29%29&limit=100&market=from_token&offset=300 HTTP/1.1" 200 None
DEBUG    2021-12-31 14:33:45,381 [2365:SpotifyBackend-6] mopidy_spotify.translator
  'spotify:track:7L03FM3omFqA7OACc2HPPe' is not playable
DEBUG    2021-12-31 14:33:45,476 [2365:SpotifyBackend-6] mopidy_spotify.translator
  'spotify:track:272gn0hwxo7UCwlgvNa4as' is not playable
DEBUG    2021-12-31 14:33:45,486 [2365:SpotifyBackend-6] mopidy_spotify.translator
  'spotify:track:3jtL9LGi9W31DWdLNtBYHf' is not playable
DEBUG    2021-12-31 14:33:45,501 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,501 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,502 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.376s for new events
DEBUG    2021-12-31 14:33:45,502 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,502 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,503 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.375s for new events
DEBUG    2021-12-31 14:33:45,503 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,504 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,504 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.373s for new events
DEBUG    2021-12-31 14:33:45,505 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,505 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,509 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.369s for new events
DEBUG    2021-12-31 14:33:45,509 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,510 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,510 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.368s for new events
DEBUG    2021-12-31 14:33:45,511 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,511 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,514 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.364s for new events
DEBUG    2021-12-31 14:33:45,514 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,515 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,516 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.361s for new events
DEBUG    2021-12-31 14:33:45,517 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,517 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,517 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.360s for new events
DEBUG    2021-12-31 14:33:45,518 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,518 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,519 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,520 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.359s for new events
DEBUG    2021-12-31 14:33:45,520 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,524 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,524 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.354s for new events
DEBUG    2021-12-31 14:33:45,524 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,529 [2365:SpotifyBackend-6] mopidy_spotify.playlists
  Fetching Spotify playlist "'spotify:playlist:37i9dQZF1DXb57FjYWz00c'"
DEBUG    2021-12-31 14:33:45,530 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:45,533 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.348s for new events
DEBUG    2021-12-31 14:33:45,535 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,536 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,536 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,537 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.342s for new events
DEBUG    2021-12-31 14:33:45,537 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,538 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,538 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.340s for new events
DEBUG    2021-12-31 14:33:45,538 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,539 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:45,539 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.339s for new events
DEBUG    2021-12-31 14:33:45,594 [2365:Dummy-9] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,595 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,595 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,599 [2365:SpotifyBackend-6] urllib3.connectionpool
  https://api.spotify.com:443 "GET /v1/playlists/37i9dQZF1DXb57FjYWz00c?fields=name%2Cowner.id%2Ctype%2Curi%2Csnapshot_id%2Ctracks%28next%2Citems%28track%28type%2Curi%2Cname%2Cduration_ms%2Cdisc_number%2Ctrack_number%2Cartists%2Calbum%2Cis_playable%2Clinked_from.uri%29%29%29%2C&market=from_token HTTP/1.1" 200 None
DEBUG    2021-12-31 14:33:45,615 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.283s for new events
DEBUG    2021-12-31 14:33:45,620 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,635 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,647 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 0.004s for new events
DEBUG    2021-12-31 14:33:45,647 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,647 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:45,648 [2365:SpotifyEventLoop] spotify.session
  Notify main thread
DEBUG    2021-12-31 14:33:45,648 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.230s for new events
DEBUG    2021-12-31 14:33:45,648 [2365:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2021-12-31 14:33:45,649 [2365:SpotifyEventLoop] spotify.session
  Metadata updated
DEBUG    2021-12-31 14:33:45,649 [2365:SpotifyEventLoop] spotify.eventloop
  Waiting 3.229s for new events
DEBUG    2021-12-31 14:33:45,649 [2365:SpotifyBackend-6] spotify.session
  Notify main thread
InanisOmnia commented 2 years ago

Getting warnings like so when doing service mopidy status

[HttpServer] mopidy_iris.core Updating Snapcast stream metadata: http://localhost:1780/jsonrpc
../gst/gstpad.c:4621:gst_pad_push_data:<wavenc0:src> Got data flow before segment event
../gst/gstpad.c:4368:gst_pad_chain_data_unchecked:<filesink0:sink> Got data flow before segment event
kingosticks commented 2 years ago

Have you tried using something other than a fifo? Such as:

All of these should work better than a gstreamer filesink, which doesn't work very well with a fifo. See https://github.com/mopidy/mopidy/issues/775 and https://github.com/mopidy/mopidy/issues/1636 which already cover much of this (and I've no interest in re-opening). If you have futher problems using Mopidy with Snapcast, create a topic on the Forum.