-- Logs begin at Fri 2025-12-05 11:19:11 CET, end at Sat 2025-12-06 15:08:32 CET. -- Dec 06 15:07:02 volumio volumio[847]: info: Preload queue cleared Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::ClearQueue Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::stop Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::stPlaybackTimer Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::updateTrackBlock Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrackBlock Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 4 Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::serviceStop Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 4 Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::serviceStop Dec 06 15:07:02 volumio volumio[847]: info: Spotify Stop Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: SPOTIFY STOP Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: {"status":"play","position":4,"title":"Sinterklaas Kapoentje","artist":"Kabouter Plop","album":"De leukste Studio 100 Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d0000b273736c238e7d097cf0f75d98d2","uri":"spotify:track:5AATsbjtYNMMTpEl34RVS9","trackType":"spotify","codec":"ogg","seek":0,"duration":133,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":72,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Dec 06 15:07:02 volumio volumio[847]: info: Sending Spotify command to local API: /player/pause Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::clearPlayQueue Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::saveQueue Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioPushQueue Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::addQueueItems Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::addQueueItems Dec 06 15:07:02 volumio volumio[847]: info: Preload queue cleared Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:0qm8UriZo0T9zcCH2Fwawt Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:0qm8UriZo0T9zcCH2Fwawt Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:26sCSwoI6M4oedka9IKmwT Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:26sCSwoI6M4oedka9IKmwT Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:71WSrrmpWoDXsRZMpRPKzg Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:71WSrrmpWoDXsRZMpRPKzg Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:3BDtDLuBwDQ0aFCSNhP5Zk Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:3BDtDLuBwDQ0aFCSNhP5Zk Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:5AATsbjtYNMMTpEl34RVS9 Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:5AATsbjtYNMMTpEl34RVS9 Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:1xmr1XfOOUIYozFai7kbkJ Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:1xmr1XfOOUIYozFai7kbkJ Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:1gniyVviDqJ5q69qyNbc82 Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:1gniyVviDqJ5q69qyNbc82 Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioPushQueue Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::saveQueue Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::updateTrackBlock Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrackBlock Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioPlay Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::play index 6 Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::addQueueItems Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::addQueueItems Dec 06 15:07:02 volumio volumio[847]: info: Preload queue cleared Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:7M2WKMVHYUL1ZRi5vWGQGB Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:7M2WKMVHYUL1ZRi5vWGQGB Dec 06 15:07:02 volumio volumio[847]: info: Adding Item to queue: spotify:track:17YBi262SGA9zYlYzZpHUg Dec 06 15:07:02 volumio volumio[847]: info: Using cached record of: spotify:track:17YBi262SGA9zYlYzZpHUg Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::stop Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioPushQueue Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::saveQueue Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::play index undefined Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::updateTrackBlock Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrackBlock Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::startPlaybackTimer Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:02 volumio volumio[847]: info: [1765030022103] ControllerSpotify::clearAddPlayTrack Dec 06 15:07:02 volumio volumio[847]: info: Sending Spotify command with payload to local API: /player/play Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="pause track at 14910ms" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="resolved context of track" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=trace msg="emitting websocket event: will_play" Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","play_origin":"go-librespot"}} Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="selected format OGG_VORBIS_320 (7cff888f173cdd62dd93ffa4b47339bae2a287c0)" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="requested aes key for file 7cff888f173cdd62dd93ffa4b47339bae2a287c0, gid: 1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="fetched first chunk of 3, total size is 1557490 bytes" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01: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, PCM format = FLOAT_LE" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=info msg="loaded track \"Sinterklaasje bonne bonne bonne\" (paused: false, position: 0ms, duration: 40847ms, prefetched: false)" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=trace msg="scheduling prefetch in 11s" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=trace msg="emitting websocket event: metadata" Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","name":"Sinterklaasje bonne bonne bonne","artist_names":["Olga Octopus","Sinterklaasliedjes","Vlaamse kinderliedjes"],"album_name":"Olga Octopus Vlaamse Sinterklaasliedjes","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0268c4b9465275e392fed1ab04","position":0,"duration":40847,"release_date":"year:2024 month:8 day:2","track_number":3,"disc_number":1}} Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=trace msg="emitting websocket event: paused" Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","play_origin":"go-librespot"}} Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: PUSH STATE SPOTIFY Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: {"status":"pause","service":"spop","title":"Sinterklaasje bonne bonne bonne","artist":"Olga Octopus, Sinterklaasliedjes, Vlaamse kinderliedjes","album":"Olga Octopus Vlaamse Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e0268c4b9465275e392fed1ab04","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","trackType":"spotify","seek":0,"duration":40,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::servicePushState Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:02 volumio volumio[847]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Sinterklaasje bonne bonne bonne","artist":"Olga Octopus, Sinterklaasliedjes, Vlaamse kinderliedjes","album":"Olga Octopus Vlaamse Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e0268c4b9465275e392fed1ab04","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","trackType":"spotify","seek":0,"duration":40,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:02 volumio volumio[847]: verbose: CURRENT POSITION 6 Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::syncState stateService pause Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::syncState currentStatus stop Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="fetched chunk 1/2, size: 524288" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=trace msg="emitting websocket event: playing" Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","resume":false,"play_origin":"go-librespot"}} Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: PUSH STATE SPOTIFY Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: {"status":"play","service":"spop","title":"Sinterklaasje bonne bonne bonne","artist":"Olga Octopus, Sinterklaasliedjes, Vlaamse kinderliedjes","album":"Olga Octopus Vlaamse Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e0268c4b9465275e392fed1ab04","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","trackType":"spotify","seek":0,"duration":40,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::servicePushState Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:02 volumio volumio[847]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sinterklaasje bonne bonne bonne","artist":"Olga Octopus, Sinterklaasliedjes, Vlaamse kinderliedjes","album":"Olga Octopus Vlaamse Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e0268c4b9465275e392fed1ab04","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","trackType":"spotify","seek":0,"duration":40,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:02 volumio volumio[847]: verbose: CURRENT POSITION 6 Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::syncState stateService play Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::syncState currentStatus stop Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: PUSH STATE SPOTIFY Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: {"status":"play","service":"spop","title":"Sinterklaasje bonne bonne bonne","artist":"Olga Octopus, Sinterklaasliedjes, Vlaamse kinderliedjes","album":"Olga Octopus Vlaamse Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e0268c4b9465275e392fed1ab04","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","trackType":"spotify","seek":0,"duration":40,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::servicePushState Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:02 volumio volumio[847]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sinterklaasje bonne bonne bonne","artist":"Olga Octopus, Sinterklaasliedjes, Vlaamse kinderliedjes","album":"Olga Octopus Vlaamse Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e0268c4b9465275e392fed1ab04","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","trackType":"spotify","seek":0,"duration":40,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:02 volumio volumio[847]: verbose: CURRENT POSITION 6 Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::syncState stateService play Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::syncState currentStatus play Dec 06 15:07:02 volumio volumio[847]: info: Received an update from plugin. extracting info from payload Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:02 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:02 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:02 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:02 volumio go-librespot[1164]: time="2025-12-06T15:07:02+01:00" level=debug msg="fetched chunk 2/2, size: 508914" uri="spotify:track:1gniyVviDqJ5q69qyNbc82" Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:02 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:05 volumio go-librespot[1164]: time="2025-12-06T15:07:05+01:00" level=trace msg="sent dealer ping" Dec 06 15:07:05 volumio go-librespot[1164]: time="2025-12-06T15:07:05+01:00" level=trace msg="received dealer pong" Dec 06 15:07:35 volumio go-librespot[1164]: time="2025-12-06T15:07:35+01:00" level=trace msg="sent dealer ping" Dec 06 15:07:35 volumio go-librespot[1164]: time="2025-12-06T15:07:35+01:00" level=trace msg="received dealer pong" Dec 06 15:07:37 volumio volumio[847]: info: CorePlayQueue::getTrack 6 Dec 06 15:07:37 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:37 volumio volumio[847]: info: Prefetching next song Dec 06 15:07:37 volumio volumio[847]: info: [1765030057716] ControllerSpotify::prefetch Dec 06 15:07:37 volumio volumio[847]: info: Sending Spotify command with payload to local API: /player/add_to_queue Dec 06 15:07:37 volumio go-librespot[1164]: time="2025-12-06T15:07:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:37 volumio go-librespot[1164]: time="2025-12-06T15:07:37+01:00" level=debug msg="prefetching next track" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:37 volumio go-librespot[1164]: time="2025-12-06T15:07:37+01:00" level=debug msg="selected format OGG_VORBIS_320 (a291a92a761478570c42fb08c96faafde884e30f)" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:37 volumio go-librespot[1164]: time="2025-12-06T15:07:37+01:00" level=debug msg="requested aes key for file a291a92a761478570c42fb08c96faafde884e30f, gid: 4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:37 volumio go-librespot[1164]: time="2025-12-06T15:07:37+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:38 volumio go-librespot[1164]: time="2025-12-06T15:07:38+01:00" level=debug msg="fetched first chunk of 18, total size is 9187076 bytes" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:38 volumio go-librespot[1164]: time="2025-12-06T15:07:38+01:00" level=info msg="prefetched track \"De Allermooiste Stoomboot\" (duration: 218853ms)" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:38 volumio go-librespot[1164]: time="2025-12-06T15:07:38+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:38 volumio go-librespot[1164]: time="2025-12-06T15:07:38+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:38 volumio go-librespot[1164]: time="2025-12-06T15:07:38+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:42 volumio volumio[847]: info: CoreStateMachine::startPlaybackTimer Dec 06 15:07:42 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=trace msg="emitting websocket event: not_playing" Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=debug msg="loading track (paused: false, position: 2ms)" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","play_origin":"go-librespot"}} Dec 06 15:07:42 volumio volumio[847]: error: Failed to decode event: not_playing Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=trace msg="emitting websocket event: will_play" Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=info msg="loaded track \"De Allermooiste Stoomboot\" (paused: false, position: 2ms, duration: 218853ms, prefetched: true)" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","uri":"spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw","play_origin":"go-librespot"}} Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=trace msg="scheduling prefetch in 189s" Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=trace msg="emitting websocket event: metadata" Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw","name":"De Allermooiste Stoomboot","artist_names":["Prinsessia","Sinterklaasliedjes","Studio 100","Liedjestuin"],"album_name":"De leukste Studio 100 Sinterklaasliedjes","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02736c238e7d097cf0f75d98d2","position":2,"duration":218853,"release_date":"year:2016 month:10 day:28","track_number":4,"disc_number":1}} Dec 06 15:07:42 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:42 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:42 volumio volumio[847]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 15:07:42 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 06 15:07:42 volumio go-librespot[1164]: time="2025-12-06T15:07:42+01:00" level=trace msg="emitting websocket event: playing" Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:1gniyVviDqJ5q69qyNbc82","uri":"spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw","resume":false,"play_origin":"go-librespot"}} Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: PUSH STATE SPOTIFY Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: {"status":"play","service":"spop","title":"De Allermooiste Stoomboot","artist":"Prinsessia, Sinterklaasliedjes, Studio 100, Liedjestuin","album":"De leukste Studio 100 Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e02736c238e7d097cf0f75d98d2","uri":"spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw","trackType":"spotify","seek":2,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:42 volumio volumio[847]: info: CoreCommandRouter::servicePushState Dec 06 15:07:42 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:42 volumio volumio[847]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"De Allermooiste Stoomboot","artist":"Prinsessia, Sinterklaasliedjes, Studio 100, Liedjestuin","album":"De leukste Studio 100 Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e02736c238e7d097cf0f75d98d2","uri":"spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw","trackType":"spotify","seek":2,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:42 volumio volumio[847]: verbose: CURRENT POSITION 7 Dec 06 15:07:42 volumio volumio[847]: info: CoreStateMachine::syncState stateService play Dec 06 15:07:42 volumio volumio[847]: info: CoreStateMachine::syncState currentStatus play Dec 06 15:07:42 volumio volumio[847]: info: Received an update from plugin. extracting info from payload Dec 06 15:07:42 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:42 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:42 volumio volumio[847]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 15:07:42 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:42 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:42 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:42 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:42 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: PUSH STATE SPOTIFY Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: {"status":"play","service":"spop","title":"De Allermooiste Stoomboot","artist":"Prinsessia, Sinterklaasliedjes, Studio 100, Liedjestuin","album":"De leukste Studio 100 Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e02736c238e7d097cf0f75d98d2","uri":"spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw","trackType":"spotify","seek":2,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:43 volumio volumio[847]: info: CoreCommandRouter::servicePushState Dec 06 15:07:43 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:43 volumio volumio[847]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"De Allermooiste Stoomboot","artist":"Prinsessia, Sinterklaasliedjes, Studio 100, Liedjestuin","album":"De leukste Studio 100 Sinterklaasliedjes","albumart":"https://i.scdn.co/image/ab67616d00001e02736c238e7d097cf0f75d98d2","uri":"spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw","trackType":"spotify","seek":2,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 06 15:07:43 volumio volumio[847]: verbose: CURRENT POSITION 7 Dec 06 15:07:43 volumio volumio[847]: info: CoreStateMachine::syncState stateService play Dec 06 15:07:43 volumio volumio[847]: info: CoreStateMachine::syncState currentStatus play Dec 06 15:07:43 volumio volumio[847]: info: Received an update from plugin. extracting info from payload Dec 06 15:07:43 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:43 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:43 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:43 volumio volumio[847]: info: CoreStateMachine::pushState Dec 06 15:07:43 volumio volumio[847]: info: CorePlayQueue::getTrack 7 Dec 06 15:07:43 volumio volumio[847]: info: CoreCommandRouter::volumioPushState Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: SPOTIFY VOLUME 73 Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: VOLUMIO VOLUME 72 Dec 06 15:07:43 volumio volumio[847]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 06 15:07:54 volumio go-librespot[1164]: time="2025-12-06T15:07:54+01:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:08:05 volumio go-librespot[1164]: time="2025-12-06T15:08:05+01:00" level=trace msg="sent dealer ping" Dec 06 15:08:05 volumio go-librespot[1164]: time="2025-12-06T15:08:05+01:00" level=trace msg="received dealer pong" Dec 06 15:08:06 volumio go-librespot[1164]: time="2025-12-06T15:08:06+01:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:08:18 volumio go-librespot[1164]: time="2025-12-06T15:08:18+01:00" level=debug msg="fetched chunk 6/17, size: 524288" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:08:27 volumio volumio[847]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 06 15:08:27 volumio volumio[847]: info: In handleBrowseUri, curUri=spotify:artist:6EKes6xaBnquLPXy5DpooY Dec 06 15:08:28 volumio volumio[847]: info: Preload queue cleared Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:4lMTOCsWcLj0aOpdlicJfi Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:1Xo75g8OibyD6WvYetFPxH Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:5HA9OAQ8rxvptW57rDrsXI Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:32jrmdiMdAMoFMOB3p4GK2 Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:3ekaLV3gIl1yjvIfBtRvxI Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:1g52sTSFcLrXU7tBwtC77R Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:74Ln0wvgK2lhgInj2EWuci Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:2Sonyeh6iaDpbfdIwyJ9gM Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:4geEtxtLXYtE9tSqSvDAiu Dec 06 15:08:28 volumio volumio[847]: info: Preloading song: spotify:track:6b4Z3f0noCg8s1X0U1lYRw Dec 06 15:08:28 volumio volumio[847]: info: Preload queue cleared Dec 06 15:08:28 volumio volumio[847]: info: Preload queue cleared Dec 06 15:08:28 volumio volumio[847]: info: Executing endpoint getSimilarArtists Dec 06 15:08:28 volumio volumio[847]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Dec 06 15:08:28 volumio volumio[847]: info: Executing endpoint metavolumio Dec 06 15:08:28 volumio volumio[847]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 06 15:08:31 volumio go-librespot[1164]: time="2025-12-06T15:08:31+01:00" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:4V7hRiSYiwLxXJ2Xp0kbcw" Dec 06 15:08:31 volumio volumio[847]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 15:08:31 volumio volumio[847]: TypeError: Cannot read property 'slice' of null Dec 06 15:08:31 volumio volumio[847]: at download (/volumio/app/plugins/miscellanea/albumart/albumart.js:718:41) Dec 06 15:08:31 volumio volumio[847]: at ClientRequest. (/volumio/app/plugins/miscellanea/albumart/albumart.js:728:7) Dec 06 15:08:31 volumio volumio[847]: at Object.onceWrapper (events.js:422:26) Dec 06 15:08:31 volumio volumio[847]: at ClientRequest.emit (events.js:315:20) Dec 06 15:08:31 volumio volumio[847]: at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:641:27) Dec 06 15:08:31 volumio volumio[847]: at HTTPParser.parserOnHeadersComplete (_http_common.js:126:17) Dec 06 15:08:31 volumio volumio[847]: at TLSSocket.socketOnData (_http_client.js:509:22) Dec 06 15:08:31 volumio volumio[847]: at TLSSocket.emit (events.js:315:20) Dec 06 15:08:31 volumio volumio[847]: at addChunk (internal/streams/readable.js:309:12) Dec 06 15:08:31 volumio volumio[847]: at readableAddChunk (internal/streams/readable.js:284:9) Dec 06 15:08:31 volumio volumio[847]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 15:08:32 volumio sudo[18746]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-06 15:07 Dec 06 15:08:32 volumio sudo[18746]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="cc50ad4a2058d01de272214eb33827883bd2b7d8" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="502750e5d54ecf269d25125b622bfabc030fb553" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 12 Nov 2025 06:58:02 PM CET" VOLUMIO_VERSION="3.874" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4ae6504ed6f22e44c01a6e93b16badbd"