Dec 27 18:49:02 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:02 volumio volumio[1289]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 27 18:49:02 volumio volumio[1289]: info: CoreStateMachine::ClearQueue Dec 27 18:49:02 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:02 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:02 volumio volumio[1289]: info: CorePlayQueue::clearPlayQueue Dec 27 18:49:02 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:49:02 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:49:02 volumio volumio[1289]: info: CoreStateMachine::addQueueItems Dec 27 18:49:02 volumio volumio[1289]: info: CorePlayQueue::addQueueItems Dec 27 18:49:02 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:02 volumio volumio[1289]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ Dec 27 18:49:02 volumio volumio[1289]: info: Exploding uri spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ in service spop Dec 27 18:49:02 volumio volumio[1289]: SPOTIFY: EXPLODING URI:spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ Dec 27 18:49:02 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6O66qS9WnOnCjpKhQk6NK4","service":"spop","name":"25 годин","artist":"Олена Тополя","album":"25 годин","type":"song","duration":155,"albumart":"https://i.scdn.co/image/ab67616d0000b2731bd4a1f231eaf8ed01a0ff23","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1f5i0oy0aeVVbXDvAbPEdg","service":"spop","name":"Шиншила","artist":"Tina Karol","album":"Шиншила","type":"song","duration":168,"albumart":"https://i.scdn.co/image/ab67616d0000b27365286a11a72200e479be6f7d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5ipHXEO6huR9GXel3WgTxg","service":"spop","name":"Готель Вараш","artist":"Do Sliz","album":"Готель Вараш","type":"song","duration":264,"albumart":"https://i.scdn.co/image/ab67616d0000b273c2da1e9acef82edc8120180e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7GoThWuPu1a1zju91QFJJz","service":"spop","name":"Black Swans","artist":"Sofia Nersesian","album":"Black Swans","type":"song","duration":208,"albumart":"https://i.scdn.co/image/ab67616d0000b273ee3a2f129d62aadaf00e6b00","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6ad18bgbiyvswK88QVVMyy","service":"spop","name":"Після Бою","artist":"Після Дощу","album":"Після Бою","type":"song","duration":184,"albumart":"https://i.scdn.co/image/ab67616d0000b273c67a74c787dd57437b5fc1c4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4CN2AdYEHN2MmbJwQfHEIw","service":"spop","name":"Love One Another (Or Die)","artist":"Nick Cave","album":"The Death Of Bunny Munro","type":"song","duration":144,"albumart":"https://i.scdn.co/image/ab67616d0000b2730a2a76f2cb67f46d7c87a978","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6xDG6gLp7aXHow2cdNozWm","service":"spop","name":"Жінка Сніжинка","artist":"Olya Polyakova","album":"Жінка Сніжинка","type":"song","duration":201,"albumart":"https://i.scdn.co/image/ab67616d0000b273b602fac4c8d16c9a9b581b90","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:44PriEMHN9HEAm2z9g2J1K","service":"spop","name":"Вбий свою голову","artist":"рома майк","album":"Вбий свою голову","type":"song","duration":156,"albumart":"https://i.scdn.co/image/ab67616d0000b273f8d9e42dc0d4d57dc49c6ff9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4rXdJ33W1I284wEHF3lIQn","service":"spop","name":"збила машина","artist":"laang","album":"збила машина","type":"song","duration":239,"albumart":"https://i.scdn.co/image/ab67616d0000b2738848aa334ea186907f0e38fc","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7gz2iRzBMNLH4tnHdlaHsr","service":"spop","name":"Місяця срібний дзюб (Павло Филипович)","artist":"Пиріг і Батіг","album":"Замордовані. Подзвін другий","type":"song","duration":178,"albumart":"https://i.scdn.co/image/ab67616d0000b273fad85261316d09956185c97e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:77QlT4RN0SUlGG1nasBR16","service":"spop","name":"Rivers","artist":"AFROJACK","album":"Rivers","type":"song","duration":202,"albumart":"https://i.scdn.co/image/ab67616d0000b2732ad3b00e296b4828cc27ce79","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0Lju8S8BTjLiRdsFqy7bTH","service":"spop","name":"Квіти на підвіконні","artist":"kavabanga Depo kolibri","album":"Квіти на підвіконні","type":"song","duration":137,"albumart":"https://i.scdn.co/image/ab67616d0000b273f37f93dbaad76cc4e591f3e4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:04 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4ld5f4ceu7dJOVpo9wzS3F","service":"spop","name":"Shades","artist":"Benny Benassi","album":"Shades","type":"song","duration":204,"albumart":"https://i.scdn.co/image/ab67616d0000b273983e40901935e01c7128a0b5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1wo16BTX3HhyfCdbeCkYXD","service":"spop","name":"Зі мною так не можна","artist":"Оля Цибульська","album":"Зі мною так не можна","type":"song","duration":145,"albumart":"https://i.scdn.co/image/ab67616d0000b273247a86328fe5786a8139eb4a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3tNYXuJrV7MwelYIVlE9YD","service":"spop","name":"душа","artist":"SIAMÍS","album":"душа","type":"song","duration":209,"albumart":"https://i.scdn.co/image/ab67616d0000b273ab6679d6cb337782c0785372","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5nxvhdJsVBsmNm7UIWLF4w","service":"spop","name":"Франсуа","artist":"Khrystyna Soloviy","album":"Франсуа","type":"song","duration":238,"albumart":"https://i.scdn.co/image/ab67616d0000b273134f1c37c274e434eba2a36e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7c6SayOcRKUtgEo4f7HE3j","service":"spop","name":"Небезпечна","artist":"USTYM","album":"Небезпечна","type":"song","duration":213,"albumart":"https://i.scdn.co/image/ab67616d0000b2737fa3f00bd50acf6e0e6e6198","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4MExWeRFu2WKlFWIrU7AUk","service":"spop","name":"Супермама","artist":"Krechet","album":"Супермама","type":"song","duration":137,"albumart":"https://i.scdn.co/image/ab67616d0000b27357ee1e3eb5fb027ff01f6a45","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1l5tIsQalI7wg2aLI4r2FX","service":"spop","name":"Граніт","artist":"Гаррі Шульц","album":"Граніт","type":"song","duration":185,"albumart":"https://i.scdn.co/image/ab67616d0000b273a47e8125c60a26c643e34064","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1jGKugxyynaWxM7UbfBqv9","service":"spop","name":"Земля","artist":"МУАЯД","album":"Земля","type":"song","duration":159,"albumart":"https://i.scdn.co/image/ab67616d0000b27321788d1f38f40aee47b17969","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:56azeQEtUhg062gyjynloT","service":"spop","name":"Тихо йшов","artist":"Білий Бо","album":"Тихо йшов","type":"song","duration":161,"albumart":"https://i.scdn.co/image/ab67616d0000b273fe91204c351f55ae17fd6dfa","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6zA1pQPhyRoP82GvxlVrLR","service":"spop","name":"Земля","artist":"CHOOB","album":"Земля","type":"song","duration":157,"albumart":"https://i.scdn.co/image/ab67616d0000b273e2d7681b77e07db3fef08ff8","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:56Kk6UU7HQJHhr6HqjR7a1","service":"spop","name":"Спогадом","artist":"Gaaya","album":"Спогадом","type":"song","duration":174,"albumart":"https://i.scdn.co/image/ab67616d0000b273435f1fb986cc2696d753cdf1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2Rvf5YsSlm4sG9O6tXMopn","service":"spop","name":"Діалог з собою","artist":"MARIÈLLE","album":"Діалог з собою","type":"song","duration":208,"albumart":"https://i.scdn.co/image/ab67616d0000b273145018772fdcb1259a963742","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1dcYeA56OaQgV52HmKzrrx","service":"spop","name":"Other worlds","artist":"Carpetman","album":"Other worlds","type":"song","duration":285,"albumart":"https://i.scdn.co/image/ab67616d0000b27313a483a9c57f86382f920acd","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0Z7Xvn2kkzR0SkPukPjzcZ","service":"spop","name":"Світло","artist":"Vsivdoma","album":"Світло","type":"song","duration":179,"albumart":"https://i.scdn.co/image/ab67616d0000b273f8b3dc0b3ffb1c3cb392b2d8","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1b7w4UuUfq9iPoDstsrT2u","service":"spop","name":"Clap Song","artist":"Dolly Style","album":"Clap Song","type":"song","duration":155,"albumart":"https://i.scdn.co/image/ab67616d0000b273e83600f0d4da70aa125f816c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7oyMAViYxBswvEXboOcT6W","service":"spop","name":"Venom's In - demo","artist":"Panda Bear","album":"Venom's In","type":"song","duration":295,"albumart":"https://i.scdn.co/image/ab67616d0000b2731ab0ef6a26ada5820541cff0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3Jh9zDKriBwYYUXX2mcJpZ","service":"spop","name":"Кордони","artist":"Volkanov","album":"Кордони","type":"song","duration":176,"albumart":"https://i.scdn.co/image/ab67616d0000b273b5ad2d63df4a0226ea923e47","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6YoiWI0Nv9ohOEcKOAg0Ch","service":"spop","name":"Гоп-стоп","artist":"субота","album":"Ломбард 24/7","type":"song","duration":132,"albumart":"https://i.scdn.co/image/ab67616d0000b2736a63e78b81a48bfbd0815c8a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2nqIkDtz2RUNRzgMegcDCv","service":"spop","name":"А на добрий вечір","artist":"Всюдисвоя","album":"Різдво і Радість","type":"song","duration":135,"albumart":"https://i.scdn.co/image/ab67616d0000b27325623ec82d3ef68d9bb7a8d9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3PdNdoktMbFpphZJQo4nK6","service":"spop","name":"Пальто","artist":"DOVI","album":"Пальто","type":"song","duration":162,"albumart":"https://i.scdn.co/image/ab67616d0000b27304a1a4f728a8ee8eb7cd214f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7N3mR4WnEuq1MUQlxb6JWH","service":"spop","name":"Muévelo","artist":"Kali Uchis","album":"Muévelo","type":"song","duration":127,"albumart":"https://i.scdn.co/image/ab67616d0000b2731b548a459611daab1d6dc3b9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6vaeOMPoVd8LcsgNeU1QKD","service":"spop","name":"Де ти","artist":"Rodniy","album":"Де ти","type":"song","duration":155,"albumart":"https://i.scdn.co/image/ab67616d0000b27306cd390d0d42ca4d2b17236c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4t3CRfsV9wL4ZSiqSe7PSx","service":"spop","name":"X-Ray","artist":"Fight Pausa","album":"X-Ray / Clumsy","type":"song","duration":154,"albumart":"https://i.scdn.co/image/ab67616d0000b27386f603f7609dcf0f4075b757","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:76oi09DpJk0S1LgFoyZz6t","service":"spop","name":"Холодно-тепло","artist":"Rusnak","album":"Холодно-тепло","type":"song","duration":192,"albumart":"https://i.scdn.co/image/ab67616d0000b2734ae984f4a8bb8163756ec8a1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1v5qNxmJfqO3luRigswkXA","service":"spop","name":"Гей, Маланка","artist":"Ruslana","album":"Гей, Маланка","type":"song","duration":218,"albumart":"https://i.scdn.co/image/ab67616d0000b273241f157a5743adf8c931c748","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3n4e4Ca4kdFwYxO7iwDIN6","service":"spop","name":"Моє серце","artist":"ОЧІ В ОЧІ","album":"Моє серце","type":"song","duration":194,"albumart":"https://i.scdn.co/image/ab67616d0000b273f34287ed3770d25ccf03848e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0eQHhHDBu3FgbaYxZaJzoP","service":"spop","name":"Чай гарячий","artist":"Vlad Darwin","album":"Чай гарячий","type":"song","duration":185,"albumart":"https://i.scdn.co/image/ab67616d0000b273581e94696cca6c78d0675b6b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0c5PvsesOoEalqxkct5lZO","service":"spop","name":"Янгол","artist":"ROPAN","album":"Янгол","type":"song","duration":158,"albumart":"https://i.scdn.co/image/ab67616d0000b2731dc4a57f9748d47f41f4c7a8","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5kCxlaNWtU5omWIQo5lqHX","service":"spop","name":"BAM BAM BAM","artist":"DEMI","album":"BAM BAM BAM","type":"song","duration":152,"albumart":"https://i.scdn.co/image/ab67616d0000b273a2db747e2e69cd0898a997b9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","service":"spop","name":"Роди, Боже, жито","artist":"ROXOLANA","album":"Роди, Боже, жито","type":"song","duration":164,"albumart":"https://i.scdn.co/image/ab67616d0000b273e1f5d255d8cc8f0813894928","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2qvtSXZMazX4qOawg9jvPI","service":"spop","name":"Щедрий вечор","artist":"Monokate","album":"Щедрий вечор","type":"song","duration":149,"albumart":"https://i.scdn.co/image/ab67616d0000b273a79500b16628c1b101178a64","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3K3CnIKp7PVXUGpsRMvs8L","service":"spop","name":"Снігопад","artist":"TESLENKO","album":"Снігопад","type":"song","duration":147,"albumart":"https://i.scdn.co/image/ab67616d0000b27391e58b6660a9a86c0095fec9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6YYg1yA4raAeDzixJfITnb","service":"spop","name":"Out Of My Body (feat. EJAE)","artist":"Anyma","album":"Out Of My Body (feat. EJAE)","type":"song","duration":159,"albumart":"https://i.scdn.co/image/ab67616d0000b273e39838a6ecc1b02530e50415","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0JUThld8jWg5XeGv0aKLzN","service":"spop","name":"Сирена","artist":"Лея","album":"Сирена","type":"song","duration":176,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbb9f9af049ab5efc198d275","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5wGnbGgVsyR5y64lRdCAvs","service":"spop","name":"Залізні","artist":"KOZAK SIROMAHA","album":"Залізні","type":"song","duration":169,"albumart":"https://i.scdn.co/image/ab67616d0000b2732da9581350ae6cda28fe7821","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:542YPmjNwAaL5AY03ex3LG","service":"spop","name":"НЕ ВІДПУСКАЙ","artist":"VARASH","album":"НЕ ВІДПУСКАЙ","type":"song","duration":186,"albumart":"https://i.scdn.co/image/ab67616d0000b27360007ab12744db0a2c8d97df","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3ofx8b2rqrLOCJQW23kNrD","service":"spop","name":"Дивовижний","artist":"TRINY T","album":"Дивовижний","type":"song","duration":117,"albumart":"https://i.scdn.co/image/ab67616d0000b273af21dc43b29c56455e877655","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0e3k1qX9hGTeOK4PNFGPAh","service":"spop","name":"У долі під прицілом","artist":"СОБАКА ЩО КРИЧИТЬ","album":"У долі під прицілом","type":"song","duration":188,"albumart":"https://i.scdn.co/image/ab67616d0000b2736a764032eaa756831e1c028f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5gqp8vNyGJUNHvCof0ExRJ","service":"spop","name":"Лід","artist":"IRYN","album":"Лід","type":"song","duration":135,"albumart":"https://i.scdn.co/image/ab67616d0000b2736e3abd86d33fb3a779540592","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4hZhElYvVCjqCNlRyZxX7Y","service":"spop","name":"Хто ти такий?","artist":"GROSU","album":"Хто ти такий?","type":"song","duration":178,"albumart":"https://i.scdn.co/image/ab67616d0000b273a5592bf98670434ff5161b09","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1AmHyK6gaiUm8znmyvtM7h","service":"spop","name":"Тонкий лід","artist":"Kinnota","album":"Тонкий лід","type":"song","duration":207,"albumart":"https://i.scdn.co/image/ab67616d0000b273629e9a26f3546faf845ca3cb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3PIgAVNHyiiAiKhxnvdrPw","service":"spop","name":"Money","artist":"Arkells","album":"Money","type":"song","duration":212,"albumart":"https://i.scdn.co/image/ab67616d0000b2730c4baba96825b9d9bbc7ea6c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4ljAZhPvLhH7bziOcMmwro","service":"spop","name":"Остогидло","artist":"Тулим","album":"Під Сумнів","type":"song","duration":218,"albumart":"https://i.scdn.co/image/ab67616d0000b273a4ee79637ed034c51d6036c5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2piSogWu6uu0zE7FwF9qqY","service":"spop","name":"Ніч догорає","artist":"KALUSH","album":"Ніч догорає","type":"song","duration":198,"albumart":"https://i.scdn.co/image/ab67616d0000b273a91f0c18dd72f7768fa5a500","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7x1djiQMBS869mOwvScTb2","service":"spop","name":"Все Змиє Дощем","artist":"Valeriia Vovk","album":"Все Змиє Дощем","type":"song","duration":255,"albumart":"https://i.scdn.co/image/ab67616d0000b27329b01ef6c33cc4f88a8cf45f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:54t7wqSpcXnAoiqMo38Fxz","service":"spop","name":"Закінчиться вечірка","artist":"beshket","album":"Закінчиться вечірка","type":"song","duration":201,"albumart":"https://i.scdn.co/image/ab67616d0000b273b709fb7d0aa4c2d152b74faa","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6ekNkZJOe2IO9xoweSRZZD","service":"spop","name":"Nothing More","artist":"NIKITAIDISYUDA","album":"Nothing More","type":"song","duration":164,"albumart":"https://i.scdn.co/image/ab67616d0000b273f37d966116257bf4de26d5e9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:46KnnJkigBXm615zkekr6A","service":"spop","name":"Все Людям","artist":"MAZEPA","album":"Все Людям","type":"song","duration":153,"albumart":"https://i.scdn.co/image/ab67616d0000b273c04ac20bd3fe9fa0f107a47b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3xZT6OEmmI8bpMKkmGIlwt","service":"spop","name":"Paper Low","artist":"DaBaby","album":"Paper Low","type":"song","duration":162,"albumart":"https://i.scdn.co/image/ab67616d0000b27383befaf0858f99cea043a834","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6Znk95xsZ3d4zxSg12nMzK","service":"spop","name":"Голограма","artist":"TENDITNA","album":"Голограма","type":"song","duration":192,"albumart":"https://i.scdn.co/image/ab67616d0000b27366338e4b4ab42ad3c3f82dbf","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1yCN2w6hOAAwRMrCNtzFhJ","service":"spop","name":"Іду сама","artist":"даніо-реріо","album":"Іду сама","type":"song","duration":319,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b5d0529fa7db01cdb631e15","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3HYcLucBMngcJxCAMiSJzn","service":"spop","name":"Мости","artist":"Electrobirds","album":"Мости","type":"song","duration":343,"albumart":"https://i.scdn.co/image/ab67616d0000b2732a826d23f52c0831d5029421","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6TxfUTMLTUxJn2xqwK0ZWf","service":"spop","name":"Голуби","artist":"Valeriya Force","album":"Голуби","type":"song","duration":196,"albumart":"https://i.scdn.co/image/ab67616d0000b27308fd69822b771ca370b383ed","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5Dm8PaOqbspvQmFxRa7H7D","service":"spop","name":"Білі полоси","artist":"Vova Cigan","album":"Білі полоси","type":"song","duration":156,"albumart":"https://i.scdn.co/image/ab67616d0000b2732530ea3b2af939878cbcb68b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6Xh8KHpNjheQ5qcmvjT170","service":"spop","name":"Едельвейс","artist":"KOZAK SIROMAHA","album":"Едельвейс","type":"song","duration":154,"albumart":"https://i.scdn.co/image/ab67616d0000b273e5eab2fedd146569d98eff49","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1lelgyfO1BqyZDMRQ3Xf2U","service":"spop","name":"Шрам","artist":"MALA","album":"Шрам","type":"song","duration":99,"albumart":"https://i.scdn.co/image/ab67616d0000b27339e73672c988a1b3b1f5bd06","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1oZqDLHmCbQyKaLmerj4bw","service":"spop","name":"Той джентельмен","artist":"Ana Pri","album":"Той джентельмен","type":"song","duration":150,"albumart":"https://i.scdn.co/image/ab67616d0000b273943375854553fb068bd1bafa","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:43zc32WPHnBx0qBt732oRI","service":"spop","name":"Пісочниця","artist":"keeroo","album":"Пісочниця","type":"song","duration":208,"albumart":"https://i.scdn.co/image/ab67616d0000b273e31e933191e691eeb0c80cab","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1LJ8ODaoio5lJMgtXzALMw","service":"spop","name":"Amateur","artist":"manifest","album":"Amateur","type":"song","duration":163,"albumart":"https://i.scdn.co/image/ab67616d0000b2737cd59e66898775de294ba530","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3TwFyjXBntSyGmTav4FNGD","service":"spop","name":"Дорога","artist":"гурт Лісапетний батальйон","album":"Дорога","type":"song","duration":216,"albumart":"https://i.scdn.co/image/ab67616d0000b2738fd2bea3561590d20d7974b7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5eHinkYFdZCzY0PzPWpnTh","service":"spop","name":"За дуру","artist":"VERONIKA","album":"За дуру","type":"song","duration":133,"albumart":"https://i.scdn.co/image/ab67616d0000b27314abefc9d97af0e83d25c1eb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5Gv1cYDAXvMyupCja1UHyW","service":"spop","name":"Метелик, лети","artist":"Alice Change","album":"Метелик, лети","type":"song","duration":155,"albumart":"https://i.scdn.co/image/ab67616d0000b27359fb80071b2aa7372446a2b1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5nsa1Ffko6yhSliZBE8JK8","service":"spop","name":"На її Різдво","artist":"ANSTAY","album":"На її Різдво","type":"song","duration":142,"albumart":"https://i.scdn.co/image/ab67616d0000b27319cb6be20cf5fa1771edab3f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0eCGCyB6968WVbZsOdCTIH","service":"spop","name":"До зупинки","artist":"У пошуках ментолової коли","album":"До зупинки","type":"song","duration":183,"albumart":"https://i.scdn.co/image/ab67616d0000b273ec3203f55171e2696ede4ec5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4qBIS1ST1sXsiWq9l9ILQx","service":"spop","name":"Те, що сталось двічі","artist":"Spiv Brativ","album":"Те, що сталось двічі","type":"song","duration":174,"albumart":"https://i.scdn.co/image/ab67616d0000b273db7e9156c8b83301be7bd940","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0tPbX55L8D2igcLgQa8Vn3","service":"spop","name":"Светр","artist":"Sexy Education","album":"Светр","type":"song","duration":214,"albumart":"https://i.scdn.co/image/ab67616d0000b273ee962c7fec84fd38eb57f02f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4VRZ9CRIrufxvBRsFbkjoU","service":"spop","name":"Духовний стан","artist":"Матвій М.","album":"Духовний стан","type":"song","duration":111,"albumart":"https://i.scdn.co/image/ab67616d0000b273d4d6ceb3291f768613a2a6ec","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:05 volumio volumio[1289]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:38KogCv80PHOcyPOM5Xn5y","service":"spop","name":"Don't You Hate Yourself?","artist":"Waiting Room","album":"Don't You Hate Yourself?","type":"song","duration":298,"albumart":"https://i.scdn.co/image/ab67616d0000b27374ae6666b66b7b96db47027d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 27 18:49:06 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:06 volumio volumio[1289]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::ClearQueue Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:06 volumio volumio[1289]: info: CorePlayQueue::clearPlayQueue Dec 27 18:49:06 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:49:06 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::addQueueItems Dec 27 18:49:06 volumio volumio[1289]: info: CorePlayQueue::addQueueItems Dec 27 18:49:06 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:06 volumio volumio[1289]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ Dec 27 18:49:06 volumio volumio[1289]: info: Exploding uri spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ in service spop Dec 27 18:49:06 volumio volumio[1289]: SPOTIFY: EXPLODING URI:spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ Dec 27 18:49:06 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:49:06 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::updateTrackBlock Dec 27 18:49:06 volumio volumio[1289]: info: CorePlayQueue::getTrackBlock Dec 27 18:49:06 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::play index 0 Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:06 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:06 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:06 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:06 volumio volumio[1289]: info: [1766854146771] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:06 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:06 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:07 volumio go-librespot[1969]: time="2025-12-27T18:49:07+02:00" level=debug msg="resolved context of track" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:07 volumio go-librespot[1969]: time="2025-12-27T18:49:07+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:07 volumio go-librespot[1969]: time="2025-12-27T18:49:07+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:07 volumio go-librespot[1969]: time="2025-12-27T18:49:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:07 volumio go-librespot[1969]: time="2025-12-27T18:49:07+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:07 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","play_origin":"go-librespot"}} Dec 27 18:49:07 volumio go-librespot[1969]: time="2025-12-27T18:49:07+02:00" level=debug msg="selected format OGG_VORBIS_320 (0be3666990cfd63ed7447f7c293b07647a9b5df2)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:07 volumio go-librespot[1969]: time="2025-12-27T18:49:07+02:00" level=debug msg="requested aes key for file 0be3666990cfd63ed7447f7c293b07647a9b5df2, gid: 3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:07 volumio go-librespot[1969]: time="2025-12-27T18:49:07+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3c7KbnkDgpHNz5RVfJyxBV: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:07 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:07 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:49:07 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:49:07 volumio volumio[1289]: info: CoreStateMachine::updateTrackBlock Dec 27 18:49:07 volumio volumio[1289]: info: CorePlayQueue::getTrackBlock Dec 27 18:49:07 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:07 volumio volumio[1289]: info: CoreStateMachine::play index 0 Dec 27 18:49:07 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:07 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:07 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:07 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:07 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:07 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:07 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:07 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:07 volumio volumio[1289]: info: [1766854147716] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:07 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=debug msg="resolved context of track" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:08 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","play_origin":"go-librespot"}} Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=debug msg="selected format OGG_VORBIS_320 (0be3666990cfd63ed7447f7c293b07647a9b5df2)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=debug msg="requested aes key for file 0be3666990cfd63ed7447f7c293b07647a9b5df2, gid: 3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3c7KbnkDgpHNz5RVfJyxBV: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=trace msg="received accesspoint ping" Dec 27 18:49:08 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=trace msg="received accesspoint pong ack" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=trace msg="sent dealer ping" Dec 27 18:49:08 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:08 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:08 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:08 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:08 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:08 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:08 volumio volumio[1289]: info: [1766854148812] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:08 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=debug msg="resolved context of track" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=trace msg="received dealer pong" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:08 volumio go-librespot[1969]: time="2025-12-27T18:49:08+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:08 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","play_origin":"go-librespot"}} Dec 27 18:49:09 volumio go-librespot[1969]: time="2025-12-27T18:49:09+02:00" level=debug msg="selected format OGG_VORBIS_320 (0be3666990cfd63ed7447f7c293b07647a9b5df2)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:09 volumio go-librespot[1969]: time="2025-12-27T18:49:09+02:00" level=debug msg="requested aes key for file 0be3666990cfd63ed7447f7c293b07647a9b5df2, gid: 3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:09 volumio go-librespot[1969]: time="2025-12-27T18:49:09+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3c7KbnkDgpHNz5RVfJyxBV: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:09 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:10 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:10 volumio volumio[1289]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 27 18:49:10 volumio volumio[1289]: info: CoreStateMachine::ClearQueue Dec 27 18:49:10 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:10 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:10 volumio volumio[1289]: info: CorePlayQueue::clearPlayQueue Dec 27 18:49:10 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:49:10 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:49:10 volumio volumio[1289]: info: CoreStateMachine::addQueueItems Dec 27 18:49:10 volumio volumio[1289]: info: CorePlayQueue::addQueueItems Dec 27 18:49:10 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:10 volumio volumio[1289]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ Dec 27 18:49:10 volumio volumio[1289]: info: Using cached record of: spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ Dec 27 18:49:10 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:49:11 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:49:11 volumio volumio[1289]: info: CoreStateMachine::updateTrackBlock Dec 27 18:49:11 volumio volumio[1289]: info: CorePlayQueue::getTrackBlock Dec 27 18:49:11 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:11 volumio volumio[1289]: info: CoreStateMachine::play index 0 Dec 27 18:49:11 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:11 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:11 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:11 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:11 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:11 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:11 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:11 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:11 volumio volumio[1289]: info: [1766854151003] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:11 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:11 volumio go-librespot[1969]: time="2025-12-27T18:49:11+02:00" level=debug msg="resolved context of track" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:11 volumio go-librespot[1969]: time="2025-12-27T18:49:11+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:11 volumio go-librespot[1969]: time="2025-12-27T18:49:11+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:11 volumio go-librespot[1969]: time="2025-12-27T18:49:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:11 volumio go-librespot[1969]: time="2025-12-27T18:49:11+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:11 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","play_origin":"go-librespot"}} Dec 27 18:49:11 volumio go-librespot[1969]: time="2025-12-27T18:49:11+02:00" level=debug msg="selected format OGG_VORBIS_320 (0be3666990cfd63ed7447f7c293b07647a9b5df2)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:11 volumio go-librespot[1969]: time="2025-12-27T18:49:11+02:00" level=debug msg="requested aes key for file 0be3666990cfd63ed7447f7c293b07647a9b5df2, gid: 3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:11 volumio go-librespot[1969]: time="2025-12-27T18:49:11+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3c7KbnkDgpHNz5RVfJyxBV: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:11 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:16 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:16 volumio volumio[1289]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::ClearQueue Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:16 volumio volumio[1289]: info: CorePlayQueue::clearPlayQueue Dec 27 18:49:16 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:49:16 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::addQueueItems Dec 27 18:49:16 volumio volumio[1289]: info: CorePlayQueue::addQueueItems Dec 27 18:49:16 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:49:16 volumio volumio[1289]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ Dec 27 18:49:16 volumio volumio[1289]: info: Using cached record of: spotify:user:spotify:playlist:37i9dQZF1DX69uAEiqiuHZ Dec 27 18:49:16 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:49:16 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::updateTrackBlock Dec 27 18:49:16 volumio volumio[1289]: info: CorePlayQueue::getTrackBlock Dec 27 18:49:16 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::play index 0 Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:16 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:16 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:16 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:16 volumio volumio[1289]: info: [1766854156292] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:16 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:16 volumio go-librespot[1969]: time="2025-12-27T18:49:16+02:00" level=debug msg="resolved context of track" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:16 volumio go-librespot[1969]: time="2025-12-27T18:49:16+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:16 volumio go-librespot[1969]: time="2025-12-27T18:49:16+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:16 volumio go-librespot[1969]: time="2025-12-27T18:49:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:16 volumio go-librespot[1969]: time="2025-12-27T18:49:16+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:16 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","play_origin":"go-librespot"}} Dec 27 18:49:16 volumio go-librespot[1969]: time="2025-12-27T18:49:16+02:00" level=debug msg="selected format OGG_VORBIS_320 (0be3666990cfd63ed7447f7c293b07647a9b5df2)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:16 volumio go-librespot[1969]: time="2025-12-27T18:49:16+02:00" level=debug msg="requested aes key for file 0be3666990cfd63ed7447f7c293b07647a9b5df2, gid: 3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:16 volumio go-librespot[1969]: time="2025-12-27T18:49:16+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3c7KbnkDgpHNz5RVfJyxBV: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:16 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:21 volumio volumio[1289]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 27 18:49:21 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 27 18:49:21 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 27 18:49:21 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Dec 27 18:49:22 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 27 18:49:36 volumio volumio[1289]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Dec 27 18:49:36 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Dec 27 18:49:36 volumio volumio[1289]: info: Preparing to save Alsa Options, stopping services first Dec 27 18:49:36 volumio volumio[1289]: info: CoreCommandRouter::volumioGetState Dec 27 18:49:36 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:36 volumio volumio[1289]: info: CoreCommandRouter::volumioPause Dec 27 18:49:36 volumio volumio[1289]: info: CoreStateMachine::pause Dec 27 18:49:36 volumio volumio[1289]: info: Saving Audio Output to: {"output_device":{"value":"1","label":"Headphones"},"i2s":false,"i2sid":{"value":"adafruit-max98357","label":"Adafruit MAX98357"}} Dec 27 18:49:36 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 27 18:49:37 volumio volumio[1289]: info: Found match in Cards Database: setting mixer PCM for card Headphones Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::volumioUpdateVolumeSettings Dec 27 18:49:37 volumio volumio[1289]: info: Updating Volume Controller Parameters: Device: 1 Name: softvolume Mixer: PCM Max Vol: 100 Vol Curve; linear Vol Steps: 1 Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Dec 27 18:49:37 volumio volumio[1289]: info: Disabling external Volume Control Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 27 18:49:37 volumio volumio[1289]: info: Enable softmixer device for audio device undefined Dec 27 18:49:37 volumio volumio[1289]: info: Software Volume ALSA configuration written Dec 27 18:49:37 volumio volumio[1289]: info: Preparing to generate the ALSA configuration file Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 27 18:49:37 volumio volumio[1289]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Dec 27 18:49:37 volumio volumio[1289]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 27 18:49:37 volumio volumio[1289]: info: Reading ALSA contributions from plugins. Dec 27 18:49:37 volumio volumio[1289]: info: VolumeController:: Volume=96 Mute =false Dec 27 18:49:37 volumio volumio[1289]: info: CoreStateMachine::pushState Dec 27 18:49:37 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 27 18:49:37 volumio volumio[1289]: info: CoreCommandRouter::volumioPushState Dec 27 18:49:37 volumio volumio[1289]: info: PeppySpectrum ---peppyspectrum status stop Dec 27 18:49:38 volumio volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 96 Dec 27 18:49:38 volumio sudo[2564]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Dec 27 18:49:38 volumio sudo[2564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 27 18:49:38 volumio sudo[2564]: pam_unix(sudo:session): session closed for user root Dec 27 18:49:38 volumio volumio[1289]: info: peppyspectrum Daemon Stop Dec 27 18:49:38 volumio volumio[1289]: info: Asound.conf file unchanged, so no further update is needed Dec 27 18:49:38 volumio volumio[1289]: info: Output device has changed, restarting MPD Dec 27 18:49:38 volumio volumio[1289]: info: Output device has changed, restarting Shairport Sync Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 27 18:49:38 volumio sudo[2572]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 27 18:49:38 volumio sudo[2572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 27 18:49:38 volumio sudo[2576]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 27 18:49:38 volumio sudo[2576]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 27 18:49:38 volumio go-librespot[1969]: time="2025-12-27T18:49:38+02:00" level=trace msg="sent dealer ping" Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio sudo[2572]: pam_unix(sudo:session): session closed for user root Dec 27 18:49:38 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 27 18:49:38 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 27 18:49:38 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 27 18:49:38 volumio systemd[1]: mpd.service: Consumed 1.619s CPU time. Dec 27 18:49:38 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 27 18:49:38 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 27 18:49:38 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 27 18:49:38 volumio volumio[1289]: info: MPD Permissions set Dec 27 18:49:38 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 27 18:49:38 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 27 18:49:38 volumio volumio[1289]: info: Starting Shairport Sync Dec 27 18:49:39 volumio go-librespot[1969]: time="2025-12-27T18:49:39+02:00" level=trace msg="received dealer pong" Dec 27 18:49:39 volumio sudo[2597]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 27 18:49:39 volumio sudo[2597]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 27 18:49:39 volumio sudo[2597]: pam_unix(sudo:session): session closed for user root Dec 27 18:49:39 volumio sudo[2599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 27 18:49:39 volumio sudo[2599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 27 18:49:39 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 27 18:49:39 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 27 18:49:39 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 27 18:49:39 volumio systemd[1]: shairport-sync.service: Consumed 1.448s CPU time. Dec 27 18:49:39 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 27 18:49:39 volumio sudo[2599]: pam_unix(sudo:session): session closed for user root Dec 27 18:49:39 volumio volumio[1289]: info: Shairport-Sync Started Dec 27 18:49:40 volumio mpd[2601]: 2025-12-27T18:49:40 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 27 18:49:40 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 27 18:49:40 volumio sudo[2576]: pam_unix(sudo:session): session closed for user root Dec 27 18:49:40 volumio volumio[1289]: error: updateQueue error: null Dec 27 18:49:40 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:40 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:40 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:40 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:40 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:40 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:40 volumio volumio[1289]: info: [1766854180914] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:40 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:40 volumio go-librespot[1969]: time="2025-12-27T18:49:40+02:00" level=debug msg="resolved context of track" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:40 volumio go-librespot[1969]: time="2025-12-27T18:49:40+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:40 volumio go-librespot[1969]: time="2025-12-27T18:49:40+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:41 volumio go-librespot[1969]: time="2025-12-27T18:49:41+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:41 volumio go-librespot[1969]: time="2025-12-27T18:49:41+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:41 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","play_origin":"go-librespot"}} Dec 27 18:49:41 volumio go-librespot[1969]: time="2025-12-27T18:49:41+02:00" level=debug msg="selected format OGG_VORBIS_320 (0be3666990cfd63ed7447f7c293b07647a9b5df2)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:41 volumio go-librespot[1969]: time="2025-12-27T18:49:41+02:00" level=debug msg="requested aes key for file 0be3666990cfd63ed7447f7c293b07647a9b5df2, gid: 3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:41 volumio go-librespot[1969]: time="2025-12-27T18:49:41+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3c7KbnkDgpHNz5RVfJyxBV: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:41 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:41 volumio volumio[1289]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Dec 27 18:49:41 volumio volumio[1289]: info: CoreStateMachine::getcurrentVolume Dec 27 18:49:41 volumio volumio[1289]: info: CoreCommandRouter::volumioRetrievevolume Dec 27 18:49:41 volumio volumio[1289]: info: VolumeController:: Volume=96 Mute =false Dec 27 18:49:41 volumio volumio[1289]: info: CoreStateMachine::pushState Dec 27 18:49:41 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:41 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 27 18:49:41 volumio volumio[1289]: info: CoreCommandRouter::volumioPushState Dec 27 18:49:41 volumio volumio[1289]: info: CoreStateMachine::updateTrackBlock Dec 27 18:49:41 volumio volumio[1289]: info: CorePlayQueue::getTrackBlock Dec 27 18:49:41 volumio volumio[1289]: info: CoreCommandRouter::volumioRetrievevolume Dec 27 18:49:41 volumio volumio[1289]: info: PeppySpectrum ---peppyspectrum status stop Dec 27 18:49:41 volumio volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 96 Dec 27 18:49:41 volumio sudo[2624]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Dec 27 18:49:41 volumio sudo[2624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 27 18:49:41 volumio volumio[1289]: info: VolumeController:: Volume=96 Mute =false Dec 27 18:49:41 volumio volumio[1289]: info: CoreStateMachine::pushState Dec 27 18:49:41 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:41 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 27 18:49:41 volumio volumio[1289]: info: CoreCommandRouter::volumioPushState Dec 27 18:49:41 volumio sudo[2624]: pam_unix(sudo:session): session closed for user root Dec 27 18:49:41 volumio volumio[1289]: info: PeppySpectrum ---peppyspectrum status stop Dec 27 18:49:41 volumio volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 96 Dec 27 18:49:41 volumio volumio[1289]: info: peppyspectrum Daemon Stop Dec 27 18:49:41 volumio sudo[2628]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Dec 27 18:49:41 volumio sudo[2628]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 27 18:49:41 volumio sudo[2628]: pam_unix(sudo:session): session closed for user root Dec 27 18:49:41 volumio volumio[1289]: info: peppyspectrum Daemon Stop Dec 27 18:49:43 volumio sudo[2631]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 27 18:49:43 volumio sudo[2631]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 27 18:49:43 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 27 18:49:43 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 27 18:49:43 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 27 18:49:43 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 27 18:49:43 volumio mpd_monitor.sh[2633]: MPD Monitor Service: Starting MPD Monitor Service Dec 27 18:49:43 volumio sudo[2631]: pam_unix(sudo:session): session closed for user root Dec 27 18:49:43 volumio volumio[1289]: info: Successfully started MPD Monitor Dec 27 18:49:44 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:44 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:44 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:44 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:44 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:44 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:44 volumio volumio[1289]: info: [1766854184686] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:44 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:44 volumio go-librespot[1969]: time="2025-12-27T18:49:44+02:00" level=debug msg="resolved context of track" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:44 volumio go-librespot[1969]: time="2025-12-27T18:49:44+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:44 volumio go-librespot[1969]: time="2025-12-27T18:49:44+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:44 volumio go-librespot[1969]: time="2025-12-27T18:49:44+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:44 volumio go-librespot[1969]: time="2025-12-27T18:49:44+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:44 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","play_origin":"go-librespot"}} Dec 27 18:49:44 volumio go-librespot[1969]: time="2025-12-27T18:49:44+02:00" level=debug msg="selected format OGG_VORBIS_320 (0be3666990cfd63ed7447f7c293b07647a9b5df2)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:44 volumio go-librespot[1969]: time="2025-12-27T18:49:44+02:00" level=debug msg="requested aes key for file 0be3666990cfd63ed7447f7c293b07647a9b5df2, gid: 3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:44 volumio go-librespot[1969]: time="2025-12-27T18:49:44+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3c7KbnkDgpHNz5RVfJyxBV: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:44 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:54 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:54 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:54 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:54 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:54 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:54 volumio volumio[1289]: info: CorePlayQueue::getTrack 0 Dec 27 18:49:54 volumio volumio[1289]: info: [1766854194565] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:54 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:54 volumio go-librespot[1969]: time="2025-12-27T18:49:54+02:00" level=debug msg="resolved context of track" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:54 volumio go-librespot[1969]: time="2025-12-27T18:49:54+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:54 volumio go-librespot[1969]: time="2025-12-27T18:49:54+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:54 volumio go-librespot[1969]: time="2025-12-27T18:49:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:54 volumio go-librespot[1969]: time="2025-12-27T18:49:54+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:54 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","uri":"spotify:track:3c7KbnkDgpHNz5RVfJyxBV","play_origin":"go-librespot"}} Dec 27 18:49:54 volumio go-librespot[1969]: time="2025-12-27T18:49:54+02:00" level=debug msg="selected format OGG_VORBIS_320 (0be3666990cfd63ed7447f7c293b07647a9b5df2)" uri="spotify:track:3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:54 volumio go-librespot[1969]: time="2025-12-27T18:49:54+02:00" level=debug msg="requested aes key for file 0be3666990cfd63ed7447f7c293b07647a9b5df2, gid: 3c7KbnkDgpHNz5RVfJyxBV" Dec 27 18:49:54 volumio go-librespot[1969]: time="2025-12-27T18:49:54+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3c7KbnkDgpHNz5RVfJyxBV: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:54 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:56 volumio volumio[1289]: info: CoreCommandRouter::volumioNext Dec 27 18:49:56 volumio volumio[1289]: info: CoreStateMachine::next Dec 27 18:49:56 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:49:56 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:56 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:56 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:56 volumio volumio[1289]: info: CorePlayQueue::getTrack 78 Dec 27 18:49:56 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:56 volumio volumio[1289]: info: CorePlayQueue::getTrack 78 Dec 27 18:49:56 volumio volumio[1289]: info: [1766854196482] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:56 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:56 volumio volumio[1289]: info: CoreStateMachine::updateTrackBlock Dec 27 18:49:56 volumio volumio[1289]: info: CorePlayQueue::getTrackBlock Dec 27 18:49:56 volumio go-librespot[1969]: time="2025-12-27T18:49:56+02:00" level=debug msg="resolved context of track" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:56 volumio go-librespot[1969]: time="2025-12-27T18:49:56+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:56 volumio go-librespot[1969]: time="2025-12-27T18:49:56+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:56 volumio go-librespot[1969]: time="2025-12-27T18:49:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:56 volumio go-librespot[1969]: time="2025-12-27T18:49:56+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:56 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1yCN2w6hOAAwRMrCNtzFhJ","uri":"spotify:track:1yCN2w6hOAAwRMrCNtzFhJ","play_origin":"go-librespot"}} Dec 27 18:49:56 volumio go-librespot[1969]: time="2025-12-27T18:49:56+02:00" level=debug msg="selected format OGG_VORBIS_320 (4d1d45f47b974df83beb28e36c8287f99f290e8b)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:56 volumio go-librespot[1969]: time="2025-12-27T18:49:56+02:00" level=debug msg="requested aes key for file 4d1d45f47b974df83beb28e36c8287f99f290e8b, gid: 1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:56 volumio go-librespot[1969]: time="2025-12-27T18:49:56+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1yCN2w6hOAAwRMrCNtzFhJ: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:56 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:49:57 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:49:57 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:49:57 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:49:57 volumio volumio[1289]: info: CorePlayQueue::getTrack 78 Dec 27 18:49:57 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:49:57 volumio volumio[1289]: info: CorePlayQueue::getTrack 78 Dec 27 18:49:57 volumio volumio[1289]: info: [1766854197856] ControllerSpotify::clearAddPlayTrack Dec 27 18:49:57 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:49:57 volumio go-librespot[1969]: time="2025-12-27T18:49:57+02:00" level=debug msg="resolved context of track" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:57 volumio go-librespot[1969]: time="2025-12-27T18:49:57+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:57 volumio go-librespot[1969]: time="2025-12-27T18:49:57+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:57 volumio go-librespot[1969]: time="2025-12-27T18:49:57+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:49:57 volumio go-librespot[1969]: time="2025-12-27T18:49:57+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:49:58 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1yCN2w6hOAAwRMrCNtzFhJ","uri":"spotify:track:1yCN2w6hOAAwRMrCNtzFhJ","play_origin":"go-librespot"}} Dec 27 18:49:58 volumio go-librespot[1969]: time="2025-12-27T18:49:58+02:00" level=debug msg="selected format OGG_VORBIS_320 (4d1d45f47b974df83beb28e36c8287f99f290e8b)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:58 volumio go-librespot[1969]: time="2025-12-27T18:49:58+02:00" level=debug msg="requested aes key for file 4d1d45f47b974df83beb28e36c8287f99f290e8b, gid: 1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:49:58 volumio go-librespot[1969]: time="2025-12-27T18:49:58+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1yCN2w6hOAAwRMrCNtzFhJ: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:49:58 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:50:02 volumio volumio[1289]: info: CoreCommandRouter::volumioPlay Dec 27 18:50:02 volumio volumio[1289]: info: CoreStateMachine::play index undefined Dec 27 18:50:02 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:50:02 volumio volumio[1289]: info: CorePlayQueue::getTrack 78 Dec 27 18:50:02 volumio volumio[1289]: info: CoreStateMachine::startPlaybackTimer Dec 27 18:50:02 volumio volumio[1289]: info: CorePlayQueue::getTrack 78 Dec 27 18:50:02 volumio volumio[1289]: info: [1766854202207] ControllerSpotify::clearAddPlayTrack Dec 27 18:50:02 volumio volumio[1289]: info: Sending Spotify command with payload to local API: /player/play Dec 27 18:50:02 volumio go-librespot[1969]: time="2025-12-27T18:50:02+02:00" level=debug msg="resolved context of track" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:50:02 volumio go-librespot[1969]: time="2025-12-27T18:50:02+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:50:02 volumio go-librespot[1969]: time="2025-12-27T18:50:02+02:00" level=debug msg="loading track (paused: false, position: 2ms)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:50:02 volumio go-librespot[1969]: time="2025-12-27T18:50:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 18:50:02 volumio go-librespot[1969]: time="2025-12-27T18:50:02+02:00" level=trace msg="emitting websocket event: will_play" Dec 27 18:50:02 volumio volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1yCN2w6hOAAwRMrCNtzFhJ","uri":"spotify:track:1yCN2w6hOAAwRMrCNtzFhJ","play_origin":"go-librespot"}} Dec 27 18:50:02 volumio go-librespot[1969]: time="2025-12-27T18:50:02+02:00" level=debug msg="selected format OGG_VORBIS_320 (4d1d45f47b974df83beb28e36c8287f99f290e8b)" uri="spotify:track:1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:50:02 volumio go-librespot[1969]: time="2025-12-27T18:50:02+02:00" level=debug msg="requested aes key for file 4d1d45f47b974df83beb28e36c8287f99f290e8b, gid: 1yCN2w6hOAAwRMrCNtzFhJ" Dec 27 18:50:02 volumio go-librespot[1969]: time="2025-12-27T18:50:02+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1yCN2w6hOAAwRMrCNtzFhJ: failed retrieving audio key: failed retrieving aes key with code 1" Dec 27 18:50:02 volumio volumio[1289]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 27 18:50:08 volumio go-librespot[1969]: time="2025-12-27T18:50:08+02:00" level=trace msg="sent dealer ping" Dec 27 18:50:08 volumio go-librespot[1969]: time="2025-12-27T18:50:08+02:00" level=trace msg="received dealer pong" Dec 27 18:50:18 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Dec 27 18:50:18 volumio volumio[1289]: info: CURURI: music-library Dec 27 18:50:18 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:50:19 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Dec 27 18:50:19 volumio volumio[1289]: info: CURURI: music-library/USB Dec 27 18:50:19 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:50:20 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:50:20 volumio volumio[1289]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 27 18:50:20 volumio volumio[1289]: info: CoreStateMachine::ClearQueue Dec 27 18:50:20 volumio volumio[1289]: info: CoreStateMachine::stop Dec 27 18:50:20 volumio volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 27 18:50:20 volumio volumio[1289]: info: CorePlayQueue::clearPlayQueue Dec 27 18:50:20 volumio volumio[1289]: info: CorePlayQueue::saveQueue Dec 27 18:50:20 volumio volumio[1289]: info: CoreCommandRouter::volumioPushQueue Dec 27 18:50:20 volumio volumio[1289]: info: CoreStateMachine::addQueueItems Dec 27 18:50:20 volumio volumio[1289]: info: CorePlayQueue::addQueueItems Dec 27 18:50:20 volumio volumio[1289]: info: Preload queue cleared Dec 27 18:50:20 volumio volumio[1289]: info: Adding Item to queue: music-library/USB/3A20E37E20E3400D Dec 27 18:50:20 volumio volumio[1289]: info: Exploding uri music-library/USB/3A20E37E20E3400D in service mpd Dec 27 18:50:23 volumio volumio[1289]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Dec 27 18:50:23 volumio volumio[1289]: info: CURURI: music-library/USB/3A20E37E20E3400D Dec 27 18:50:23 volumio volumio[1289]: info: ALBUMART /albumart?cacheid=251&web=//large&path=%2Fmnt%2FUSB%2F3A20E37E20E3400D%2F16%20Bit%20Featuring%20Eddie%20Hind%2F1987%20(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single)%2F16%20Bit%20Featuring%20Eddie%20Hind%20-%20(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single)%20(Side%20A).wv&metadata=false Dec 27 18:50:23 volumio volumio[1289]: info: URI /mnt/USB/3A20E37E20E3400D/16 Bit Featuring Eddie Hind/1987 (Ina) Gadda-Da-Vida (12'' Maxi-Single)/16 Bit Featuring Eddie Hind - (Ina) Gadda-Da-Vida (12'' Maxi-Single) (Side A).wv Dec 27 18:50:23 volumio volumio[1289]: info: ALBUMART /albumart?cacheid=251&web=//large&path=%2Fmnt%2FUSB%2F3A20E37E20E3400D%2F16%20Bit%20Featuring%20Eddie%20Hind%2F1987%20(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single)%2F16%20Bit%20Featuring%20Eddie%20Hind%20-%20(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single)%20(Side%20B).wv&metadata=false Dec 27 18:50:23 volumio volumio[1289]: info: URI /mnt/USB/3A20E37E20E3400D/16 Bit Featuring Eddie Hind/1987 (Ina) Gadda-Da-Vida (12'' Maxi-Single)/16 Bit Featuring Eddie Hind - (Ina) Gadda-Da-Vida (12'' Maxi-Single) (Side B).wv Dec 27 18:50:23 volumio volumio[1289]: info: ALBUMART /albumart?cacheid=251&web=16%20Bit%20%26%20Eddie%20Hind/(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single)%20(Ariola%20-%20609%20302%2C%20Europe)/large&path=%2Fmnt%2FUSB%2F3A20E37E20E3400D%2F16%20Bit%20Featuring%20Eddie%20Hind%2F1987%20(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single)%2F16%20Bit%20Featuring%20Eddie%20Hind%20-%20(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single).cue&metadata=false Dec 27 18:50:23 volumio volumio[1289]: info: URI /mnt/USB/3A20E37E20E3400D/16 Bit Featuring Eddie Hind/1987 (Ina) Gadda-Da-Vida (12'' Maxi-Single)/16 Bit Featuring Eddie Hind - (Ina) Gadda-Da-Vida (12'' Maxi-Single).cue Dec 27 18:50:23 volumio volumio[1289]: info: ALBUMART /albumart?cacheid=251&web=16%20Bit/(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single)%20(Ariola%20-%20609%20302%2C%20Europe)/large&path=%2Fmnt%2FUSB%2F3A20E37E20E3400D%2F16%20Bit%20Featuring%20Eddie%20Hind%2F1987%20(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single)%2F16%20Bit%20Featuring%20Eddie%20Hind%20-%20(Ina)%20Gadda-Da-Vida%20(12''%20Maxi-Single).cue&metadata=false Dec 27 18:50:23 volumio volumio[1289]: info: URI /mnt/USB/3A20E37E20E3400D/16 Bit Featuring Eddie Hind/1987 (Ina) Gadda-Da-Vida (12'' Maxi-Single)/16 Bit Featuring Eddie Hind - (Ina) Gadda-Da-Vida (12'' Maxi-Single).cue Dec 27 18:50:23 volumio volumio[1289]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 27 18:50:23 volumio volumio[1289]: Error: Unable to resolve or reject the same promise twice Dec 27 18:50:23 volumio volumio[1289]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Dec 27 18:50:23 volumio volumio[1289]: at /volumio/app/plugins/music_service/mpd/index.js:2587:21 Dec 27 18:50:23 volumio volumio[1289]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Dec 27 18:50:23 volumio volumio[1289]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Dec 27 18:50:23 volumio volumio[1289]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Dec 27 18:50:23 volumio volumio[1289]: at Socket.emit (node:events:514:28) Dec 27 18:50:23 volumio volumio[1289]: at addChunk (node:internal/streams/readable:343:12) Dec 27 18:50:23 volumio volumio[1289]: at readableAddChunk (node:internal/streams/readable:312:11) Dec 27 18:50:23 volumio volumio[1289]: at Readable.push (node:internal/streams/readable:253:10) Dec 27 18:50:23 volumio volumio[1289]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Dec 27 18:50:23 volumio volumio[1289]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 27 18:50:27 volumio sudo[2720]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-27 18:49' Dec 27 18:50:27 volumio sudo[2720]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"