-- Logs begin at Wed 2025-06-11 17:01:02 CEST, end at Wed 2025-06-11 19:24:19 CEST. -- Jun 11 19:23:10 volumio volumio[1103]: Searching plugin music_service/spop Jun 11 19:23:10 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: spop , search Jun 11 19:23:10 volumio volumio[1103]: info: All search sources collected, pushing search results Jun 11 19:23:11 volumio volumio[1103]: Searching plugin music_service/spop Jun 11 19:23:11 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: spop , search Jun 11 19:23:12 volumio volumio[1103]: info: All search sources collected, pushing search results Jun 11 19:23:13 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jun 11 19:23:13 volumio volumio[1103]: info: In handleBrowseUri, curUri=spotify:artist:27M9shmwhIjRo7WntpT9Rp Jun 11 19:23:14 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jun 11 19:23:14 volumio volumio[1103]: info: In handleBrowseUri, curUri=spotify:artist:27M9shmwhIjRo7WntpT9Rp Jun 11 19:23:14 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:49ccDOSipaIJ4PcmovJy4h Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:33WV1lT63pq12t9jlyrxlW Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:7nQ9OZQI52vqOyVM7UDhVm Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:0HguGCX8PYSBE2hiSWmjeR Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:1AN3Ljpu2jB6fgtWAyU3oW Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:6aW2iwJxBurjRMkbcKuSRi Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:2jawkv0nQfqrAcf1D1EQNg Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:0tfgbbx3n9EFL4fKIAQRBC Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:1PhwjWzUJRNcKBhgVhxG8l Jun 11 19:23:14 volumio volumio[1103]: info: Preloading song: spotify:track:5pajrflzRSu55mgXcEKLUG Jun 11 19:23:14 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:14 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:14 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:14 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:14 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:15 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:49ccDOSipaIJ4PcmovJy4h Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:33WV1lT63pq12t9jlyrxlW Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:7nQ9OZQI52vqOyVM7UDhVm Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:0HguGCX8PYSBE2hiSWmjeR Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:1AN3Ljpu2jB6fgtWAyU3oW Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:6aW2iwJxBurjRMkbcKuSRi Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:2jawkv0nQfqrAcf1D1EQNg Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:0tfgbbx3n9EFL4fKIAQRBC Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:1PhwjWzUJRNcKBhgVhxG8l Jun 11 19:23:15 volumio volumio[1103]: info: Preloading song: spotify:track:5pajrflzRSu55mgXcEKLUG Jun 11 19:23:15 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:15 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:15 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:15 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:18 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:18 volumio volumio[1103]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::ClearQueue Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::stop Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::clearPlayQueue Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:18 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::addQueueItems Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::addQueueItems Jun 11 19:23:18 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:49ccDOSipaIJ4PcmovJy4h Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:49ccDOSipaIJ4PcmovJy4h in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:49ccDOSipaIJ4PcmovJy4h Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:33WV1lT63pq12t9jlyrxlW Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:33WV1lT63pq12t9jlyrxlW in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:33WV1lT63pq12t9jlyrxlW Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:7nQ9OZQI52vqOyVM7UDhVm Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:7nQ9OZQI52vqOyVM7UDhVm in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:7nQ9OZQI52vqOyVM7UDhVm Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0HguGCX8PYSBE2hiSWmjeR Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:0HguGCX8PYSBE2hiSWmjeR in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:0HguGCX8PYSBE2hiSWmjeR Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:1AN3Ljpu2jB6fgtWAyU3oW Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:1AN3Ljpu2jB6fgtWAyU3oW in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:1AN3Ljpu2jB6fgtWAyU3oW Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:33WV1lT63pq12t9jlyrxlW","service":"spop","name":"The Way I Tend To Be","artist":"Frank Turner","album":"Tape Deck Heart (Deluxe Edition)","type":"song","duration":221,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b58c9232add877f07f3f419","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7nQ9OZQI52vqOyVM7UDhVm","service":"spop","name":"Get Better","artist":"Frank Turner","album":"Positive Songs For Negative People","type":"song","duration":166,"albumart":"https://i.scdn.co/image/ab67616d0000b273cc84c97e364f1fa1c896ea58","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","service":"spop","name":"Be More Kind","artist":"Frank Turner","album":"Be More Kind","type":"song","duration":246,"albumart":"https://i.scdn.co/image/ab67616d0000b273dce3805d8e00aac763236018","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:49ccDOSipaIJ4PcmovJy4h","service":"spop","name":"Recovery","artist":"Frank Turner","album":"Tape Deck Heart (Deluxe Edition)","type":"song","duration":208,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b58c9232add877f07f3f419","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0HguGCX8PYSBE2hiSWmjeR","service":"spop","name":"I Still Believe","artist":"Frank Turner","album":"England Keep My Bones (Deluxe Edition)","type":"song","duration":225,"albumart":"https://i.scdn.co/image/ab67616d0000b273622048d88aeb5a88efec9667","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:18 volumio volumio[1103]: info: CoreCommandRouter::volumioPlay Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::play index 4 Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::addQueueItems Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::addQueueItems Jun 11 19:23:18 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:6aW2iwJxBurjRMkbcKuSRi Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:6aW2iwJxBurjRMkbcKuSRi in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:6aW2iwJxBurjRMkbcKuSRi Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:2jawkv0nQfqrAcf1D1EQNg Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:2jawkv0nQfqrAcf1D1EQNg in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:2jawkv0nQfqrAcf1D1EQNg Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0tfgbbx3n9EFL4fKIAQRBC Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:0tfgbbx3n9EFL4fKIAQRBC in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:0tfgbbx3n9EFL4fKIAQRBC Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:1PhwjWzUJRNcKBhgVhxG8l Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:1PhwjWzUJRNcKBhgVhxG8l in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:1PhwjWzUJRNcKBhgVhxG8l Jun 11 19:23:18 volumio volumio[1103]: info: Adding Item to queue: spotify:track:5pajrflzRSu55mgXcEKLUG Jun 11 19:23:18 volumio volumio[1103]: info: Exploding uri spotify:track:5pajrflzRSu55mgXcEKLUG in service spop Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:5pajrflzRSu55mgXcEKLUG Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::stop Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::play index undefined Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::startPlaybackTimer Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:18 volumio volumio[1103]: info: [1749662598247] ControllerSpotify::clearAddPlayTrack Jun 11 19:23:18 volumio volumio[1103]: info: Sending Spotify command with payload to local API: /player/play Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2jawkv0nQfqrAcf1D1EQNg","service":"spop","name":"Photosynthesis","artist":"Frank Turner","album":"Love Ire & Song","type":"song","duration":252,"albumart":"https://i.scdn.co/image/ab67616d0000b273fcfd5863538f21ef2eb4df2c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6aW2iwJxBurjRMkbcKuSRi","service":"spop","name":"Four Simple Words","artist":"Frank Turner","album":"Tape Deck Heart (Deluxe Edition)","type":"song","duration":296,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b58c9232add877f07f3f419","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="resolved context of track" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0tfgbbx3n9EFL4fKIAQRBC","service":"spop","name":"Plain Sailing Weather","artist":"Frank Turner","album":"Tape Deck Heart (Deluxe Edition)","type":"song","duration":241,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b58c9232add877f07f3f419","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5pajrflzRSu55mgXcEKLUG","service":"spop","name":"The Next Storm","artist":"Frank Turner","album":"Positive Songs For Negative People","type":"song","duration":214,"albumart":"https://i.scdn.co/image/ab67616d0000b273cc84c97e364f1fa1c896ea58","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1PhwjWzUJRNcKBhgVhxG8l","service":"spop","name":"1933","artist":"Frank Turner","album":"Be More Kind","type":"song","duration":187,"albumart":"https://i.scdn.co/image/ab67616d0000b273dce3805d8e00aac763236018","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:18 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=trace msg="emitting websocket event: will_play" Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","play_origin":"go-librespot"}} Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="selected format OGG_VORBIS_320 (c433dc599d876958ea88437dbc962de09d959d3a)" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="requested aes key for file c433dc599d876958ea88437dbc962de09d959d3a, gid: 1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="fetched first chunk of 22, total size is 11068288 bytes" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=info msg="loaded track \"Be More Kind\" (paused: false, position: 0ms, duration: 246973ms, prefetched: false)" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=trace msg="scheduling prefetch in 217s" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=trace msg="emitting websocket event: metadata" Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","name":"Be More Kind","artist_names":["Frank Turner"],"album_name":"Be More Kind","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02dce3805d8e00aac763236018","position":0,"duration":246973,"release_date":"year:2018 month:5 day:4","track_number":4,"disc_number":1}} Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:18 volumio go-librespot[1444]: time="2025-06-11T19:23:18+02:00" level=trace msg="emitting websocket event: playing" Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","play_origin":"go-librespot"}} Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:18 volumio volumio[1103]: SPOTIFY: {"status":"play","service":"spop","title":"Be More Kind","artist":"Frank Turner","album":"Be More Kind","albumart":"https://i.scdn.co/image/ab67616d00001e02dce3805d8e00aac763236018","uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","trackType":"spotify","seek":0,"duration":246,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:18 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:18 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:18 volumio volumio[1103]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Be More Kind","artist":"Frank Turner","album":"Be More Kind","albumart":"https://i.scdn.co/image/ab67616d00001e02dce3805d8e00aac763236018","uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","trackType":"spotify","seek":0,"duration":246,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:18 volumio volumio[1103]: verbose: CURRENT POSITION 4 Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::syncState stateService play Jun 11 19:23:18 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus stop Jun 11 19:23:19 volumio go-librespot[1444]: time="2025-06-11T19:23:19+02:00" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:19 volumio go-librespot[1444]: time="2025-06-11T19:23:19+02:00" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:19 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:19 volumio volumio[1103]: SPOTIFY: {"status":"play","service":"spop","title":"Be More Kind","artist":"Frank Turner","album":"Be More Kind","albumart":"https://i.scdn.co/image/ab67616d00001e02dce3805d8e00aac763236018","uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","trackType":"spotify","seek":0,"duration":246,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:19 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:19 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:19 volumio volumio[1103]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Be More Kind","artist":"Frank Turner","album":"Be More Kind","albumart":"https://i.scdn.co/image/ab67616d00001e02dce3805d8e00aac763236018","uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","trackType":"spotify","seek":0,"duration":246,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:19 volumio volumio[1103]: verbose: CURRENT POSITION 4 Jun 11 19:23:19 volumio volumio[1103]: info: CoreStateMachine::syncState stateService play Jun 11 19:23:19 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus play Jun 11 19:23:19 volumio volumio[1103]: info: Received an update from plugin. extracting info from payload Jun 11 19:23:19 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:19 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:19 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:19 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:19 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:19 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:19 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:19 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:19 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:21 volumio go-librespot[1444]: time="2025-06-11T19:23:21+02:00" level=trace msg="sent dealer ping" Jun 11 19:23:21 volumio go-librespot[1444]: time="2025-06-11T19:23:21+02:00" level=trace msg="received dealer pong" Jun 11 19:23:26 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jun 11 19:23:26 volumio volumio[1103]: info: In handleBrowseUri, curUri=spotify:album:1V0jqCyz5StIhGp16Ggdz7 Jun 11 19:23:26 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:6FOktD0ZXPpXdGQDHgEdrJ Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:0RrSXCmyIpLvhCg7ktX4nZ Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:4bQm41HanVPO4wh6pNpB9L Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:2a4pj4CGoNhLzDTt8ywMNs Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:6Z7bolzCTlmzqjzPGFrC7v Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:4Dz9F7tVEHQu5PC53QOzvl Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:5hhhrZMKz1NEZM7jRWufbf Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:0rQ146AWbwiDC1DheKXJxm Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:7EcFRiCKqijYsuA5UbNnQZ Jun 11 19:23:26 volumio volumio[1103]: info: Preloading song: spotify:track:0YEYytFY23bYyEwHWA9hAH Jun 11 19:23:26 volumio volumio[1103]: info: Exploding uri spotify:track:6FOktD0ZXPpXdGQDHgEdrJ in service spop Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:6FOktD0ZXPpXdGQDHgEdrJ Jun 11 19:23:26 volumio volumio[1103]: info: Exploding uri spotify:track:0RrSXCmyIpLvhCg7ktX4nZ in service spop Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:0RrSXCmyIpLvhCg7ktX4nZ Jun 11 19:23:26 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:26 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:26 volumio volumio[1103]: info: No valid Plugin REST Endpoint Jun 11 19:23:26 volumio volumio[1103]: info: Exploding uri spotify:track:4bQm41HanVPO4wh6pNpB9L in service spop Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:4bQm41HanVPO4wh6pNpB9L Jun 11 19:23:26 volumio volumio[1103]: info: Exploding uri spotify:track:2a4pj4CGoNhLzDTt8ywMNs in service spop Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:2a4pj4CGoNhLzDTt8ywMNs Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6FOktD0ZXPpXdGQDHgEdrJ","service":"spop","name":"Substitute","artist":"NOFX","album":"West Coast vs. Wessex","type":"song","duration":165,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0RrSXCmyIpLvhCg7ktX4nZ","service":"spop","name":"Worse Things Happen at Sea","artist":"NOFX","album":"West Coast vs. Wessex","type":"song","duration":199,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:26 volumio volumio[1103]: info: Exploding uri spotify:track:6Z7bolzCTlmzqjzPGFrC7v in service spop Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:6Z7bolzCTlmzqjzPGFrC7v Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","service":"spop","name":"Thatcher Fucked the Kids","artist":"NOFX","album":"West Coast vs. Wessex","type":"song","duration":187,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:26 volumio volumio[1103]: info: Exploding uri spotify:track:4Dz9F7tVEHQu5PC53QOzvl in service spop Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:4Dz9F7tVEHQu5PC53QOzvl Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","service":"spop","name":"Ballad of Me and My Friends","artist":"NOFX","album":"West Coast vs. Wessex","type":"song","duration":110,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:26 volumio volumio[1103]: info: Exploding uri spotify:track:5hhhrZMKz1NEZM7jRWufbf in service spop Jun 11 19:23:26 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:5hhhrZMKz1NEZM7jRWufbf Jun 11 19:23:27 volumio volumio[1103]: info: Exploding uri spotify:track:0rQ146AWbwiDC1DheKXJxm in service spop Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:0rQ146AWbwiDC1DheKXJxm Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","service":"spop","name":"Glory Hallelujah","artist":"NOFX","album":"West Coast vs. Wessex","type":"song","duration":207,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4Dz9F7tVEHQu5PC53QOzvl","service":"spop","name":"Scavenger Type","artist":"Frank Turner","album":"West Coast vs. Wessex","type":"song","duration":103,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:27 volumio volumio[1103]: info: Exploding uri spotify:track:7EcFRiCKqijYsuA5UbNnQZ in service spop Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:7EcFRiCKqijYsuA5UbNnQZ Jun 11 19:23:27 volumio volumio[1103]: info: Exploding uri spotify:track:0YEYytFY23bYyEwHWA9hAH in service spop Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: EXPLODING URI:spotify:track:0YEYytFY23bYyEwHWA9hAH Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0rQ146AWbwiDC1DheKXJxm","service":"spop","name":"Eat the Meek","artist":"Frank Turner","album":"West Coast vs. Wessex","type":"song","duration":237,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5hhhrZMKz1NEZM7jRWufbf","service":"spop","name":"Bob","artist":"Frank Turner","album":"West Coast vs. Wessex","type":"song","duration":188,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7EcFRiCKqijYsuA5UbNnQZ","service":"spop","name":"Perfect Government","artist":"Frank Turner","album":"West Coast vs. Wessex","type":"song","duration":146,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:27 volumio volumio[1103]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0YEYytFY23bYyEwHWA9hAH","service":"spop","name":"Falling in Love","artist":"Frank Turner","album":"West Coast vs. Wessex","type":"song","duration":248,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 11 19:23:29 volumio go-librespot[1444]: time="2025-06-11T19:23:29+02:00" level=debug msg="fetched chunk 4/21, size: 524288" uri="spotify:track:1AN3Ljpu2jB6fgtWAyU3oW" Jun 11 19:23:32 volumio wpa_supplicant[960]: wlan0: WPA: Group rekeying completed with 74:42:7f:a0:b6:38 [GTK=CCMP] Jun 11 19:23:34 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::ClearQueue Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::stop Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::stPlaybackTimer Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::serviceStop Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::serviceStop Jun 11 19:23:34 volumio volumio[1103]: info: Spotify Stop Jun 11 19:23:34 volumio volumio[1103]: SPOTIFY: SPOTIFY STOP Jun 11 19:23:34 volumio volumio[1103]: SPOTIFY: {"status":"play","position":4,"title":"Be More Kind","artist":"Frank Turner","album":"Be More Kind","albumart":"https://i.scdn.co/image/ab67616d0000b273dce3805d8e00aac763236018","uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","trackType":"spotify","codec":"ogg","seek":0,"duration":246,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":34,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jun 11 19:23:34 volumio volumio[1103]: info: Sending Spotify command to local API: /player/pause Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::clearPlayQueue Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::addQueueItems Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::addQueueItems Jun 11 19:23:34 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:6FOktD0ZXPpXdGQDHgEdrJ Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:6FOktD0ZXPpXdGQDHgEdrJ Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0RrSXCmyIpLvhCg7ktX4nZ Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:0RrSXCmyIpLvhCg7ktX4nZ Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:4bQm41HanVPO4wh6pNpB9L Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:4bQm41HanVPO4wh6pNpB9L Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:2a4pj4CGoNhLzDTt8ywMNs Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:2a4pj4CGoNhLzDTt8ywMNs Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::volumioPlay Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::play index 3 Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::addQueueItems Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::addQueueItems Jun 11 19:23:34 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:6Z7bolzCTlmzqjzPGFrC7v Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:6Z7bolzCTlmzqjzPGFrC7v Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:4Dz9F7tVEHQu5PC53QOzvl Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:4Dz9F7tVEHQu5PC53QOzvl Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:5hhhrZMKz1NEZM7jRWufbf Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:5hhhrZMKz1NEZM7jRWufbf Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0rQ146AWbwiDC1DheKXJxm Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:0rQ146AWbwiDC1DheKXJxm Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:7EcFRiCKqijYsuA5UbNnQZ Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:7EcFRiCKqijYsuA5UbNnQZ Jun 11 19:23:34 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0YEYytFY23bYyEwHWA9hAH Jun 11 19:23:34 volumio volumio[1103]: info: Using cached record of: spotify:track:0YEYytFY23bYyEwHWA9hAH Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::stop Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::play index undefined Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::startPlaybackTimer Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:34 volumio volumio[1103]: info: [1749662614061] ControllerSpotify::clearAddPlayTrack Jun 11 19:23:34 volumio volumio[1103]: info: Sending Spotify command with payload to local API: /player/play Jun 11 19:23:34 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=debug msg="pause track at 15264ms" Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=trace msg="emitting websocket event: paused" Jun 11 19:23:34 volumio volumio[1103]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:1AN3Ljpu2jB6fgtWAyU3oW","play_origin":"go-librespot"}} Jun 11 19:23:34 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:34 volumio volumio[1103]: SPOTIFY: {"status":"pause","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} Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:34 volumio volumio[1103]: verbose: STATE SERVICE {"status":"pause","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} Jun 11 19:23:34 volumio volumio[1103]: verbose: CURRENT POSITION 3 Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::syncState stateService pause Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus stop Jun 11 19:23:34 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:34 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:34 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:34 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=debug msg="resolved context of track" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=trace msg="emitting websocket event: will_play" Jun 11 19:23:34 volumio volumio[1103]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","play_origin":"go-librespot"}} Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=debug msg="selected format OGG_VORBIS_320 (ec01d0b7e670ea589d31aec7a182d9b79e46a7c3)" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:34 volumio go-librespot[1444]: time="2025-06-11T19:23:34+02:00" level=debug msg="requested aes key for file ec01d0b7e670ea589d31aec7a182d9b79e46a7c3, gid: 2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=debug msg="fetched first chunk of 9, total size is 4303716 bytes" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=info msg="loaded track \"Ballad of Me and My Friends\" (paused: false, position: 0ms, duration: 110466ms, prefetched: false)" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=trace msg="scheduling prefetch in 80s" Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=trace msg="emitting websocket event: metadata" Jun 11 19:23:35 volumio volumio[1103]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","name":"Ballad of Me and My Friends","artist_names":["NOFX"],"album_name":"West Coast vs. Wessex","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","position":0,"duration":110466,"release_date":"year:2020 month:7 day:31","track_number":4,"disc_number":1}} Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=debug msg="fetched chunk 1/8, size: 524288" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=trace msg="emitting websocket event: playing" Jun 11 19:23:35 volumio volumio[1103]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","play_origin":"go-librespot"}} Jun 11 19:23:35 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:35 volumio volumio[1103]: SPOTIFY: {"status":"play","service":"spop","title":"Ballad of Me and My Friends","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","trackType":"spotify","seek":0,"duration":110,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:35 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:35 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:35 volumio volumio[1103]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Ballad of Me and My Friends","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","trackType":"spotify","seek":0,"duration":110,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:35 volumio volumio[1103]: verbose: CURRENT POSITION 3 Jun 11 19:23:35 volumio volumio[1103]: info: CoreStateMachine::syncState stateService play Jun 11 19:23:35 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus stop Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=debug msg="fetched chunk 2/8, size: 524288" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:35 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:35 volumio volumio[1103]: SPOTIFY: {"status":"play","service":"spop","title":"Ballad of Me and My Friends","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","trackType":"spotify","seek":0,"duration":110,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:35 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:35 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:35 volumio volumio[1103]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Ballad of Me and My Friends","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","trackType":"spotify","seek":0,"duration":110,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:35 volumio volumio[1103]: verbose: CURRENT POSITION 3 Jun 11 19:23:35 volumio volumio[1103]: info: CoreStateMachine::syncState stateService play Jun 11 19:23:35 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus play Jun 11 19:23:35 volumio volumio[1103]: info: Received an update from plugin. extracting info from payload Jun 11 19:23:35 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:35 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:35 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:35 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:35 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:35 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:35 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:35 volumio go-librespot[1444]: time="2025-06-11T19:23:35+02:00" level=debug msg="fetched chunk 3/8, size: 524288" uri="spotify:track:2a4pj4CGoNhLzDTt8ywMNs" Jun 11 19:23:35 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:35 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:39 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:39 volumio volumio[1103]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::ClearQueue Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::stop Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::stPlaybackTimer Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:39 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:39 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::serviceStop Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::getTrack 3 Jun 11 19:23:39 volumio volumio[1103]: info: CoreCommandRouter::serviceStop Jun 11 19:23:39 volumio volumio[1103]: info: Spotify Stop Jun 11 19:23:39 volumio volumio[1103]: SPOTIFY: SPOTIFY STOP Jun 11 19:23:39 volumio volumio[1103]: SPOTIFY: {"status":"play","position":3,"title":"Ballad of Me and My Friends","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:2a4pj4CGoNhLzDTt8ywMNs","trackType":"spotify","codec":"ogg","seek":0,"duration":110,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":34,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jun 11 19:23:39 volumio volumio[1103]: info: Sending Spotify command to local API: /player/pause Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::clearPlayQueue Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:39 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::addQueueItems Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::addQueueItems Jun 11 19:23:39 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:6FOktD0ZXPpXdGQDHgEdrJ Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:6FOktD0ZXPpXdGQDHgEdrJ Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0RrSXCmyIpLvhCg7ktX4nZ Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:0RrSXCmyIpLvhCg7ktX4nZ Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:4bQm41HanVPO4wh6pNpB9L Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:4bQm41HanVPO4wh6pNpB9L Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:2a4pj4CGoNhLzDTt8ywMNs Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:2a4pj4CGoNhLzDTt8ywMNs Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:6Z7bolzCTlmzqjzPGFrC7v Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:6Z7bolzCTlmzqjzPGFrC7v Jun 11 19:23:39 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:39 volumio volumio[1103]: info: CoreCommandRouter::volumioPlay Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::play index 4 Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::addQueueItems Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::addQueueItems Jun 11 19:23:39 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:4Dz9F7tVEHQu5PC53QOzvl Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:4Dz9F7tVEHQu5PC53QOzvl Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:5hhhrZMKz1NEZM7jRWufbf Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:5hhhrZMKz1NEZM7jRWufbf Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0rQ146AWbwiDC1DheKXJxm Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:0rQ146AWbwiDC1DheKXJxm Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:7EcFRiCKqijYsuA5UbNnQZ Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:7EcFRiCKqijYsuA5UbNnQZ Jun 11 19:23:39 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0YEYytFY23bYyEwHWA9hAH Jun 11 19:23:39 volumio volumio[1103]: info: Using cached record of: spotify:track:0YEYytFY23bYyEwHWA9hAH Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::stop Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:39 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::play index undefined Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:39 volumio volumio[1103]: info: CoreStateMachine::startPlaybackTimer Jun 11 19:23:39 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:39 volumio volumio[1103]: info: [1749662619794] ControllerSpotify::clearAddPlayTrack Jun 11 19:23:39 volumio volumio[1103]: info: Sending Spotify command with payload to local API: /player/play Jun 11 19:23:39 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=debug msg="pause track at 4381ms" Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=debug msg="resolved context of track" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=trace msg="emitting websocket event: will_play" Jun 11 19:23:39 volumio volumio[1103]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","play_origin":"go-librespot"}} Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=debug msg="selected format OGG_VORBIS_320 (fd2ed8ed89bbc64e93c593fb1673c7616d2f2f12)" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:39 volumio go-librespot[1444]: time="2025-06-11T19:23:39+02:00" level=debug msg="requested aes key for file fd2ed8ed89bbc64e93c593fb1673c7616d2f2f12, gid: 6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=debug msg="fetched first chunk of 15, total size is 7848196 bytes" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=info msg="loaded track \"Glory Hallelujah\" (paused: false, position: 1ms, duration: 207162ms, prefetched: false)" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=trace msg="scheduling prefetch in 177s" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=trace msg="emitting websocket event: metadata" Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","name":"Glory Hallelujah","artist_names":["NOFX"],"album_name":"West Coast vs. Wessex","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","position":1,"duration":207162,"release_date":"year:2020 month:7 day:31","track_number":5,"disc_number":1}} Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=trace msg="emitting websocket event: paused" Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","play_origin":"go-librespot"}} Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: {"status":"pause","service":"spop","title":"Glory Hallelujah","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","trackType":"spotify","seek":1,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:40 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:40 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:40 volumio volumio[1103]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Glory Hallelujah","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","trackType":"spotify","seek":1,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:40 volumio volumio[1103]: verbose: CURRENT POSITION 4 Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::syncState stateService pause Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus stop Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:40 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:40 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:40 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=trace msg="emitting websocket event: playing" Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","play_origin":"go-librespot"}} Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: {"status":"play","service":"spop","title":"Glory Hallelujah","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","trackType":"spotify","seek":1,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:40 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:40 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:40 volumio volumio[1103]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Glory Hallelujah","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","trackType":"spotify","seek":1,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:40 volumio volumio[1103]: verbose: CURRENT POSITION 4 Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::syncState stateService play Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus stop Jun 11 19:23:40 volumio go-librespot[1444]: time="2025-06-11T19:23:40+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:6Z7bolzCTlmzqjzPGFrC7v" Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: {"status":"play","service":"spop","title":"Glory Hallelujah","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","trackType":"spotify","seek":1,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:40 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:40 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:40 volumio volumio[1103]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Glory Hallelujah","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","trackType":"spotify","seek":1,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:40 volumio volumio[1103]: verbose: CURRENT POSITION 4 Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::syncState stateService play Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus play Jun 11 19:23:40 volumio volumio[1103]: info: Received an update from plugin. extracting info from payload Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:40 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:40 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:40 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:40 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:40 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:40 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:40 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:42 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:42 volumio volumio[1103]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::ClearQueue Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::stop Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::stPlaybackTimer Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:42 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:42 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::serviceStop Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::getTrack 4 Jun 11 19:23:42 volumio volumio[1103]: info: CoreCommandRouter::serviceStop Jun 11 19:23:42 volumio volumio[1103]: info: Spotify Stop Jun 11 19:23:42 volumio volumio[1103]: SPOTIFY: SPOTIFY STOP Jun 11 19:23:42 volumio volumio[1103]: SPOTIFY: {"status":"play","position":4,"title":"Glory Hallelujah","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d0000b273fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:6Z7bolzCTlmzqjzPGFrC7v","trackType":"spotify","codec":"ogg","seek":1,"duration":207,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":34,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jun 11 19:23:42 volumio volumio[1103]: info: Sending Spotify command to local API: /player/pause Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::clearPlayQueue Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:42 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::addQueueItems Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::addQueueItems Jun 11 19:23:42 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:6FOktD0ZXPpXdGQDHgEdrJ Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:6FOktD0ZXPpXdGQDHgEdrJ Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0RrSXCmyIpLvhCg7ktX4nZ Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:0RrSXCmyIpLvhCg7ktX4nZ Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:4bQm41HanVPO4wh6pNpB9L Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:4bQm41HanVPO4wh6pNpB9L Jun 11 19:23:42 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:42 volumio volumio[1103]: info: CoreCommandRouter::volumioPlay Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::play index 2 Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::addQueueItems Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::addQueueItems Jun 11 19:23:42 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:2a4pj4CGoNhLzDTt8ywMNs Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:2a4pj4CGoNhLzDTt8ywMNs Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:6Z7bolzCTlmzqjzPGFrC7v Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:6Z7bolzCTlmzqjzPGFrC7v Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:4Dz9F7tVEHQu5PC53QOzvl Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:4Dz9F7tVEHQu5PC53QOzvl Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:5hhhrZMKz1NEZM7jRWufbf Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:5hhhrZMKz1NEZM7jRWufbf Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0rQ146AWbwiDC1DheKXJxm Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:0rQ146AWbwiDC1DheKXJxm Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:7EcFRiCKqijYsuA5UbNnQZ Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:7EcFRiCKqijYsuA5UbNnQZ Jun 11 19:23:42 volumio volumio[1103]: info: Adding Item to queue: spotify:track:0YEYytFY23bYyEwHWA9hAH Jun 11 19:23:42 volumio volumio[1103]: info: Using cached record of: spotify:track:0YEYytFY23bYyEwHWA9hAH Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::stop Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:42 volumio volumio[1103]: info: CoreCommandRouter::volumioPushQueue Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::saveQueue Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::play index undefined Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::updateTrackBlock Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::getTrackBlock Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:42 volumio volumio[1103]: info: CoreStateMachine::startPlaybackTimer Jun 11 19:23:42 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:42 volumio volumio[1103]: info: [1749662622073] ControllerSpotify::clearAddPlayTrack Jun 11 19:23:42 volumio volumio[1103]: info: Sending Spotify command with payload to local API: /player/play Jun 11 19:23:42 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="pause track at 1843ms" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="resolved context of track" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=trace msg="emitting websocket event: will_play" Jun 11 19:23:42 volumio volumio[1103]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","play_origin":"go-librespot"}} Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="selected format OGG_VORBIS_320 (57146c9994a034d59cc73a4da20e8632857f26d6)" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="requested aes key for file 57146c9994a034d59cc73a4da20e8632857f26d6, gid: 4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="fetched first chunk of 15, total size is 7418844 bytes" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=info msg="loaded track \"Thatcher Fucked the Kids\" (paused: false, position: 0ms, duration: 187505ms, prefetched: false)" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=trace msg="scheduling prefetch in 157s" Jun 11 19:23:42 volumio go-librespot[1444]: time="2025-06-11T19:23:42+02:00" level=trace msg="emitting websocket event: metadata" Jun 11 19:23:42 volumio volumio[1103]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","name":"Thatcher Fucked the Kids","artist_names":["NOFX"],"album_name":"West Coast vs. Wessex","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","position":0,"duration":187505,"release_date":"year:2020 month:7 day:31","track_number":3,"disc_number":1}} Jun 11 19:23:43 volumio go-librespot[1444]: time="2025-06-11T19:23:43+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:43 volumio go-librespot[1444]: time="2025-06-11T19:23:43+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:43 volumio go-librespot[1444]: time="2025-06-11T19:23:43+02:00" level=trace msg="emitting websocket event: paused" Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","play_origin":"go-librespot"}} Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: {"status":"pause","service":"spop","title":"Thatcher Fucked the Kids","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","trackType":"spotify","seek":0,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:43 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:43 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:43 volumio volumio[1103]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Thatcher Fucked the Kids","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","trackType":"spotify","seek":0,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:43 volumio volumio[1103]: verbose: CURRENT POSITION 2 Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::syncState stateService pause Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus stop Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:43 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:43 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:43 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:43 volumio go-librespot[1444]: time="2025-06-11T19:23:43+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:43 volumio go-librespot[1444]: time="2025-06-11T19:23:43+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 19:23:43 volumio go-librespot[1444]: time="2025-06-11T19:23:43+02:00" level=trace msg="emitting websocket event: playing" Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","play_origin":"go-librespot"}} Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: {"status":"play","service":"spop","title":"Thatcher Fucked the Kids","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","trackType":"spotify","seek":0,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:43 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:43 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:43 volumio volumio[1103]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Thatcher Fucked the Kids","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","trackType":"spotify","seek":0,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:43 volumio volumio[1103]: verbose: CURRENT POSITION 2 Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::syncState stateService play Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus stop Jun 11 19:23:43 volumio go-librespot[1444]: time="2025-06-11T19:23:43+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: {"status":"play","service":"spop","title":"Thatcher Fucked the Kids","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","trackType":"spotify","seek":0,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:43 volumio volumio[1103]: info: CoreCommandRouter::servicePushState Jun 11 19:23:43 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:43 volumio volumio[1103]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Thatcher Fucked the Kids","artist":"NOFX","album":"West Coast vs. Wessex","albumart":"https://i.scdn.co/image/ab67616d00001e02fbe6c9f5ef7c45d4b759268c","uri":"spotify:track:4bQm41HanVPO4wh6pNpB9L","trackType":"spotify","seek":0,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 19:23:43 volumio volumio[1103]: verbose: CURRENT POSITION 2 Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::syncState stateService play Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::syncState currentStatus play Jun 11 19:23:43 volumio volumio[1103]: info: Received an update from plugin. extracting info from payload Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:43 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:43 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 19:23:43 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:43 volumio volumio[1103]: info: CoreStateMachine::pushState Jun 11 19:23:43 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:43 volumio volumio[1103]: info: CoreCommandRouter::volumioPushState Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:43 volumio volumio[1103]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Jun 11 19:23:49 volumio volumio[1103]: info: CoreCommandRouter::volumioGetState Jun 11 19:23:49 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:23:51 volumio go-librespot[1444]: time="2025-06-11T19:23:51+02:00" level=trace msg="sent dealer ping" Jun 11 19:23:51 volumio go-librespot[1444]: time="2025-06-11T19:23:51+02:00" level=trace msg="received dealer pong" Jun 11 19:23:55 volumio go-librespot[1444]: time="2025-06-11T19:23:55+02:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:23:59 volumio volumio[1103]: info: CoreCommandRouter::volumioGetState Jun 11 19:23:59 volumio volumio[1103]: info: CorePlayQueue::getTrack 2 Jun 11 19:24:08 volumio go-librespot[1444]: time="2025-06-11T19:24:08+02:00" level=debug msg="fetched chunk 5/14, size: 524288" uri="spotify:track:4bQm41HanVPO4wh6pNpB9L" Jun 11 19:24:12 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 11 19:24:12 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:24:15 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 11 19:24:15 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:24:16 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 11 19:24:16 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:24:17 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 11 19:24:18 volumio volumio[1103]: info: Preload queue cleared Jun 11 19:24:19 volumio volumio[1103]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 11 19:24:19 volumio volumio[1103]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 11 19:24:19 volumio volumio[1103]: TypeError: Cannot read property 'length' of undefined Jun 11 19:24:19 volumio volumio[1103]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jun 11 19:24:19 volumio volumio[1103]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jun 11 19:24:19 volumio volumio[1103]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jun 11 19:24:19 volumio volumio[1103]: at Parser.emit (events.js:400:28) Jun 11 19:24:19 volumio volumio[1103]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jun 11 19:24:19 volumio volumio[1103]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jun 11 19:24:19 volumio volumio[1103]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jun 11 19:24:19 volumio volumio[1103]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jun 11 19:24:19 volumio volumio[1103]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jun 11 19:24:19 volumio volumio[1103]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jun 11 19:24:19 volumio volumio[1103]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jun 11 19:24:19 volumio volumio[1103]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jun 11 19:24:19 volumio volumio[1103]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jun 11 19:24:19 volumio volumio[1103]: at IncomingMessage.emit (events.js:412:35) Jun 11 19:24:19 volumio volumio[1103]: at endReadableNT (internal/streams/readable.js:1333:12) Jun 11 19:24:19 volumio volumio[1103]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Jun 11 19:24:19 volumio volumio[1103]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 11 19:24:19 volumio sudo[3349]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-11 19:23 Jun 11 19:24:19 volumio sudo[3349]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 03 Jun 2025 10:59:11 AM CEST" VOLUMIO_VERSION="3.813" VOLUMIO_HARDWARE="tinkerboard" VOLUMIO_DEVICENAME="Asus Tinkerboard" VOLUMIO_HASH="4ab7906c45503ee0ba719461ff7118b6"