New 2023 Spotify Plugin

devgianlu · August 2, 2024, 8:15am

I am not sure this is an issue with go-librespot, mainly because in the lastest release I set a fixed ALSA buffer time of 500ms, which should worsen the stuttering. This may be something to investigate with the Volumio team. It is also very strange to me, because I have and use a Primo for the development and testing.

raev · August 2, 2024, 8:55am

Thanks for the answer!
That is very strange indeed, if you have no problem on your Primo, but others have. I’ve been in contact with support and, they seem to think it was a problem with go-librespot. Maybe we just have to wait and see if a future update somehow solves the issue completely.

pjorgenunes · August 5, 2024, 3:45am

I’ve tried today with just 4 tracks and everything went well in my Volumio Primo (1st Edition).
Connect at first try from my spotify on android phone;
Collacted tracks played with no fuss;
No skips or troubles until now.

Gold007 · August 6, 2024, 11:32am

I have tried out the latest 4.1.0 version of the plugin. Initially there was quite some hiccups: playback stopping after few minutes, spotify connect session closing randomly, volumio disappearing from available playback devices etc. After a restart and some trying it started to behave normally and play tracks.

But one big problem still persists: autoplay does not work. If playback gets to the last track of current list, it then just stops and jumps back to displaying the first track from the list.
You can find a quick log representing the issue here:
http://logs.volumio.org/volumio/ROkjflA.html

I have tried it with multiple lists and all behaved the same. No autoplay, just stop playback and jump to the beginning of list.
Latest Volumio (3.742) running on Raspberry Pi Zero 2 W.

raev · August 6, 2024, 4:55pm

Maybe the remaining stuttering on my device is buffering issues then, as I use a wireless connection - but I have no way of testing it with a wired connection :-/
At least Spotify is somewhat listenable now, even though ‘Multi room’ is activated.

Edit: When disabling ‘Multi room’ all stuttering disappears, so there’s still some kind of ‘fault’ in the plugin.

sciensys · August 13, 2024, 7:34am

3rd day after updating Volumio to version 3.742.
So far, not one stop of plugin.
I continue monitoring.
Thank you.

sciensys · August 14, 2024, 11:10am

But I was wrong.
At place I hear no sound! Player show time and You think that all is OK.

After Spotify playing, when I try to listen Radio, I get an error:
Faild to open “asla” (alsa); Failed to open ALSA device “volumio”: Device or resource busy.
Untitled

When I reboot Volumio, it start play Spotify (every boot need to login in setting of Spotify plugin and authorize) with AutoPlay plugin about 12 seconds,then I hear quite, but player show me the it works, it show time and switch to next track

> Aug 14 13:34:41 main mpd[2469]: exception: failed to open log file "/var/log/mpd.log" (config line 7): Permission denied
> Aug 14 13:34:41 main systemd[2458]: mpd.service: Main process exited, code=exited, status=1/FAILURE
> Aug 14 13:34:41 main systemd[2458]: mpd.service: Failed with result 'exit-code'.
> Aug 14 13:34:41 main systemd[2458]: Failed to start Music Player Daemon.
> Aug 14 13:34:41 main systemd[2458]: Reached target Default.
> Aug 14 13:34:41 main systemd[2458]: Startup finished in 916ms.

When select new play list in spotify, in 1 minute I hear a track during 5-10 seconds and again quite.
See log.
After 5-8 minutes spotify start play tracks by 5-10 second with pause 0.5-2 minutes of quite.
In browser everything OK, changing pitures, time, but I here music with pause and but in browser I see different track .

> Aug 14 13:51:11 main volumio[851]: info: Preload queue cleared
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0i1KkstzKrwFNvGeIphIuZ
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3IyikwjDC5J3RO1z1xbyIx
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:1VbQ1nbKIEbiR7JL7htId5
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6UegdjWPzCU3fkECOWwy3v
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0lxV7IydOdiJ6BKrkhtDhX
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5ztIul377mylwHJkCnIWbn
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:193aBnEo8qi098d3MQZrNC
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4wFIX5TaIwCJEUp1Hl6kOR
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0M4bg3q6Cjb1kVIfQJEBUR
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3Bv1eR7Q2AM6CZyBR1Ci7B
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5BSrJwLRF1eZr12BCVtH4B
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0JNlASn9XtasodWgM6hv7C
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:1guHQac8sGYR17kRUJVJN4
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:69Z9DW2lShC0KQlVqs6DSJ
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7JFT6vfzNI3Qtyyza6J55R
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:56j3S6jECUqwOExBifwy4B
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3SAECeINnjJaNbvVa5XMv3
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6nq8mMlQ2RKpG4SmqziE3j
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0eIW0BGY63JpCydq9j0oVL
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6LAIuS6A5qBqFP41FEQnsY
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6UeCjzfLUBhHOtney81sPn
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0uziRA46wxFQvNRtArLcZ4
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:29QksJV1n13inzZ2F6iNSP
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:2K9pZMX96NXf19MhJCtca0
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:2reLiqBW2EfejTe7OixGmT
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:30N6mzmZPQ0fUGW59krTc0
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4YzVZ67bjyhs1BylmBZDzx
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5OYofWmgGb1gTpBvrsIKnP
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3MrZpuWijCWDsCPl6bqDqc
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4Ee7XJ0Yk12BnoD2wRjSjD
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0oPbNzAAmWaKIcf5WQE6A0
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7JTyXQErhpjBJMVKEmL2MZ
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3mP8MIDvxxeCo3vx1MHeri
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:1uxoxQ1KHoHxO8GTYSe0kO
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3xNsHKqsBYt4aV90Bp4l5Y
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6mW4mrJtGsUNWXtO0rzg2i
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6hOXorsfbtCqWZ53bTsspU
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6rAH7LYZyxS026YWxYOqvA
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:2ZeHwwyO4hRMKYk5L1uke6
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5xxJz9J4bVAda0b0k1G8tP
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5nRYOuYInJeQWZR3r65wfJ
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3rUVcKmdmAjJEt0Zx7nSL5
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7oerc6eVjPLonOvtJq2qp3
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7k125cYjRfIYB23FOQTeTy
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:58aPWEzZwi7iEptm6l7Nz5
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:654RprVvr0L8l6wm7XEHci
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:28t1r5jQcliVMX6CKE8pkc
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:73vUl3nSQf7SwSGDDkTKCd
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:76yz1HdkCglnsSVyIjy1YS
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3ePsmfhb7hduvnDadoNNyi
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:1tLf0h0lt7QEJaZtyVdRrB
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7yzUHiCgF7JOzJOFE0Bnpd
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:23N8i7mAfbKfOWi0xD7v0f
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:1cfxSquzIuVUXxG7yfUmwF
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:08T5wMbEnPN8ghT8o24KY6
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5GWys8RxfQAAVxdiW1yN2p
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4zXKbHN9FKRTIirYQdMRqI
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:1DaKM1Mzf9cOhHF9eKZZ4w
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6DH3tZeaV2AZuaCJcdidRd
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7xForrtRX502c5ZGSjyaiX
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:2RcwqefTH11THzlwJHoS6D
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5YCcEL6h9usr4OUANFIPTu
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4Qw9NyyIYkgGzcmRnrZPrT
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:6UAOdfOdWSprSGvQAz5wDU
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4IJcZGJbZy0FQEC7oNnfVg
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:45gpJxviKRBsQo1lDZ03Xf
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0oMp06EjwhYFvDB33VCiW3
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5mb8d1F1YpajcnnoHhQFNh
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0UOKYamx2rZB4HYjedYFxn
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:628WzzZejEljPNLB2an42K
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0OtLnXYlL9nvUDhD5CCVaY
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7vR1aKpcVCNDt3McKkFLDO
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7bUG83VazqfG2G7b8L4CUS
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4RuYWUd85Pij03o7kuH6bO
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:38hsyjcR0xXU1a4xrExl13
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7lTYyo3pDiHnKpw3qSDBa8
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0OJY4Co8wfvutJg1r4tmkJ
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:71B847yYnD56zyHeSP4dRY
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:70OWZytVT3znmnCzHXZuVW
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0HscTiDcU2346DJAtjJThS
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:2iHMlhebiSk5TXx9F6QPKl
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4SdloKbQ6OV3D7K4BGTHVZ
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0Agl6KULj9qcIKKNLEAxyS
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0dc0zEseqfI8hAG3NJap3B
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:62Y7NjTwBdFRX5dXBKe3ti
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7btkqjF0Jw2DopaH6wvgvD
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:1CRDfNPQbtCGcqeAAgBGdW
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:1uY1IBa1UCS8u0nvAwO9Qd
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:78HeeCaFOxphQ0XPWmLxye
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0RMgMzxxcgOIUqxYzaezRM
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:3VE24SJnyeotIfXCEkYokj
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:73QGtATSeGM522WwmNED1V
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:48YLN7vV37I59GRuonTXWw
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:16DkQnS1oMNo0q0Txh5RjB
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:2ZouCCwvtrdDh1xJEZhJO0
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:4xbAiEKYJT0OCvKVzdkhoS
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:0K4sxJf1SSnoGPmEWjGDnA
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:7jANDEyhqACuL2NMkR5AOR
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:416pK3e4noKGynYRvbB7nc
> Aug 14 13:51:11 main volumio[851]: info: Preloading song: spotify:track:5V5CZu8wvT0UFwfh3r6FyI
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:0i1KkstzKrwFNvGeIphIuZ in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:0i1KkstzKrwFNvGeIphIuZ
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:3IyikwjDC5J3RO1z1xbyIx in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:3IyikwjDC5J3RO1z1xbyIx
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:1VbQ1nbKIEbiR7JL7htId5 in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:1VbQ1nbKIEbiR7JL7htId5
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0i1KkstzKrwFNvGeIphIuZ","service":"spop","name":"L'ongle","artist":"Presque Oui","album":"Sauvez les meubles","type":"song","duration":182,"albumart":"https://i.scdn.co/image/ab67616d0000b273a55d367b7e7e3a884102b2ee","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:6UegdjWPzCU3fkECOWwy3v in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:6UegdjWPzCU3fkECOWwy3v
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:0lxV7IydOdiJ6BKrkhtDhX in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:0lxV7IydOdiJ6BKrkhtDhX
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3IyikwjDC5J3RO1z1xbyIx","service":"spop","name":"Sous le ciel de Paris","artist":"Jill Barber","album":"Chansons","type":"song","duration":200,"albumart":"https://i.scdn.co/image/ab67616d0000b273c9be8eaa8d96ced17c3d4e2f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1VbQ1nbKIEbiR7JL7htId5","service":"spop","name":"Cette Nuit là","artist":"Les Chauds Lapins","album":"Amourettes","type":"song","duration":150,"albumart":"https://i.scdn.co/image/ab67616d0000b2736b25a9a455240185c9fccb31","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:5ztIul377mylwHJkCnIWbn in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:5ztIul377mylwHJkCnIWbn
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6UegdjWPzCU3fkECOWwy3v","service":"spop","name":"La fée clochette","artist":"Polo","album":"Bienvenue dans l'univers","type":"song","duration":185,"albumart":"https://i.scdn.co/image/ab67616d0000b273f6abbfb9ea42f7632c3b41a6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:193aBnEo8qi098d3MQZrNC in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:193aBnEo8qi098d3MQZrNC
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:4wFIX5TaIwCJEUp1Hl6kOR in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:4wFIX5TaIwCJEUp1Hl6kOR
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5ztIul377mylwHJkCnIWbn","service":"spop","name":"Dance Me To The End Of Love","artist":"Leonard Cohen","album":"Careless Love","type":"song","duration":235,"albumart":"https://i.scdn.co/image/ab67616d0000b273d13ca9f96706966a8f640bec","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0lxV7IydOdiJ6BKrkhtDhX","service":"spop","name":"Champs-Elysées","artist":"Zaz","album":"Paris","type":"song","duration":175,"albumart":"https://i.scdn.co/image/ab67616d0000b27343ddfb314d892a8f3864a57f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:0M4bg3q6Cjb1kVIfQJEBUR in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:0M4bg3q6Cjb1kVIfQJEBUR
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:193aBnEo8qi098d3MQZrNC","service":"spop","name":"Nuages","artist":"Chema Peñalver","album":"Old & New Gypsy Jazz","type":"song","duration":336,"albumart":"https://i.scdn.co/image/ab67616d0000b273a7c9b8775202ad1a087d8085","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:3Bv1eR7Q2AM6CZyBR1Ci7B in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:3Bv1eR7Q2AM6CZyBR1Ci7B
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4wFIX5TaIwCJEUp1Hl6kOR","service":"spop","name":"L'etang","artist":"Stacey Kent","album":"Raconte-Moi","type":"song","duration":264,"albumart":"https://i.scdn.co/image/ab67616d0000b273641d45fff46f5332abe9dd0b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:11 main volumio[851]: info: Exploding uri spotify:track:5BSrJwLRF1eZr12BCVtH4B in service spop
> Aug 14 13:51:11 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:5BSrJwLRF1eZr12BCVtH4B
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:0JNlASn9XtasodWgM6hv7C in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:0JNlASn9XtasodWgM6hv7C
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3Bv1eR7Q2AM6CZyBR1Ci7B","service":"spop","name":"On N'a Pas Besoin","artist":"Paris Combo","album":"Paris Combo","type":"song","duration":247,"albumart":"https://i.scdn.co/image/ab67616d0000b27303a99ff99c1d22ee407d779a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0M4bg3q6Cjb1kVIfQJEBUR","service":"spop","name":"La Valse Des Niglos","artist":"Zazou","album":"Merle Noir","type":"song","duration":191,"albumart":"https://i.scdn.co/image/ab67616d0000b273778a12fb9cdc9fa5add0c589","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:1guHQac8sGYR17kRUJVJN4 in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:1guHQac8sGYR17kRUJVJN4
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5BSrJwLRF1eZr12BCVtH4B","service":"spop","name":"Des croissants de soleil","artist":"Emilie-Claire Barlow","album":"Seule ce soir","type":"song","duration":238,"albumart":"https://i.scdn.co/image/ab67616d0000b273e80259504053fa2a7099cac1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:69Z9DW2lShC0KQlVqs6DSJ in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:69Z9DW2lShC0KQlVqs6DSJ
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:7JFT6vfzNI3Qtyyza6J55R in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:7JFT6vfzNI3Qtyyza6J55R
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0JNlASn9XtasodWgM6hv7C","service":"spop","name":"Mi amor","artist":"Stacey Kent","album":"Raconte-Moi","type":"song","duration":238,"albumart":"https://i.scdn.co/image/ab67616d0000b273641d45fff46f5332abe9dd0b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:56j3S6jECUqwOExBifwy4B in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:56j3S6jECUqwOExBifwy4B
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:69Z9DW2lShC0KQlVqs6DSJ","service":"spop","name":"Merle Noir","artist":"Zazou","album":"Merle Noir","type":"song","duration":213,"albumart":"https://i.scdn.co/image/ab67616d0000b273778a12fb9cdc9fa5add0c589","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1guHQac8sGYR17kRUJVJN4","service":"spop","name":"C'est Si Bon","artist":"Eartha Kitt","album":"That Bad Eartha","type":"song","duration":179,"albumart":"https://i.scdn.co/image/ab67616d0000b27397cfe12185da8979c227d735","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:3SAECeINnjJaNbvVa5XMv3 in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:3SAECeINnjJaNbvVa5XMv3
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:6nq8mMlQ2RKpG4SmqziE3j in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:6nq8mMlQ2RKpG4SmqziE3j
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:56j3S6jECUqwOExBifwy4B","service":"spop","name":"Lettre A P","artist":"Paris Combo","album":"Attraction","type":"song","duration":222,"albumart":"https://i.scdn.co/image/ab67616d0000b273fafa4386845fd5bc5645dbc1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:0eIW0BGY63JpCydq9j0oVL in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:0eIW0BGY63JpCydq9j0oVL
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:6LAIuS6A5qBqFP41FEQnsY in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:6LAIuS6A5qBqFP41FEQnsY
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3SAECeINnjJaNbvVa5XMv3","service":"spop","name":"Le fou de la reine","artist":"Henri Salvador","album":"Chambre avec vue","type":"song","duration":190,"albumart":"https://i.scdn.co/image/ab67616d0000b273bd771df79a492fd20f31aec5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6nq8mMlQ2RKpG4SmqziE3j","service":"spop","name":"Aquarium","artist":"Paris Combo","album":"Motifs","type":"song","duration":271,"albumart":"https://i.scdn.co/image/ab67616d0000b273a0cdabcb2ee7dbe7aa69f6ac","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:6UeCjzfLUBhHOtney81sPn in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:6UeCjzfLUBhHOtney81sPn
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7JFT6vfzNI3Qtyyza6J55R","service":"spop","name":"Faire des ronds dans l'eau","artist":"Henri Salvador","album":"Chambre avec vue","type":"song","duration":168,"albumart":"https://i.scdn.co/image/ab67616d0000b273bd771df79a492fd20f31aec5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0eIW0BGY63JpCydq9j0oVL","service":"spop","name":"La rua madureira","artist":"Pauline Croze","album":"Bossa Nova","type":"song","duration":197,"albumart":"https://i.scdn.co/image/ab67616d0000b2737fd363aaee0c52f987e67c2d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:0uziRA46wxFQvNRtArLcZ4 in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:0uziRA46wxFQvNRtArLcZ4
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6LAIuS6A5qBqFP41FEQnsY","service":"spop","name":"High Low In","artist":"Paris Combo","album":"Motifs","type":"song","duration":210,"albumart":"https://i.scdn.co/image/ab67616d0000b273a0cdabcb2ee7dbe7aa69f6ac","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:29QksJV1n13inzZ2F6iNSP in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:29QksJV1n13inzZ2F6iNSP
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6UeCjzfLUBhHOtney81sPn","service":"spop","name":"Don't Think Twice, It's Alright","artist":"Emilie-Claire Barlow","album":"The Beat Goes On","type":"song","duration":280,"albumart":"https://i.scdn.co/image/ab67616d0000b273e19e28d12fcb823c2f223754","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:2K9pZMX96NXf19MhJCtca0 in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:2K9pZMX96NXf19MhJCtca0
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0uziRA46wxFQvNRtArLcZ4","service":"spop","name":"Paris","artist":"Márcio Faraco","album":"Cajueiro","type":"song","duration":201,"albumart":"https://i.scdn.co/image/ab67616d0000b273bad9fbb7868beabefa4171cb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:2reLiqBW2EfejTe7OixGmT in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:2reLiqBW2EfejTe7OixGmT
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:30N6mzmZPQ0fUGW59krTc0 in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:30N6mzmZPQ0fUGW59krTc0
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:29QksJV1n13inzZ2F6iNSP","service":"spop","name":"Instead","artist":"Madeleine Peyroux","album":"Bare Bones","type":"song","duration":311,"albumart":"https://i.scdn.co/image/ab67616d0000b273d9091cc29864b6d1d80f7102","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:4YzVZ67bjyhs1BylmBZDzx in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:4YzVZ67bjyhs1BylmBZDzx
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2K9pZMX96NXf19MhJCtca0","service":"spop","name":"La contradiction","artist":"Coralie Clement","album":"Salle des pas perdus","type":"song","duration":174,"albumart":"https://i.scdn.co/image/ab67616d0000b27336289d656815dee4b657acb6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:5OYofWmgGb1gTpBvrsIKnP in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:5OYofWmgGb1gTpBvrsIKnP
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2reLiqBW2EfejTe7OixGmT","service":"spop","name":"Aime moi","artist":"Henri Salvador","album":"Chambre avec vue","type":"song","duration":234,"albumart":"https://i.scdn.co/image/ab67616d0000b273bd771df79a492fd20f31aec5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:3MrZpuWijCWDsCPl6bqDqc in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:3MrZpuWijCWDsCPl6bqDqc
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:30N6mzmZPQ0fUGW59krTc0","service":"spop","name":"Où est ma tête?","artist":"Pink Martini","album":"Splendor in the Grass","type":"song","duration":252,"albumart":"https://i.scdn.co/image/ab67616d0000b273dc875aef0f5d5d1de8949aab","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4YzVZ67bjyhs1BylmBZDzx","service":"spop","name":"The Way You Look Tonight","artist":"Madeleine Peyroux","album":"Got You on My Mind","type":"song","duration":182,"albumart":"https://i.scdn.co/image/ab67616d0000b2739dbddcf6d4c96347bb36c810","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:4Ee7XJ0Yk12BnoD2wRjSjD in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:4Ee7XJ0Yk12BnoD2wRjSjD
> Aug 14 13:51:12 main volumio[851]: info: Exploding uri spotify:track:0oPbNzAAmWaKIcf5WQE6A0 in service spop
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:0oPbNzAAmWaKIcf5WQE6A0
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5OYofWmgGb1gTpBvrsIKnP","service":"spop","name":"C'est le printemps","artist":"Stacey Kent","album":"Raconte-Moi","type":"song","duration":268,"albumart":"https://i.scdn.co/image/ab67616d0000b273641d45fff46f5332abe9dd0b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:12 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3MrZpuWijCWDsCPl6bqDqc","service":"spop","name":"Où veux-tu aller ?","artist":"Fredrika Stahl","album":"A Fraction Of You","type":"song","duration":211,"albumart":"https://i.scdn.co/image/ab67616d0000b27333267b7aaa9c0df627789be1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:7JTyXQErhpjBJMVKEmL2MZ in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:7JTyXQErhpjBJMVKEmL2MZ
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4Ee7XJ0Yk12BnoD2wRjSjD","service":"spop","name":"La belle dame sans regret - 2012","artist":"Emilie-Claire Barlow","album":"Seule ce soir","type":"song","duration":360,"albumart":"https://i.scdn.co/image/ab67616d0000b273e80259504053fa2a7099cac1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:3mP8MIDvxxeCo3vx1MHeri in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:3mP8MIDvxxeCo3vx1MHeri
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0oPbNzAAmWaKIcf5WQE6A0","service":"spop","name":"Chez moi","artist":"Emilie-Claire Barlow","album":"Haven't We Met?","type":"song","duration":173,"albumart":"https://i.scdn.co/image/ab67616d0000b273a6f59f5b55e45037b88b7b01","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:1uxoxQ1KHoHxO8GTYSe0kO in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:1uxoxQ1KHoHxO8GTYSe0kO
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:3xNsHKqsBYt4aV90Bp4l5Y in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:3xNsHKqsBYt4aV90Bp4l5Y
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7JTyXQErhpjBJMVKEmL2MZ","service":"spop","name":"Les jeux sont faits","artist":"Fredrika Stahl","album":"A Fraction Of You","type":"song","duration":217,"albumart":"https://i.scdn.co/image/ab67616d0000b27333267b7aaa9c0df627789be1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3mP8MIDvxxeCo3vx1MHeri","service":"spop","name":"Seule ce soir","artist":"Emilie-Claire Barlow","album":"Seule ce soir","type":"song","duration":365,"albumart":"https://i.scdn.co/image/ab67616d0000b273e80259504053fa2a7099cac1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:6mW4mrJtGsUNWXtO0rzg2i in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:6mW4mrJtGsUNWXtO0rzg2i
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1uxoxQ1KHoHxO8GTYSe0kO","service":"spop","name":"Le soir","artist":"Biréli Lagrène","album":"Gipsy Trio","type":"song","duration":250,"albumart":"https://i.scdn.co/image/ab67616d0000b273d3e472762ee43dccbf2b9068","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:6hOXorsfbtCqWZ53bTsspU in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:6hOXorsfbtCqWZ53bTsspU
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:6rAH7LYZyxS026YWxYOqvA in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:6rAH7LYZyxS026YWxYOqvA
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3xNsHKqsBYt4aV90Bp4l5Y","service":"spop","name":"Le chien d'avant garde","artist":"Keren Ann","album":"La disparition","type":"song","duration":238,"albumart":"https://i.scdn.co/image/ab67616d0000b273a2387751c48ab4451ea19962","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:2ZeHwwyO4hRMKYk5L1uke6 in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:2ZeHwwyO4hRMKYk5L1uke6
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6mW4mrJtGsUNWXtO0rzg2i","service":"spop","name":"Juste quelqu'un de bien","artist":"Enzo Enzo","album":"Deux","type":"song","duration":247,"albumart":"https://i.scdn.co/image/ab67616d0000b2737fdb508a7dbde50acb050008","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:5xxJz9J4bVAda0b0k1G8tP in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:5xxJz9J4bVAda0b0k1G8tP
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6hOXorsfbtCqWZ53bTsspU","service":"spop","name":"Mon fantôme","artist":"Baptiste Trotignon","album":"Song, Song, Song","type":"song","duration":261,"albumart":"https://i.scdn.co/image/ab67616d0000b273e9c5dc4b77bb1b7965d7bb05","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6rAH7LYZyxS026YWxYOqvA","service":"spop","name":"Assedic","artist":"LES ESCROCS","album":"Faites vous des amis","type":"song","duration":265,"albumart":"https://i.scdn.co/image/ab67616d0000b2731a7e91c14e2f99267d76bc0f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:5nRYOuYInJeQWZR3r65wfJ in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:5nRYOuYInJeQWZR3r65wfJ
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:3rUVcKmdmAjJEt0Zx7nSL5 in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:3rUVcKmdmAjJEt0Zx7nSL5
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5xxJz9J4bVAda0b0k1G8tP","service":"spop","name":"J'ai Vu","artist":"DANIEL ROURE","album":"Le Temps D'un Jazz","type":"song","duration":332,"albumart":"https://i.scdn.co/image/ab67616d0000b273bcadece1f892e877b381a2a6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2ZeHwwyO4hRMKYk5L1uke6","service":"spop","name":"La Mer","artist":"Chantal Chamberland","album":"The Other Woman","type":"song","duration":230,"albumart":"https://i.scdn.co/image/ab67616d0000b273bcfe2118646ff4724a8ab305","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:7oerc6eVjPLonOvtJq2qp3 in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:7oerc6eVjPLonOvtJq2qp3
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5nRYOuYInJeQWZR3r65wfJ","service":"spop","name":"C'est Magnifique","artist":"Patricia Barber","album":"The Cole Porter Mix","type":"song","duration":217,"albumart":"https://i.scdn.co/image/ab67616d0000b2733affec6cf25b0273f26e8525","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:7k125cYjRfIYB23FOQTeTy in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:7k125cYjRfIYB23FOQTeTy
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3rUVcKmdmAjJEt0Zx7nSL5","service":"spop","name":"Que reste t-il de nos amours","artist":"Cyntia M.","album":"Bistro Blue","type":"song","duration":211,"albumart":"https://i.scdn.co/image/ab67616d0000b27305908df1bc3f035add42c0e9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:58aPWEzZwi7iEptm6l7Nz5 in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:58aPWEzZwi7iEptm6l7Nz5
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7oerc6eVjPLonOvtJq2qp3","service":"spop","name":"I Wish You Love","artist":"Chantal Chamberland","album":"The Other Woman","type":"song","duration":171,"albumart":"https://i.scdn.co/image/ab67616d0000b273bcfe2118646ff4724a8ab305","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:654RprVvr0L8l6wm7XEHci in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:654RprVvr0L8l6wm7XEHci
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7k125cYjRfIYB23FOQTeTy","service":"spop","name":"Menilmontant","artist":"Zazou","album":"Merle Noir","type":"song","duration":289,"albumart":"https://i.scdn.co/image/ab67616d0000b273778a12fb9cdc9fa5add0c589","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:28t1r5jQcliVMX6CKE8pkc in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:28t1r5jQcliVMX6CKE8pkc
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:58aPWEzZwi7iEptm6l7Nz5","service":"spop","name":"Tous les garçons et les filles","artist":"Zona Sul","album":"Beira","type":"song","duration":260,"albumart":"https://i.scdn.co/image/ab67616d0000b2731cd30088960b1d161b289393","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:73vUl3nSQf7SwSGDDkTKCd in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:73vUl3nSQf7SwSGDDkTKCd
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:654RprVvr0L8l6wm7XEHci","service":"spop","name":"Une Belle Histoire","artist":"Eva sur Seine","album":"Eva sur Seine","type":"song","duration":309,"albumart":"https://i.scdn.co/image/ab67616d0000b2736626c7b801202b95e1d83c8f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:76yz1HdkCglnsSVyIjy1YS in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:76yz1HdkCglnsSVyIjy1YS
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:3ePsmfhb7hduvnDadoNNyi in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:3ePsmfhb7hduvnDadoNNyi
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:28t1r5jQcliVMX6CKE8pkc","service":"spop","name":"Comment Te Dire Adieu","artist":"String Swing","album":"Waiting For The Good Times","type":"song","duration":196,"albumart":"https://i.scdn.co/image/ab67616d0000b2730ab39d6e885f127b2d1a2263","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:73vUl3nSQf7SwSGDDkTKCd","service":"spop","name":"Poisson Rouge","artist":"Saint Privat","album":"Superflu","type":"song","duration":151,"albumart":"https://i.scdn.co/image/ab67616d0000b273a672bab3a32a346b1c76b4d4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:13 main volumio[851]: info: Exploding uri spotify:track:1tLf0h0lt7QEJaZtyVdRrB in service spop
> Aug 14 13:51:13 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:1tLf0h0lt7QEJaZtyVdRrB
> Aug 14 13:51:14 main volumio[851]: info: Exploding uri spotify:track:7yzUHiCgF7JOzJOFE0Bnpd in service spop
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:7yzUHiCgF7JOzJOFE0Bnpd
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:76yz1HdkCglnsSVyIjy1YS","service":"spop","name":"Désuets","artist":"Stacey Kent","album":"Raconte-Moi","type":"song","duration":189,"albumart":"https://i.scdn.co/image/ab67616d0000b273641d45fff46f5332abe9dd0b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:14 main volumio[851]: info: Exploding uri spotify:track:23N8i7mAfbKfOWi0xD7v0f in service spop
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:23N8i7mAfbKfOWi0xD7v0f
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3ePsmfhb7hduvnDadoNNyi","service":"spop","name":"Les eaux de mars","artist":"Stacey Kent","album":"Raconte-Moi","type":"song","duration":218,"albumart":"https://i.scdn.co/image/ab67616d0000b273641d45fff46f5332abe9dd0b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:14 main volumio[851]: info: Exploding uri spotify:track:1cfxSquzIuVUXxG7yfUmwF in service spop
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:1cfxSquzIuVUXxG7yfUmwF
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1tLf0h0lt7QEJaZtyVdRrB","service":"spop","name":"April In Paris","artist":"Billie Holiday","album":"All Or Nothing At All","type":"song","duration":185,"albumart":"https://i.scdn.co/image/ab67616d0000b2732fff95cdecc441f0f12e2c3c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7yzUHiCgF7JOzJOFE0Bnpd","service":"spop","name":"L'ombre et la lumière","artist":"Coralie Clement","album":"Salle des pas perdus","type":"song","duration":248,"albumart":"https://i.scdn.co/image/ab67616d0000b27336289d656815dee4b657acb6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:14 main volumio[851]: info: Exploding uri spotify:track:08T5wMbEnPN8ghT8o24KY6 in service spop
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:08T5wMbEnPN8ghT8o24KY6
> Aug 14 13:51:14 main volumio[851]: info: Exploding uri spotify:track:5GWys8RxfQAAVxdiW1yN2p in service spop
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:5GWys8RxfQAAVxdiW1yN2p
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1cfxSquzIuVUXxG7yfUmwF","service":"spop","name":"Just Like Heaven","artist":"Kat Edmonson","album":"Take To The Sky","type":"song","duration":252,"albumart":"https://i.scdn.co/image/ab67616d0000b273f87dab2c046b1c32b99aed25","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:23N8i7mAfbKfOWi0xD7v0f","service":"spop","name":"Samba Saravah","artist":"Stacey Kent","album":"Breakfast on the Morning Tram","type":"song","duration":229,"albumart":"https://i.scdn.co/image/ab67616d0000b27372fb9383a4e394271146d94c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:14 main volumio[851]: info: Exploding uri spotify:track:4zXKbHN9FKRTIirYQdMRqI in service spop
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:4zXKbHN9FKRTIirYQdMRqI
> Aug 14 13:51:14 main volumio[851]: info: Preload queue cleared
> Aug 14 13:51:14 main volumio[851]: info: CoreCommandRouter::volumioReplaceandPlayItems
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::ClearQueue
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::stop
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined
> Aug 14 13:51:14 main volumio[851]: info: CorePlayQueue::clearPlayQueue
> Aug 14 13:51:14 main volumio[851]: info: CorePlayQueue::saveQueue
> Aug 14 13:51:14 main volumio[851]: info: CoreCommandRouter::volumioPushQueue
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::addQueueItems
> Aug 14 13:51:14 main volumio[851]: info: CorePlayQueue::addQueueItems
> Aug 14 13:51:14 main volumio[851]: info: Preload queue cleared
> Aug 14 13:51:14 main volumio[851]: info: Adding Item to queue: spotify:user:spotify:playlist:0KtmIaJxqUAtwIq4JG5vOM
> Aug 14 13:51:14 main volumio[851]: info: Using cached record of: spotify:user:spotify:playlist:0KtmIaJxqUAtwIq4JG5vOM
> Aug 14 13:51:14 main volumio[851]: info: CoreCommandRouter::volumioPushQueue
> Aug 14 13:51:14 main volumio[851]: info: CorePlayQueue::saveQueue
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::updateTrackBlock
> Aug 14 13:51:14 main volumio[851]: info: CorePlayQueue::getTrackBlock
> Aug 14 13:51:14 main volumio[851]: info: CoreCommandRouter::volumioPlay
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::play index 0
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::stop
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::play index undefined
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined
> Aug 14 13:51:14 main volumio[851]: info: CorePlayQueue::getTrack 0
> Aug 14 13:51:14 main volumio[851]: info: CoreStateMachine::startPlaybackTimer
> Aug 14 13:51:14 main volumio[851]: info: CorePlayQueue::getTrack 0
> Aug 14 13:51:14 main volumio[851]: info: [1723632674302] ControllerSpotify::clearAddPlayTrack
> Aug 14 13:51:14 main volumio[851]: info: Sending Spotify command with payload to local API: /player/play
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:08T5wMbEnPN8ghT8o24KY6","service":"spop","name":"Bistro Fada","artist":"Stephane Wrembel","album":"Bistro Fada","type":"song","duration":182,"albumart":"https://i.scdn.co/image/ab67616d0000b2736c4e1ea26e08b3be90b3c5a4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5GWys8RxfQAAVxdiW1yN2p","service":"spop","name":"Come on Eileen","artist":"Nouvelle Vague","album":"Late Night Tales: Nouvelle Vague","type":"song","duration":201,"albumart":"https://i.scdn.co/image/ab67616d0000b273b96c98b54bca5e954576cc9e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]
> Aug 14 13:51:14 main volumio[851]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4zXKbHN9FKRTIirYQdMRqI","service":"spop","name":"Samba de mon cœur qui bat","artist":"Coralie Clement","album":"Salle des pas perdus","type":"song","duration":233,"albumart":"https://i.scdn.co/image/ab67616d0000b27336289d656815dee4b657acb6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}]

jerickson721 · August 17, 2024, 9:07pm

Updated to Volumio 3.742 with same Spotify 4.1.0. I was having the following issues with prior versions and ran into two instances of a go-librespot crash:

Songs that won’t play on Volumio but play on Spotify iOS and Mac (potentially same/similar issue to sciensys earlier)
Issues with Spotify queue clearing/disappearing when playing on Volumio (see consistent repro below)

While trying to create a repro for the Spotify queue issue with Volumio, I ran into the crash below twice. Here is a consistent repro for Spotify queue issues with Volumio:

Play a playlist on Volumio from iOS (confirmed OS and Spotify on latest)
Add a few songs to queue while playlist is playing
On iOS Spotify app attempt to change the order of your queue

Expected: Queue order adjusts without dropping songs (confirmed this works as expected with an Amazon Echo device)
Actual: Every time you change the order of a song in queue a song is dropped from the Spotify queue. This is typically but not always the top-most song

While checking consistency of repro above I hit the following crash twice which I’m guessing is a timing issue with the queue going empty just before it is about to play a song from the queue. Once it hits this crash, Volumio was unable to recover and required not only a shutdown but full disconnect from power (simple restart persisted I2C errors):

Aug 17 13:48:55 justin-volumio go-librespot[1095]: time="2024-08-17T13:48:55-07:00" level=debug msg="sending successful reply for dealer request"
Aug 17 13:48:55 justin-volumio volumio[911]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6Owc2SuzwO3LW1SAODYK3l","name":"Melody","artist_names":["Sigala"],"album_name":"Melody","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0201649797af71d97b8f53ebf3","position":0,"duration":167142,"release_date":"year:2022 month:1 day:21","track_number":1,"disc_number":1}}
Aug 17 13:48:55 justin-volumio go-librespot[1095]: time="2024-08-17T13:48:55-07:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:6Owc2SuzwO3LW1SAODYK3l"
Aug 17 13:48:55 justin-volumio go-librespot[1095]: time="2024-08-17T13:48:55-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 17 13:48:55 justin-volumio go-librespot[1095]: time="2024-08-17T13:48:55-07:00" level=trace msg="emitting websocket event: playing"
Aug 17 13:48:55 justin-volumio volumio[911]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6Owc2SuzwO3LW1SAODYK3l","play_origin":"playlist"}}
Aug 17 13:48:55 justin-volumio volumio[911]: SPOTIFY: PUSH STATE SPOTIFY
Aug 17 13:48:55 justin-volumio volumio[911]: SPOTIFY: {"status":"play","service":"spop","title":"Melody","artist":"Sigala","album":"Melody","albumart":"https://i.scdn.co/image/ab67616d00001e0201649797af71d97b8f53ebf3","uri":"spotify:track:6Owc2SuzwO3LW1SAODYK3l","trackType":"spotify","seek":0,"duration":167,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":false,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"}
Aug 17 13:48:55 justin-volumio volumio[911]: info: CoreCommandRouter::servicePushState
Aug 17 13:48:55 justin-volumio volumio[911]: info: CoreStateMachine::pushState
Aug 17 13:48:55 justin-volumio volumio[911]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 17 13:48:55 justin-volumio volumio[911]: info: CoreCommandRouter::volumioPushState
Aug 17 13:48:55 justin-volumio volumio[911]: SPOTIFY: PUSH STATE SPOTIFY
Aug 17 13:48:55 justin-volumio volumio[911]: SPOTIFY: {"status":"play","service":"spop","title":"Melody","artist":"Sigala","album":"Melody","albumart":"https://i.scdn.co/image/ab67616d00001e0201649797af71d97b8f53ebf3","uri":"spotify:track:6Owc2SuzwO3LW1SAODYK3l","trackType":"spotify","seek":1000,"duration":167,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":false,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"}
Aug 17 13:48:55 justin-volumio volumio[911]: info: CoreCommandRouter::servicePushState
Aug 17 13:48:55 justin-volumio volumio[911]: info: CoreStateMachine::pushState
Aug 17 13:48:55 justin-volumio volumio[911]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 17 13:48:55 justin-volumio volumio[911]: info: CoreCommandRouter::volumioPushState
Aug 17 13:49:07 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:07-07:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:6Owc2SuzwO3LW1SAODYK3l"
Aug 17 13:49:08 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:08-07:00" level=debug msg="handling add_to_queue player command from 9eda0ba692653833edff1c733595c03d39826acc"
Aug 17 13:49:08 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:08-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 17 13:49:08 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:08-07:00" level=trace msg="scheduling prefetch in 123s"
Aug 17 13:49:08 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:08-07:00" level=debug msg="sending successful reply for dealer request"
Aug 17 13:49:13 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:13-07:00" level=debug msg="handling set_queue player command from ce34ae43b66d247156df6dcec20bb4173c7f5ad0"
Aug 17 13:49:13 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:13-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Aug 17 13:49:13 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:13-07:00" level=trace msg="scheduling prefetch in 118s"
Aug 17 13:49:13 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:13-07:00" level=debug msg="sending successful reply for dealer request"
Aug 17 13:49:18 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:18-07:00" level=debug msg="fetched chunk 5/14, size: 524288" uri="spotify:track:6Owc2SuzwO3LW1SAODYK3l"
Aug 17 13:49:21 justin-volumio go-librespot[1095]: time="2024-08-17T13:49:21-07:00" level=debug msg="handling skip_next player command from ce34ae43b66d247156df6dcec20bb4173c7f5ad0"
Aug 17 13:49:21 justin-volumio go-librespot[1095]: panic: runtime error: slice bounds out of range [1:0]
Aug 17 13:49:21 justin-volumio go-librespot[1095]: goroutine 204 gp=0x1209328 m=8 mp=0x1080588 [running]:
Aug 17 13:49:21 justin-volumio go-librespot[1095]: panic({0x623058, 0x1756240})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/panic.go:779 +0x12c fp=0x151b530 sp=0x151b4dc pc=0x58364
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goPanicSliceB(0x1, 0x0)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/panic.go:154 +0xa4 fp=0x151b550 sp=0x151b530 pc=0x5717c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: go-librespot/tracks.(*List).GoNext(0x128a150)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/tracks/tracks.go:177 +0x1c0 fp=0x151b578 sp=0x151b550 pc=0x4ac290
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*AppPlayer).advanceNext(0x1112e10, 0x1)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/controls.go:460 +0x60 fp=0x151b668 sp=0x151b578 pc=0x5763b8
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*AppPlayer).skipNext(0x1112e10)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/controls.go:433 +0x24 fp=0x151b6a4 sp=0x151b668 pc=0x5761f8
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*AppPlayer).handlePlayerCommand(0x1112e10, {0x621a1565, {0x0, 0x0}, {0x12ac060, 0x28}, {{0x1756220, 0x9}, {0x0, 0x0}, ...}})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/player.go:257 +0x624 fp=0x151b7c4 sp=0x151b6a4 pc=0x57b4d8
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*AppPlayer).handleDealerRequest(0x1112e10, {0x115e000, {0x12ac000, 0x24}, {0x621a1565, {0x0, 0x0}, {0x12ac060, 0x28}, {{0x1756220, ...}, ...}}})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/player.go:303 +0xe4 fp=0x151b8fc sp=0x151b7c4 pc=0x57cbb0
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*AppPlayer).Run(0x1112e10, 0x1076f80)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/player.go:442 +0x3d8 fp=0x151bfe0 sp=0x151b8fc pc=0x57df84
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*App).withAppPlayer.func3.gowrap1()
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:321 +0x30 fp=0x151bfec sp=0x151bfe0 pc=0x578d60
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goexit({})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x151bfec sp=0x151bfec pc=0x9346c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: created by main.(*App).withAppPlayer.func3 in goroutine 1
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:321 +0x2f8
Aug 17 13:49:21 justin-volumio go-librespot[1095]: goroutine 1 gp=0x1002128 m=nil [select, 12 minutes]:
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gopark(0x68f774, 0x0, 0x9, 0x3, 0x1)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1285d68 sp=0x1285d54 pc=0x5c82c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.selectgo(0x1285e68, 0x10b7e34, 0x0, 0x0, 0x2, 0x1)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/select.go:327 +0xaf0 fp=0x1285e08 sp=0x1285d68 pc=0x705e4
Aug 17 13:49:21 justin-volumio go-librespot[1095]: go-librespot/zeroconf.(*Zeroconf).Serve(0x130c0a0, 0x1285ee4)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/zeroconf/zeroconf.go:268 +0x228 fp=0x1285eac sp=0x1285e08 pc=0x528ad8
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*App).withAppPlayer(0x111e180, 0x68f0d4)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:297 +0x4b0 fp=0x1285f1c sp=0x1285eac pc=0x578904
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*App).Zeroconf(...)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:127
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.main()
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:458 +0x78c fp=0x1285fa8 sp=0x1285f1c pc=0x57a180
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.main()
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:271 +0x2fc fp=0x1285fec sp=0x1285fa8 pc=0x5c29c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goexit({})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1285fec sp=0x1285fec pc=0x9346c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: goroutine 18 gp=0x1084248 m=nil [force gc (idle), 15 minutes]:
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gopark(0x68f740, 0xaa84c0, 0x11, 0xa, 0x1)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x103e7d4 sp=0x103e7c0 pc=0x5c82c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goparkunlock(...)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:408
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.forcegchelper()
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:326 +0xe4 fp=0x103e7ec sp=0x103e7d4 pc=0x5c668
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goexit({})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x103e7ec sp=0x103e7ec pc=0x9346c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: created by runtime.init.5 in goroutine 1
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:314 +0x1c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: goroutine 19 gp=0x1084368 m=nil [GC sweep wait]:
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gopark(0x68f740, 0xaa8a10, 0xc, 0x9, 0x1)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x103efc4 sp=0x103efb0 pc=0x5c82c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goparkunlock(...)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:408
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.bgsweep(0x1092000)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgcsweep.go:318 +0x11c fp=0x103efe4 sp=0x103efc4 pc=0x4506c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gcenable.gowrap1()
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:203 +0x28 fp=0x103efec sp=0x103efe4 pc=0x3518c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goexit({})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x103efec sp=0x103efec pc=0x9346c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: created by runtime.gcenable in goroutine 1
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:203 +0x74
Aug 17 13:49:21 justin-volumio go-librespot[1095]: goroutine 20 gp=0x1084488 m=nil [GC scavenge wait]:
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gopark(0x68f740, 0xaa9020, 0xd, 0xa, 0x2)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x103f7b4 sp=0x103f7a0 pc=0x5c82c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goparkunlock(...)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:408
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.(*scavengerState).park(0xaa9020)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgcscavenge.go:425 +0x68 fp=0x103f7c8 sp=0x103f7b4 pc=0x4238c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.bgscavenge(0x1092000)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgcscavenge.go:658 +0x60 fp=0x103f7e4 sp=0x103f7c8 pc=0x42ac4
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gcenable.gowrap2()
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:204 +0x28 fp=0x103f7ec sp=0x103f7e4 pc=0x35138
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goexit({})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x103f7ec sp=0x103f7ec pc=0x9346c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: created by runtime.gcenable in goroutine 1
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mgc.go:204 +0xbc
Aug 17 13:49:21 justin-volumio go-librespot[1095]: goroutine 2 gp=0x1002c68 m=nil [finalizer wait]:
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gopark(0x68f5ec, 0xad3bac, 0x10, 0xa, 0x1)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x1042f8c sp=0x1042f78 pc=0x5c82c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.runfinq()
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mfinal.go:194 +0x110 fp=0x1042fec sp=0x1042f8c pc=0x33f78
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goexit({})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x1042fec sp=0x1042fec pc=0x9346c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: created by runtime.createfing in goroutine 1
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/mfinal.go:164 +0x5c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: goroutine 34 gp=0x1106488 m=nil [IO wait, 15 minutes]:
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gopark(0x68f730, 0x7606ded8, 0x2, 0x2, 0x5)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/proc.go:402 +0x104 fp=0x117a5dc sp=0x117a5c8 pc=0x5c82c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.netpollblock(0x7606dec8, 0x72, 0x0)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:573 +0x100 fp=0x117a5f4 sp=0x117a5dc pc=0x540f0
Aug 17 13:49:21 justin-volumio go-librespot[1095]: internal/poll.runtime_pollWait(0x7606dec8, 0x72)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/netpoll.go:345 +0x54 fp=0x117a608 sp=0x117a5f4 pc=0x8eba8
Aug 17 13:49:21 justin-volumio go-librespot[1095]: internal/poll.(*pollDesc).wait(0x1112ba8, 0x72, 0x0)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x117a61c sp=0x117a608 pc=0x108108
Aug 17 13:49:21 justin-volumio go-librespot[1095]: internal/poll.(*pollDesc).waitRead(...)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_poll_runtime.go:89
Aug 17 13:49:21 justin-volumio go-librespot[1095]: internal/poll.(*FD).Accept(0x1112b90)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/internal/poll/fd_unix.go:611 +0x294 fp=0x117a664 sp=0x117a61c pc=0x10c974
Aug 17 13:49:21 justin-volumio go-librespot[1095]: net.(*netFD).accept(0x1112b90)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/net/fd_unix.go:172 +0x20 fp=0x117a6cc sp=0x117a664 pc=0x2a24f4
Aug 17 13:49:21 justin-volumio go-librespot[1095]: net.(*TCPListener).accept(0x112a270)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/net/tcpsock_posix.go:159 +0x20 fp=0x117a6e4 sp=0x117a6cc pc=0x2ba5f4
Aug 17 13:49:21 justin-volumio go-librespot[1095]: net.(*TCPListener).Accept(0x112a270)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/net/tcpsock.go:327 +0x30 fp=0x117a700 sp=0x117a6e4 pc=0x2b9660
Aug 17 13:49:21 justin-volumio go-librespot[1095]: net/http.(*onceCloseListener).Accept(0x1073560)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         :1 +0x34 fp=0x117a718 sp=0x117a700 pc=0x45e904
Aug 17 13:49:21 justin-volumio go-librespot[1095]: net/http.(*Server).Serve(0x1193408, {0x724fbc, 0x112a270})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:3255 +0x314 fp=0x117a7b0 sp=0x117a718 pc=0x43cfc0
Aug 17 13:49:21 justin-volumio go-librespot[1095]: net/http.Serve(...)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/net/http/server.go:2794
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.(*ApiServer).serve(0x112ed00)
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:470 +0x5ec fp=0x117a7e4 sp=0x117a7b0 pc=0x5706a4
Aug 17 13:49:21 justin-volumio go-librespot[1095]: main.NewApiServer.gowrap1()
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:240 +0x28 fp=0x117a7ec sp=0x117a7e4 pc=0x56fd78
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.goexit({})
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/asm_arm.s:859 +0x4 fp=0x117a7ec sp=0x117a7ec pc=0x9346c
Aug 17 13:49:21 justin-volumio go-librespot[1095]: created by main.NewApiServer in goroutine 1
Aug 17 13:49:21 justin-volumio go-librespot[1095]:         /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:240 +0x224
Aug 17 13:49:21 justin-volumio go-librespot[1095]: goroutine 41 gp=0x11066c8 m=nil [GC worker (idle)]:
Aug 17 13:49:21 justin-volumio go-librespot[1095]: runtime.gopark(0x68f5fc, 0x1029cc8, 0x1a, 0xa, 0x0)

sciensys · August 19, 2024, 2:47pm

Today I completely re-flashed the microSD of two RPI4 devices.
sv: 7.742
spotify: 4.1.0
AutoStart: 3.0.4
No additional software was installed for testing clear work of volumio and spotify.

Spotify started playing.
But within an hour I found it stopped again. I plan to catch the logs.
The radio works as before, sometimes it stops once every 3-5 days, until I caught the stop log.

Brunnis · August 20, 2024, 10:17am

New user here. Just set up Volumio on a Pi 4, installed the Spotify plug-in (and authorized the device with Spotify) and Fusion DSP. It’s looking quite good so far. One problem I’m having now, though, is that if I connect to Volumio from my desktop Spotify application via Spotify Connect and play songs in my playlists, only the first 25 songs play correctly. Trying to play song 26 and onwards will always result in playing the first song in the playlist instead. This goes for any of my playlists. The problem does not seem to appear if I use the iPhone Spotify app instead of the Windows desktop one.

Is this a known issue and is it perhaps a Spotify issue and not something Volumio can control?

devgianlu · August 21, 2024, 8:00am

@jerickson721 Thank you for reporting! I’ll address the issues you mentioned:

Would you mind sharing some tracks that do not play on Volumio, but do on the official client? I am yet to find any that do it for me. You can post them on issue #55, or even here.
I can reproduce some strange behaviors with reordering the queue and tracking them as issue #73. Unluckily I don’t have an iOS device to test your exact steps, but some strange stuff happens on Android too.
The crash has been fixed as of commit cdd6a53c and will be in the next release.

@Brunnis The issue has already been fixed with pull request #71 by @tooxo, but won’t make it into Volumio until the next release.

Brunnis · August 21, 2024, 9:04am

That’s great to hear! Thank you.

jerickson721 · August 21, 2024, 4:11pm

Thanks @devgianlu for the updates and quick fix for the crash:

PR #71 explains the issue I’ve seen so far with songs not playing on Volumio since the update to Volumio 3.742 (with same Spotify 4.1.0). I’ll post an update with song/repro if I find other issues with songs that won’t play on Volumio with the latest Volumio 3.742
For queues, I can’t tell if they’re symptoms of the same underlying issue or not but have basically found queues with Spotify “Jams” from two devices very unstable since the New 2023 Spotify Plugin (it used to work fine previous to the latest). I started with trying to find and post the first consistent repro. Basically listening on Volumio and adding songs to the queue from two devices most often ends up at some point clearing/dropping the queue entirely

sciensys · August 31, 2024, 10:27am

Clear instance still works like as it should!

Thank everyone who worked of that.

I continue to observe.

GlennBurnett · September 2, 2024, 5:49pm

Hi Guys,

I just found and inconsistency in the loading on Spotify tracks from all other music sources (Local music, Pandora & web radio). It appears the new plugin uses the “name” instead of “title” when loading playlists. Spotify provides both, however Volumio wont load a track without the “title” key. The impact is that playlists that have both local (NAS) tracks and Spotify tracks the Spotify tracks are ignored, this is new behavior from older versions of the plugin.

See the below examples.

from http://volumio3dev/api/v1/getqueue

{
  "queue": [
    {
      "uri": "spotify:track:0pYJaPb80f8Ye86b2qXurN",
      "service": "spop",
      "name": "Gordon R Freestyle",
      "artist": "Remble",
      "album": "Gordon R Freestyle",
      "type": "song",
      "duration": 125,
      "albumart": "https://i.scdn.co/image/ab67616d0000b2733ac507f94bd63555d002ce80",
      "samplerate": "320 kbps",
      "bitdepth": "16 bit",
      "bitrate": "",
      "codec": "ogg",
      "trackType": "spotify"
    },
    {
      "uri": "spotify:track:0si0BqHFccbmGENDvATw2g",
      "service": "spop",
      "name": "Mind of a Real",
      "artist": "T9ine",
      "album": "From Nun To Something",
      "type": "song",
      "duration": 153,
      "albumart": "https://i.scdn.co/image/ab67616d0000b273f614be1074aff9e17145a42c",
      "samplerate": "320 kbps",
      "bitdepth": "16 bit",
      "bitrate": "",
      "codec": "ogg",
      "trackType": "spotify"
    },

and from http://volumio3dev/api/v1/browse?uri=spotify:user:spotify:playlist:**********************

{
  "navigation": {
    "prev": {
      "uri": "spotify"
    },
    "lists": [
      {
        "availableListViews": [
          "list"
        ],
        "items": [
          {
            "service": "spop",
            "type": "song",
            "name": "Losing Sleep",
            "title": "Losing Sleep",
            "artist": "Curbi",
            "album": "Losing Sleep",
            "uri": "spotify:track:0kbd4eKn7jyHTjdIBX6aZk",
            "samplerate": "320 kbps",
            "bitdepth": "16 bit",
            "bitrate": "",
            "codec": "ogg",
            "trackType": "spotify",
            "albumart": "https://i.scdn.co/image/ab67616d0000b273f0ef046220f0bd8ccf6797de",
            "duration": 169
          },
          {
            "service": "spop",
            "type": "song",
            "name": "Gotta Be You",
            "title": "Gotta Be You",
            "artist": "NERVO",
            "album": "Gotta Be You",
            "uri": "spotify:track:2Q8fFORnsDE6I3RNvSLXSf",
            "samplerate": "320 kbps",
            "bitdepth": "16 bit",
            "bitrate": "",
            "codec": "ogg",
            "trackType": "spotify",
            "albumart": "https://i.scdn.co/image/ab67616d0000b27329204e387d2575124fbb2811",
            "duration": 149
          },

sciensys · September 5, 2024, 3:00pm

Spotify plugin work with long pauses, skips tracks on the following equipment:
RP 4B+
Suptronics X450 - 200 watt amplifier - hardware - software
PS 350Watt, out 2x24V
Volumio 3.742 (clear instance)
Spotify plugin 4.1.0
Spotify Premium subscription
DAC Model: HiFIBerry DAC

~68 seconds player show playing but no sound
then player skiping to next track, but play previos track (somewhere in middle or at the end of track)
in 5 seconds, plays new track
and that stable.

Any ideas ?

log:

Sep 05 16:34:34 liv volumio[796]: info: CorePlayQueue::getTrack 0
Sep 05 16:34:34 liv volumio[796]: info: CorePlayQueue::getTrack 1
Sep 05 16:34:34 liv volumio[796]: info: Prefetching next song
Sep 05 16:34:34 liv volumio[796]: info: [1725543274624] ControllerSpotify::prefetch
Sep 05 16:34:34 liv volumio[796]: info: Sending Spotify command with payload to local API: /player/add_to_queue
Sep 05 16:34:37 liv go-librespot[1666]: time="2024-09-05T16:34:37+03:00" level=trace msg="cleared closed output device"
Sep 05 16:34:39 liv volumio[796]: info: CoreStateMachine::startPlaybackTimer
Sep 05 16:34:39 liv volumio[796]: info: CorePlayQueue::getTrack 1
Sep 05 16:34:39 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:34:39 liv volumio[796]: info: CorePlayQueue::getTrack 1
Sep 05 16:34:39 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:34:39 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:34:50 liv systemd[1]: Starting Cleanup of Temporary Directories...
Sep 05 16:34:50 liv systemd[1]: systemd-tmpfiles-clean.service: Succeeded.
Sep 05 16:34:50 liv systemd[1]: Started Cleanup of Temporary Directories.
Sep 05 16:35:41 liv go-librespot[1666]: time="2024-09-05T16:35:41+03:00" level=error msg="failed put state after update" error="put state request failed with status 400: Missing payload"
Sep 05 16:35:41 liv go-librespot[1666]: time="2024-09-05T16:35:41+03:00" level=trace msg="scheduling prefetch in 119s"
Sep 05 16:35:41 liv go-librespot[1666]: time="2024-09-05T16:35:41+03:00" level=trace msg="emitting websocket event: not_playing"
Sep 05 16:35:41 liv go-librespot[1666]: time="2024-09-05T16:35:41+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:41 liv volumio[796]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:5TZnCu5vibZW8AqEFgsqgY","play_origin":"go-librespot"}}
Sep 05 16:35:41 liv volumio[796]: error: Failed to decode event: not_playing
Sep 05 16:35:41 liv volumio[796]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:5TZnCu5vibZW8AqEFgsqgY","play_origin":"go-librespot"}}
Sep 05 16:35:41 liv volumio[796]: error: Failed to decode event: not_playing
Sep 05 16:35:42 liv go-librespot[1666]: time="2024-09-05T16:35:42+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:35:42 liv go-librespot[1666]: time="2024-09-05T16:35:42+03:00" level=trace msg="emitting websocket event: will_play"
Sep 05 16:35:42 liv volumio[796]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4eSw6hVL8UAxa0dAjKi5YP","play_origin":"go-librespot"}}
Sep 05 16:35:44 liv go-librespot[1666]: time="2024-09-05T16:35:44+03:00" level=debug msg="selected format OGG_VORBIS_320 (ef9c84f0f47d5394a879206eda44b2bb845a1391)" uri="spotify:track:4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:44 liv go-librespot[1666]: time="2024-09-05T16:35:44+03:00" level=debug msg="requested aes key for file ef9c84f0f47d5394a879206eda44b2bb845a1391, gid: 4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:50 liv go-librespot[1666]: time="2024-09-05T16:35:50+03:00" level=debug msg="fetched first chunk of 14, total size is 6946516 bytes" uri="spotify:track:4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:50 liv go-librespot[1666]: time="2024-09-05T16:35:50+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:50 liv go-librespot[1666]: time="2024-09-05T16:35:50+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames"
Sep 05 16:35:50 liv go-librespot[1666]: time="2024-09-05T16:35:50+03:00" level=debug msg="created new output device"
Sep 05 16:35:50 liv go-librespot[1666]: time="2024-09-05T16:35:50+03:00" level=info msg="loaded track \"In Your Eyes\" (paused: false, position: 0ms, duration: 165993ms, prefetched: false)" uri="spotify:track:4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:50 liv go-librespot[1666]: time="2024-09-05T16:35:50+03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:51 liv go-librespot[1666]: time="2024-09-05T16:35:51+03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:52 liv go-librespot[1666]: time="2024-09-05T16:35:52+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:35:52 liv go-librespot[1666]: time="2024-09-05T16:35:52+03:00" level=trace msg="scheduling prefetch in 134s"
Sep 05 16:35:52 liv go-librespot[1666]: time="2024-09-05T16:35:52+03:00" level=trace msg="emitting websocket event: metadata"
Sep 05 16:35:52 liv go-librespot[1666]: time="2024-09-05T16:35:52+03:00" level=trace msg="emitting websocket event: stopped"
Sep 05 16:35:52 liv volumio[796]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4eSw6hVL8UAxa0dAjKi5YP","name":"In Your Eyes","artist_names":["INNA"],"album_name":"Party Never Ends, Pt. 1 (Deluxe Edition)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0221e639a53f2707d4b32f7faf","position":0,"duration":165993,"release_date":"year:2013 month:3 day:4","track_number":1,"disc_number":1}}
Sep 05 16:35:52 liv volumio[796]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4eSw6hVL8UAxa0dAjKi5YP","name":"In Your Eyes","artist_names":["INNA"],"album_name":"Party Never Ends, Pt. 1 (Deluxe Edition)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0221e639a53f2707d4b32f7faf","position":0,"duration":165993,"release_date":"year:2013 month:3 day:4","track_number":1,"disc_number":1}}
Sep 05 16:35:52 liv volumio[796]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Sep 05 16:35:52 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:35:52 liv volumio[796]: SPOTIFY: {"status":"stop","service":"spop","title":"In Your Eyes","artist":"INNA","album":"Party Never Ends, Pt. 1 (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e0221e639a53f2707d4b32f7faf","uri":"spotify:track:4eSw6hVL8UAxa0dAjKi5YP","trackType":"spotify","seek":0,"duration":165,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 1
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 1
Sep 05 16:35:52 liv volumio[796]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"In Your Eyes","artist":"INNA","album":"Party Never Ends, Pt. 1 (Deluxe Edition)","albumart":"https://i.scdn.co/image/ab67616d00001e0221e639a53f2707d4b32f7faf","uri":"spotify:track:4eSw6hVL8UAxa0dAjKi5YP","trackType":"spotify","seek":0,"duration":165,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:52 liv volumio[796]: verbose: CURRENT POSITION 1
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::syncState   stateService stop
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::play index undefined
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::startPlaybackTimer
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:52 liv volumio[796]: info: [1725543352553] ControllerSpotify::clearAddPlayTrack
Sep 05 16:35:52 liv volumio[796]: info: Sending Spotify command with payload to local API: /player/play
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:52 liv volumio[796]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Sep 05 16:35:52 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:35:52 liv volumio[796]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:52 liv volumio[796]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:52 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::syncState   stateService stop
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus stop
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:52 liv volumio[796]: info: No code
Sep 05 16:35:52 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:52 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:52 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:53 liv go-librespot[1666]: time="2024-09-05T16:35:53+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:35:53 liv go-librespot[1666]: time="2024-09-05T16:35:53+03:00" level=trace msg="emitting websocket event: playing"
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4eSw6hVL8UAxa0dAjKi5YP","play_origin":"go-librespot"}}
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:53 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus stop
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4eSw6hVL8UAxa0dAjKi5YP","play_origin":"go-librespot"}}
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:53 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:35:53 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:53 liv go-librespot[1666]: time="2024-09-05T16:35:53+03:00" level=debug msg="resolved context of track" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:35:53 liv go-librespot[1666]: time="2024-09-05T16:35:53+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:35:53 liv go-librespot[1666]: time="2024-09-05T16:35:53+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:53 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:35:53 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:35:53 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:35:53 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:35:53 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:53 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:35:53 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:35:53 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:35:54 liv go-librespot[1666]: time="2024-09-05T16:35:54+03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4eSw6hVL8UAxa0dAjKi5YP"
Sep 05 16:35:55 liv go-librespot[1666]: time="2024-09-05T16:35:55+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:35:55 liv go-librespot[1666]: time="2024-09-05T16:35:55+03:00" level=trace msg="emitting websocket event: will_play"
Sep 05 16:35:55 liv volumio[796]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","play_origin":"go-librespot"}}
Sep 05 16:35:55 liv volumio[796]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","play_origin":"go-librespot"}}
Sep 05 16:35:57 liv go-librespot[1666]: time="2024-09-05T16:35:57+03:00" level=debug msg="selected format OGG_VORBIS_320 (c29f0cf0892adb8f8e29a6c0801088a59568c13c)" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:35:57 liv go-librespot[1666]: time="2024-09-05T16:35:57+03:00" level=debug msg="requested aes key for file c29f0cf0892adb8f8e29a6c0801088a59568c13c, gid: 2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:00 liv go-librespot[1666]: time="2024-09-05T16:36:00+03:00" level=debug msg="fetched first chunk of 19, total size is 9836532 bytes" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:00 liv go-librespot[1666]: time="2024-09-05T16:36:00+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:00 liv go-librespot[1666]: time="2024-09-05T16:36:00+03:00" level=info msg="loaded track \"Love\" (paused: false, position: 0ms, duration: 218368ms, prefetched: false)" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:00 liv go-librespot[1666]: time="2024-09-05T16:36:00+03:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:00 liv go-librespot[1666]: time="2024-09-05T16:36:00+03:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:01 liv go-librespot[1666]: time="2024-09-05T16:36:01+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:36:01 liv go-librespot[1666]: time="2024-09-05T16:36:01+03:00" level=trace msg="scheduling prefetch in 187s"
Sep 05 16:36:01 liv go-librespot[1666]: time="2024-09-05T16:36:01+03:00" level=trace msg="emitting websocket event: metadata"
Sep 05 16:36:01 liv volumio[796]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","name":"Love","artist_names":["INNA"],"album_name":"Hot","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","position":0,"duration":218368,"release_date":"year:2010","track_number":3,"disc_number":1}}
Sep 05 16:36:01 liv volumio[796]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","name":"Love","artist_names":["INNA"],"album_name":"Hot","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","position":0,"duration":218368,"release_date":"year:2010","track_number":3,"disc_number":1}}
Sep 05 16:36:01 liv go-librespot[1666]: time="2024-09-05T16:36:01+03:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:02 liv go-librespot[1666]: time="2024-09-05T16:36:02+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:36:02 liv go-librespot[1666]: time="2024-09-05T16:36:02+03:00" level=trace msg="emitting websocket event: playing"
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","play_origin":"go-librespot"}}
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"Love","artist":"INNA","album":"Hot","albumart":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","trackType":"spotify","seek":1000,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Love","artist":"INNA","album":"Hot","albumart":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","trackType":"spotify","seek":1000,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:36:02 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:36:02 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","play_origin":"go-librespot"}}
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"Love","artist":"INNA","album":"Hot","albumart":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","trackType":"spotify","seek":1000,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Love","artist":"INNA","album":"Hot","albumart":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","trackType":"spotify","seek":1000,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:36:02 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:36:02 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"Love","artist":"INNA","album":"Hot","albumart":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","trackType":"spotify","seek":2000,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Love","artist":"INNA","album":"Hot","albumart":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","trackType":"spotify","seek":2000,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:36:02 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:36:02 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:36:02 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"Love","artist":"INNA","album":"Hot","albumart":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","trackType":"spotify","seek":2000,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Love","artist":"INNA","album":"Hot","albumart":"https://i.scdn.co/image/ab67616d00001e023d6413c7dc24318bdbd5b366","uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","trackType":"spotify","seek":2000,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:36:02 liv volumio[796]: verbose: CURRENT POSITION 2
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:36:02 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:36:02 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:36:02 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:36:02 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:36:12 liv go-librespot[1666]: time="2024-09-05T16:36:12+03:00" level=debug msg="fetched chunk 4/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:23 liv go-librespot[1666]: time="2024-09-05T16:36:23+03:00" level=debug msg="fetched chunk 5/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:34 liv go-librespot[1666]: time="2024-09-05T16:36:34+03:00" level=debug msg="fetched chunk 6/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:46 liv go-librespot[1666]: time="2024-09-05T16:36:46+03:00" level=debug msg="fetched chunk 7/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:36:58 liv go-librespot[1666]: time="2024-09-05T16:36:58+03:00" level=debug msg="fetched chunk 8/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:37:10 liv go-librespot[1666]: time="2024-09-05T16:37:10+03:00" level=debug msg="fetched chunk 9/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:37:21 liv go-librespot[1666]: time="2024-09-05T16:37:21+03:00" level=debug msg="fetched chunk 10/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:37:32 liv go-librespot[1666]: time="2024-09-05T16:37:32+03:00" level=debug msg="fetched chunk 11/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:37:46 liv go-librespot[1666]: time="2024-09-05T16:37:46+03:00" level=debug msg="fetched chunk 12/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:37:59 liv go-librespot[1666]: time="2024-09-05T16:37:59+03:00" level=debug msg="fetched chunk 13/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:38:11 liv go-librespot[1666]: time="2024-09-05T16:38:11+03:00" level=debug msg="fetched chunk 14/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:38:22 liv go-librespot[1666]: time="2024-09-05T16:38:22+03:00" level=debug msg="fetched chunk 15/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:38:32 liv go-librespot[1666]: time="2024-09-05T16:38:32+03:00" level=debug msg="fetched chunk 16/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:38:44 liv go-librespot[1666]: time="2024-09-05T16:38:44+03:00" level=debug msg="fetched chunk 17/18, size: 524288" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:38:56 liv go-librespot[1666]: time="2024-09-05T16:38:56+03:00" level=debug msg="fetched chunk 18/18, size: 399348" uri="spotify:track:2S6PttqbENA5jscXyLcZIT"
Sep 05 16:39:33 liv volumio[796]: info: CorePlayQueue::getTrack 2
Sep 05 16:39:33 liv volumio[796]: info: CorePlayQueue::getTrack 3
Sep 05 16:39:33 liv volumio[796]: info: Prefetching next song
Sep 05 16:39:33 liv volumio[796]: info: [1725543573644] ControllerSpotify::prefetch
Sep 05 16:39:33 liv volumio[796]: info: Sending Spotify command with payload to local API: /player/add_to_queue
Sep 05 16:39:38 liv volumio[796]: info: CoreStateMachine::startPlaybackTimer
Sep 05 16:39:38 liv volumio[796]: info: CorePlayQueue::getTrack 3
Sep 05 16:39:38 liv go-librespot[1666]: time="2024-09-05T16:39:38+03:00" level=trace msg="cleared closed output device"
Sep 05 16:39:38 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:39:38 liv volumio[796]: info: CorePlayQueue::getTrack 3
Sep 05 16:39:38 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:39:38 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:18 liv ntpd[1014]: 213.222.217.10 local addr 192.168.135.191 -> <null>
Sep 05 16:40:40 liv go-librespot[1666]: time="2024-09-05T16:40:40+03:00" level=error msg="failed put state after update" error="put state request failed with status 400: Missing payload"
Sep 05 16:40:40 liv go-librespot[1666]: time="2024-09-05T16:40:40+03:00" level=trace msg="scheduling prefetch in 188s"
Sep 05 16:40:40 liv go-librespot[1666]: time="2024-09-05T16:40:40+03:00" level=trace msg="emitting websocket event: not_playing"
Sep 05 16:40:40 liv go-librespot[1666]: time="2024-09-05T16:40:40+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:40 liv volumio[796]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","play_origin":"go-librespot"}}
Sep 05 16:40:40 liv volumio[796]: error: Failed to decode event: not_playing
Sep 05 16:40:40 liv volumio[796]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:2S6PttqbENA5jscXyLcZIT","play_origin":"go-librespot"}}
Sep 05 16:40:40 liv volumio[796]: error: Failed to decode event: not_playing
Sep 05 16:40:41 liv go-librespot[1666]: time="2024-09-05T16:40:41+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:40:41 liv go-librespot[1666]: time="2024-09-05T16:40:41+03:00" level=trace msg="emitting websocket event: will_play"
Sep 05 16:40:41 liv volumio[796]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1TtteYFQeZfSU8AmfIAOvu","play_origin":"go-librespot"}}
Sep 05 16:40:43 liv go-librespot[1666]: time="2024-09-05T16:40:43+03:00" level=debug msg="selected format OGG_VORBIS_320 (560b6a95efb8de86f9b19e2d9044951e6585f61b)" uri="spotify:track:1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:43 liv go-librespot[1666]: time="2024-09-05T16:40:43+03:00" level=debug msg="requested aes key for file 560b6a95efb8de86f9b19e2d9044951e6585f61b, gid: 1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:48 liv go-librespot[1666]: time="2024-09-05T16:40:48+03:00" level=debug msg="fetched first chunk of 20, total size is 9971556 bytes" uri="spotify:track:1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:48 liv go-librespot[1666]: time="2024-09-05T16:40:48+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:48 liv go-librespot[1666]: time="2024-09-05T16:40:48+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames"
Sep 05 16:40:48 liv go-librespot[1666]: time="2024-09-05T16:40:48+03:00" level=debug msg="created new output device"
Sep 05 16:40:48 liv go-librespot[1666]: time="2024-09-05T16:40:48+03:00" level=info msg="loaded track \"Sun Is Up\" (paused: false, position: 0ms, duration: 224531ms, prefetched: false)" uri="spotify:track:1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:48 liv go-librespot[1666]: time="2024-09-05T16:40:48+03:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:49 liv go-librespot[1666]: time="2024-09-05T16:40:49+03:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:50 liv go-librespot[1666]: time="2024-09-05T16:40:50+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:40:50 liv go-librespot[1666]: time="2024-09-05T16:40:50+03:00" level=trace msg="scheduling prefetch in 192s"
Sep 05 16:40:50 liv go-librespot[1666]: time="2024-09-05T16:40:50+03:00" level=trace msg="emitting websocket event: metadata"
Sep 05 16:40:50 liv volumio[796]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1TtteYFQeZfSU8AmfIAOvu","name":"Sun Is Up","artist_names":["INNA"],"album_name":"I Am the Club Rocker","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02464f14f7c511222dc6c95b97","position":0,"duration":224531,"release_date":"year:2011","track_number":11,"disc_number":1}}
Sep 05 16:40:50 liv volumio[796]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1TtteYFQeZfSU8AmfIAOvu","name":"Sun Is Up","artist_names":["INNA"],"album_name":"I Am the Club Rocker","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02464f14f7c511222dc6c95b97","position":0,"duration":224531,"release_date":"year:2011","track_number":11,"disc_number":1}}
Sep 05 16:40:50 liv go-librespot[1666]: time="2024-09-05T16:40:50+03:00" level=trace msg="emitting websocket event: stopped"
Sep 05 16:40:50 liv volumio[796]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Sep 05 16:40:50 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:40:50 liv volumio[796]: SPOTIFY: {"status":"stop","service":"spop","title":"Sun Is Up","artist":"INNA","album":"I Am the Club Rocker","albumart":"https://i.scdn.co/image/ab67616d00001e02464f14f7c511222dc6c95b97","uri":"spotify:track:1TtteYFQeZfSU8AmfIAOvu","trackType":"spotify","seek":0,"duration":224,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 3
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 3
Sep 05 16:40:50 liv volumio[796]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"Sun Is Up","artist":"INNA","album":"I Am the Club Rocker","albumart":"https://i.scdn.co/image/ab67616d00001e02464f14f7c511222dc6c95b97","uri":"spotify:track:1TtteYFQeZfSU8AmfIAOvu","trackType":"spotify","seek":0,"duration":224,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:50 liv volumio[796]: verbose: CURRENT POSITION 3
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::syncState   stateService stop
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::play index undefined
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::setConsumeUpdateService undefined
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::startPlaybackTimer
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:50 liv volumio[796]: info: [1725543650229] ControllerSpotify::clearAddPlayTrack
Sep 05 16:40:50 liv volumio[796]: info: Sending Spotify command with payload to local API: /player/play
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:50 liv volumio[796]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Sep 05 16:40:50 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:40:50 liv volumio[796]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:50 liv volumio[796]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:50 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::syncState   stateService stop
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus stop
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:50 liv volumio[796]: info: No code
Sep 05 16:40:50 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:50 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:50 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:51 liv go-librespot[1666]: time="2024-09-05T16:40:51+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:40:51 liv go-librespot[1666]: time="2024-09-05T16:40:51+03:00" level=trace msg="emitting websocket event: playing"
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1TtteYFQeZfSU8AmfIAOvu","play_origin":"go-librespot"}}
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:51 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus stop
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1TtteYFQeZfSU8AmfIAOvu","play_origin":"go-librespot"}}
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:51 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:40:51 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:51 liv go-librespot[1666]: time="2024-09-05T16:40:51+03:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:1TtteYFQeZfSU8AmfIAOvu"
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:51 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:40:51 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:40:51 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:40:51 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:40:51 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:51 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:40:51 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:40:51 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:40:52 liv go-librespot[1666]: time="2024-09-05T16:40:52+03:00" level=debug msg="resolved context of track" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:52 liv go-librespot[1666]: time="2024-09-05T16:40:52+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:52 liv go-librespot[1666]: time="2024-09-05T16:40:52+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:54 liv go-librespot[1666]: time="2024-09-05T16:40:54+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:40:54 liv go-librespot[1666]: time="2024-09-05T16:40:54+03:00" level=trace msg="emitting websocket event: will_play"
Sep 05 16:40:54 liv volumio[796]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7ltLi7CG003USSGYsSba9s","play_origin":"go-librespot"}}
Sep 05 16:40:54 liv volumio[796]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7ltLi7CG003USSGYsSba9s","play_origin":"go-librespot"}}
Sep 05 16:40:55 liv go-librespot[1666]: time="2024-09-05T16:40:55+03:00" level=debug msg="selected format OGG_VORBIS_320 (157addd49b8762785d3a5784a55f4b9e444fd5d4)" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:55 liv go-librespot[1666]: time="2024-09-05T16:40:55+03:00" level=debug msg="requested aes key for file 157addd49b8762785d3a5784a55f4b9e444fd5d4, gid: 7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:58 liv go-librespot[1666]: time="2024-09-05T16:40:58+03:00" level=debug msg="fetched first chunk of 14, total size is 7023640 bytes" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:58 liv go-librespot[1666]: time="2024-09-05T16:40:58+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:58 liv go-librespot[1666]: time="2024-09-05T16:40:58+03:00" level=info msg="loaded track \"It Don’t Matter - Spotify Singles\" (paused: false, position: 0ms, duration: 173742ms, prefetched: false)" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:59 liv go-librespot[1666]: time="2024-09-05T16:40:59+03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:59 liv go-librespot[1666]: time="2024-09-05T16:40:59+03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:40:59 liv go-librespot[1666]: time="2024-09-05T16:40:59+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:40:59 liv go-librespot[1666]: time="2024-09-05T16:40:59+03:00" level=trace msg="scheduling prefetch in 143s"
Sep 05 16:40:59 liv go-librespot[1666]: time="2024-09-05T16:40:59+03:00" level=trace msg="emitting websocket event: metadata"
Sep 05 16:40:59 liv volumio[796]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7ltLi7CG003USSGYsSba9s","name":"It Don’t Matter - Spotify Singles","artist_names":["Alok","Sofi Tukker","INNA"],"album_name":"It Don’t Matter - Spotify Singles","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","position":0,"duration":173742,"release_date":"year:2021 month:5 day:7","track_number":1,"disc_number":1}}
Sep 05 16:40:59 liv volumio[796]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7ltLi7CG003USSGYsSba9s","name":"It Don’t Matter - Spotify Singles","artist_names":["Alok","Sofi Tukker","INNA"],"album_name":"It Don’t Matter - Spotify Singles","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","position":0,"duration":173742,"release_date":"year:2021 month:5 day:7","track_number":1,"disc_number":1}}
Sep 05 16:40:59 liv go-librespot[1666]: time="2024-09-05T16:40:59+03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:41:00 liv go-librespot[1666]: time="2024-09-05T16:41:00+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 05 16:41:00 liv go-librespot[1666]: time="2024-09-05T16:41:00+03:00" level=trace msg="emitting websocket event: playing"
Sep 05 16:41:00 liv volumio[796]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7ltLi7CG003USSGYsSba9s","play_origin":"go-librespot"}}
Sep 05 16:41:00 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:41:00 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"It Don’t Matter - Spotify Singles","artist":"Alok, Sofi Tukker, INNA","album":"It Don’t Matter - Spotify Singles","albumart":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","uri":"spotify:track:7ltLi7CG003USSGYsSba9s","trackType":"spotify","seek":1000,"duration":173,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:41:00 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:41:00 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:00 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"It Don’t Matter - Spotify Singles","artist":"Alok, Sofi Tukker, INNA","album":"It Don’t Matter - Spotify Singles","albumart":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","uri":"spotify:track:7ltLi7CG003USSGYsSba9s","trackType":"spotify","seek":1000,"duration":173,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:41:00 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:41:00 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:41:00 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:41:00 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:41:00 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:41:00 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:00 liv volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Sep 05 16:41:00 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:41:00 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:41:00 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:00 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:41:00 liv volumio[796]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7ltLi7CG003USSGYsSba9s","play_origin":"go-librespot"}}
Sep 05 16:41:00 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:41:00 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"It Don’t Matter - Spotify Singles","artist":"Alok, Sofi Tukker, INNA","album":"It Don’t Matter - Spotify Singles","albumart":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","uri":"spotify:track:7ltLi7CG003USSGYsSba9s","trackType":"spotify","seek":1000,"duration":173,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:41:00 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:41:00 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:00 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"It Don’t Matter - Spotify Singles","artist":"Alok, Sofi Tukker, INNA","album":"It Don’t Matter - Spotify Singles","albumart":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","uri":"spotify:track:7ltLi7CG003USSGYsSba9s","trackType":"spotify","seek":1000,"duration":173,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:41:00 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:41:00 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:41:00 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:41:00 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:41:00 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:41:00 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:00 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:41:00 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:41:00 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:00 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:41:01 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:41:01 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"It Don’t Matter - Spotify Singles","artist":"Alok, Sofi Tukker, INNA","album":"It Don’t Matter - Spotify Singles","albumart":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","uri":"spotify:track:7ltLi7CG003USSGYsSba9s","trackType":"spotify","seek":1000,"duration":173,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:41:01 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:41:01 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:01 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"It Don’t Matter - Spotify Singles","artist":"Alok, Sofi Tukker, INNA","album":"It Don’t Matter - Spotify Singles","albumart":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","uri":"spotify:track:7ltLi7CG003USSGYsSba9s","trackType":"spotify","seek":1000,"duration":173,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:41:01 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:41:01 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:41:01 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:41:01 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:41:01 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:41:01 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:01 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:41:01 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:41:01 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:01 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:41:01 liv volumio[796]: SPOTIFY: PUSH STATE SPOTIFY
Sep 05 16:41:01 liv volumio[796]: SPOTIFY: {"status":"play","service":"spop","title":"It Don’t Matter - Spotify Singles","artist":"Alok, Sofi Tukker, INNA","album":"It Don’t Matter - Spotify Singles","albumart":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","uri":"spotify:track:7ltLi7CG003USSGYsSba9s","trackType":"spotify","seek":1000,"duration":173,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:41:01 liv volumio[796]: info: CoreCommandRouter::servicePushState
Sep 05 16:41:01 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:01 liv volumio[796]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"It Don’t Matter - Spotify Singles","artist":"Alok, Sofi Tukker, INNA","album":"It Don’t Matter - Spotify Singles","albumart":"https://i.scdn.co/image/ab67616d00001e0260b16fc0b0cc5948f2173511","uri":"spotify:track:7ltLi7CG003USSGYsSba9s","trackType":"spotify","seek":1000,"duration":173,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Sep 05 16:41:01 liv volumio[796]: verbose: CURRENT POSITION 4
Sep 05 16:41:01 liv volumio[796]: info: CoreStateMachine::syncState   stateService play
Sep 05 16:41:01 liv volumio[796]: info: CoreStateMachine::syncState   currentStatus play
Sep 05 16:41:01 liv volumio[796]: info: Received an update from plugin. extracting info from payload
Sep 05 16:41:01 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:41:01 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:01 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:41:01 liv volumio[796]: info: CoreStateMachine::pushState
Sep 05 16:41:01 liv volumio[796]: info: CorePlayQueue::getTrack 4
Sep 05 16:41:01 liv volumio[796]: info: CoreCommandRouter::volumioPushState
Sep 05 16:41:12 liv go-librespot[1666]: time="2024-09-05T16:41:12+03:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:7ltLi7CG003USSGYsSba9s"
Sep 05 16:41:25 liv go-librespot[1666]: time="2024-09-05T16:41:25+03:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:7ltLi7CG003USSGYsSba9s"

sciensys · September 5, 2024, 3:39pm

Sorry,
I found out, that raspberry ethernet port was tuned up to use IPSEC channel.
When I change route, spotify plugin started work as need it.

P.S. anyway, plugin not works properly with IPSEC channels, and I suppose plugin not works with OpenVPN, Wireguard and so on, like a Volumio too.
But spotify plugin more critical then Volumio.

Spotify plugin process you can see at post above.
Is it possible to teach spotify plugin work with any secure channels ?

burrumio · September 5, 2024, 8:00pm

As of this morning, Spotify has stopped playing. As in literally no audio, but everything else seems to work. I’ve tried everything I can think of and could use some help!

It’s authorized with my Spotify account, connects just fine, and is definitely communicating with Spotify. I can browse via the interface (both on device and via a web browser), successfully search, see my playlists, add tracks to the queue etc. It even occasionally updates what track is “now playing” in my queue… even though nothing is playing.

I’ve tried restarting, uninstalling and reinstalling the plugin, logging out of Spotify and logging back in with a different user account, but nothing has helped.

(I should add that other audio sources, like Web Radio, are playing just fine, so it’s not a hardware thing.)

Looking to my log, it appears that the go-librespot Daemon is continuously starting, erroring, stopping and trying to start again. It’s done this over 800 times since my last restart a handful of minutes below. Here’s a snippet:

Started go-librespot Daemon.
Librespot-go daemon starting...
time="2024-09-05T15:52:39-04:00" level=info msg="generated new device id: 80ca5db10244272e6d2a22868f1b7f983dd8e2fc"
time="2024-09-05T15:52:39-04:00" level=debug msg="stored credentials not found"
time="2024-09-05T15:52:40-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
time="2024-09-05T15:52:40-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
time="2024-09-05T15:52:40-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
time="2024-09-05T15:52:40-04:00" level=debug msg="zeroconf server listening on port 34427"
time="2024-09-05T15:52:40-04:00" level=debug msg="obtained new client token: AADuUtWzoWc5gVPY0e/tjzThzynIlBdULr/loyarWtgtI15AFjC3ZPtkK+mm+fzwZzeNeHABUHXuU2UVJ74Jvc8PiGUXb9BD9PUWpxn/Xg2i+bEP2iyk+RvZ2QvwNPVKdiuI3cIA2PQ8L2UVouwsw0FmwS9GDilRLrOp21jljElnirAPgnBH3fbXRZ2YWusboLiZzCvTGU5ho6wQ2WAtCGVukn8IQlb/vl4dRsEGxbTdK6fgIzAoovDm"
time="2024-09-05T15:52:40-04:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.65.124:4070: connect: connection refused"
go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
go-librespot-daemon.service: Failed with result 'exit-code'.
info: Initializing connection to go-librespot Websocket
info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
info: Initializing connection to go-librespot Websocket
info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
go-librespot-daemon.service: Scheduled restart job, restart counter is at 822.
Stopped go-librespot Daemon.

And here’s a fuller log: http://logs.volumio.org/volumio/pOU1yYf.html

Can anyone help? This is my daughter’s alarm clock, so would love to get it working again. Thank you!

giorgosperi · September 7, 2024, 4:33pm

mine also stopped working…
the same error as @burrumio

burrumio · September 9, 2024, 2:09pm

Have you had any luck getting yours running again, @giorgosperi ?