Hey there 
I’ve just installed Pi MusicBox on my RPi 2B, but noticed when trying to play tracks from Spotify, it can take way over 2 minutes before the track starts outputting audio.
To test, I ran it using basic Mopidy and it’s the same. I see the timestamp on the song count up to a max of 9s, then reset back to 0 and continue doing this over and over until it finally starts playing.
The Debug logs show a lot as expected.
There is an awful lot of these:
2017-08-11 20:09:06,850 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:09:06,853 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 176, “result”: 0}’
2017-08-11 20:09:07,863 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_posi
tion”,“jsonrpc”:“2.0”,“id”:177}’
At first I thought it was buffering, but I found if I clicked anywhere along the track, it would start playing from there instantly. Even if I clicked right to the end, it would pick it up almost instantly. It just seems to be at the beginning of every spotify song, it sits there trying for 2-5 minutes, before it finally goes “okay good, changing from stopped to playing”
Here’s a larger log snippet. this is me manually seeking it to 0 and experiencing the pause, then seeking to a random part of the song and it working instantly.
2017-08-11 20:24:33,034 DEBUG [2632:Audio-2] mopidy.audio.gst: Sent flushing seek: position=0
2017-08-11 20:24:33,036 DEBUG [2632:Core-16] mopidy.core.playback: Triggering seeked event
2017-08-11 20:24:33,040 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 350, “result”: true}
’
2017-08-11 20:24:33,041 DEBUG [2632:MainThread] mopidy.listener: Sending seeked to CoreListener: {‘time_position’: 0}
2017-08-11 20:24:33,059 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_posi
tion”,“jsonrpc”:“2.0”,“id”:351}’
2017-08-11 20:24:33,063 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:33,067 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 351, “result”: 0}’
2017-08-11 20:24:33,330 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:352}’
2017-08-11 20:24:33,335 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:33,338 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 352, “result”: 0}’
2017-08-11 20:24:33,416 DEBUG [2632:Dummy-12] mopidy_spotify.session_manager: System message: 19:24:33.416 I [file_streamer_simple.cpp:769] Request for file 11f2ee5c5fde366fc2a6185eaecf44e644ac8e89 complete (code: 0)
2017-08-11 20:24:33,647 DEBUG [2632:Dummy-12] mopidy_spotify.session_manager: System message: 19:24:33.647 I [file_streamer_simple.cpp:769] Request for file 11f2ee5c5fde366fc2a6185eaecf44e644ac8e89 complete (code: 0)
2017-08-11 20:24:33,856 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:353}’
2017-08-11 20:24:33,860 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:33,863 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 353, “result”: 0}’
2017-08-11 20:24:34,875 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:354}’
2017-08-11 20:24:34,883 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:34,887 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 354, “result”: 0}’
2017-08-11 20:24:35,890 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:355}’
2017-08-11 20:24:35,894 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:35,896 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 355, “result”: 0}’
2017-08-11 20:24:36,907 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:356}’
2017-08-11 20:24:36,911 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:36,914 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 356, “result”: 0}’
2017-08-11 20:24:37,924 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:357}’
2017-08-11 20:24:37,928 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:37,930 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 357, “result”: 0}’
2017-08-11 20:24:38,941 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:358}’
2017-08-11 20:24:38,945 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:38,947 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 358, “result”: 0}’
2017-08-11 20:24:39,958 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:359}’
2017-08-11 20:24:39,962 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:39,965 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 359, “result”: 0}’
2017-08-11 20:24:40,975 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:360}’
2017-08-11 20:24:40,979 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:40,982 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 360, “result”: 0}’
2017-08-11 20:24:41,839 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.seek”,“params”:{“time_position”:38400},“jsonrpc”:“2.0”,“id”:361}’
2017-08-11 20:24:41,851 DEBUG [2632:Audio-2] mopidy.audio.gst: Sent flushing seek: position=38400000000
2017-08-11 20:24:41,853 DEBUG [2632:Core-16] mopidy.core.playback: Triggering seeked event
2017-08-11 20:24:41,855 DEBUG [2632:MainThread] mopidy.listener: Sending seeked to CoreListener: {‘time_position’: 38400}
2017-08-11 20:24:41,857 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 361, “result”: true}’
2017-08-11 20:24:41,873 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:362}’
2017-08-11 20:24:41,877 DEBUG [2632:Audio-2] mopidy.audio.actor: Position query failed
2017-08-11 20:24:41,879 DEBUG [2632:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.0.6: ‘{“jsonrpc”: “2.0”, “id”: 362, “result”: 0}’
2017-08-11 20:24:42,248 DEBUG [2632:Dummy-21] mopidy.audio.gst: Got new-segment event: update=False rate=1.0 format=GST_FORMAT_TIME start=38400000000 stop=-1 position=38400000000
2017-08-11 20:24:42,249 DEBUG [2632:Dummy-12] mopidy_spotify.session_manager: System message: 19:24:42.248 I [file_streamer_simple.cpp:769] Request for file 11f2ee5c5fde366fc2a6185eaecf44e644ac8e89 complete (code: 0)
2017-08-11 20:24:42,250 DEBUG [2632:Dummy-21] mopidy.audio.actor: Audio event: position_changed(position=38400)
2017-08-11 20:24:42,252 DEBUG [2632:MainThread] mopidy.listener: Sending position_changed to AudioListener: {‘position’: 38400L}
2017-08-11 20:24:42,255 DEBUG [2632:MainThread] mopidy.audio.gst: Got state-changed message: old=GST_STATE_PAUSED new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
2017-08-11 20:24:42,257 DEBUG [2632:MainThread] mopidy.audio.gst: Got async-done.
2017-08-11 20:24:42,258 DEBUG [2632:MainThread] mopidy.audio.gst: Got state-changed message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
2017-08-11 20:24:42,259 DEBUG [2632:MainThread] mopidy.audio.actor: Audio event: state_changed(old_state=playing, new_state=playing, target_state=None)
2017-08-11 20:24:42,260 DEBUG [2632:MainThread] mopidy.listener: Sending state_changed to AudioListener: {‘old_state’: u’playing’, ‘target_state’: None, ‘new_state’: u’playing’}
2017-08-11 20:24:42,462 DEBUG [2632:Dummy-12] mopidy_spotify.session_manager: System message: 19:24:42.461 I [file_streamer_simple.cpp:769] Request for file 11f2ee5c5fde366fc2a6185eaecf44e644ac8e89 complete (code: 0)
2017-08-11 20:24:42,891 DEBUG [2632:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.0.6: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:363}’
This is using Mopidy 1.1.2 and Mopidy-Spotify 1.4.0. The latest Pi musicbox 0.7.0 RC5.
