# Spotify playback fails to start **URL:** \ **Category:** Misc\ **Created:** [August 11, 2017, 7:30pm UTC](https://discourse.mopidy.com/t/spotify-playback-fails-to-start/1809 "2017-08-11T19:30:50Z")\ **Posts on this page:** 2\ **Page:** 1

**Author:** ![MattDevUK](https://yyz2.discourse-cdn.com/flex036/user_avatar/discourse.mopidy.com/mattdevuk/32/665_2.png) [@MattDevUK](https://discourse.mopidy.com/u/MattDevUK)\ **Post date:** [August 11, 2017, 7:30pm UTC](https://discourse.mopidy.com/t/spotify-playback-fails-to-start/1809/1 "2017-08-11T19:30:50Z")

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. ---

**Author:** ![MattDevUK](https://yyz2.discourse-cdn.com/flex036/user_avatar/discourse.mopidy.com/mattdevuk/32/665_2.png) [@MattDevUK](https://discourse.mopidy.com/u/MattDevUK)\ **Post date:** [August 27, 2017, 12:40pm UTC](https://discourse.mopidy.com/t/spotify-playback-fails-to-start/1809/2 "2017-08-27T12:40:09Z")

I’m guessing either nobody knows what this issue is? I’d hope someone would let me know if I was just being stupid 😃