Sep 15 20:12:03 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:03 volumio volumio[1099]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::ClearQueue Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::stPlaybackTimer Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:03 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:03 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::serviceStop Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:03 volumio volumio[1099]: info: CoreCommandRouter::serviceStop Sep 15 20:12:03 volumio volumio[1099]: info: Spotify Stop Sep 15 20:12:03 volumio volumio[1099]: SPOTIFY: SPOTIFY STOP Sep 15 20:12:03 volumio volumio[1099]: SPOTIFY: {"status":"play","position":3,"title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d0000b2736df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","codec":"ogg","seek":318,"duration":217,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":"70","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Sep 15 20:12:03 volumio volumio[1099]: info: Sending Spotify command to local API: /player/pause Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::clearPlayQueue Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:03 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:12:03 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:3WgAWLldWRQvMNj1NI0Xcr Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:3WgAWLldWRQvMNj1NI0Xcr Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:419diT5slwDx5LaXXjhU25 Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:419diT5slwDx5LaXXjhU25 Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:0cvilndw7e1iLWob1gUVMq Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:0cvilndw7e1iLWob1gUVMq Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6MTsfDyLSejmtQtyD2ORr2 Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:6MTsfDyLSejmtQtyD2ORr2 Sep 15 20:12:03 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:03 volumio volumio[1099]: info: CoreCommandRouter::volumioPlay Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::play index 3 Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:12:03 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:0xO4bgGhRVh15cnP0mWaDb Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:0xO4bgGhRVh15cnP0mWaDb Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:03xOHkMsdzs3qH9OVhz6Q6 Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:03xOHkMsdzs3qH9OVhz6Q6 Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:1wOOAanReSJuIcEL4Kl1K0 Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:1wOOAanReSJuIcEL4Kl1K0 Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:5z9uYIYaF7xjea23aftzc8 Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:5z9uYIYaF7xjea23aftzc8 Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:3ezqYb3yjMiNv0Eu9dFojT Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:3ezqYb3yjMiNv0Eu9dFojT Sep 15 20:12:03 volumio volumio[1099]: info: Adding Item to queue: spotify:track:7cMnAxe6ZSrhaMORBpeVqQ Sep 15 20:12:03 volumio volumio[1099]: info: Using cached record of: spotify:track:7cMnAxe6ZSrhaMORBpeVqQ Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:03 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::play index undefined Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:03 volumio volumio[1099]: info: CoreStateMachine::startPlaybackTimer Sep 15 20:12:03 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:03 volumio volumio[1099]: info: [1757959923772] ControllerSpotify::clearAddPlayTrack Sep 15 20:12:03 volumio volumio[1099]: info: Sending Spotify command with payload to local API: /player/play Sep 15 20:12:03 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:03 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:03 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:03 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=debug msg="pause track at 0ms" Sep 15 20:12:03 volumio volumio[1099]: info: touch_display: Setting screensaver timeout to 0 seconds. Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=debug msg="resolved context of track" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=trace msg="emitting websocket event: will_play" Sep 15 20:12:03 volumio volumio[1099]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","play_origin":"go-librespot"}} Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=debug msg="selected format OGG_VORBIS_320 (9afa0dd6902733bf762c348b042b35286b5d9d78)" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=debug msg="requested aes key for file 9afa0dd6902733bf762c348b042b35286b5d9d78, gid: 6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:03 volumio go-librespot[1418]: time="2025-09-15T20:12:03+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=debug msg="fetched first chunk of 20, total size is 10151856 bytes" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=info msg="loaded track \"Living in the Night - Euro Classic Radio\" (paused: false, position: 0ms, duration: 217472ms, prefetched: false)" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=trace msg="scheduling prefetch in 187s" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=trace msg="emitting websocket event: metadata" Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","name":"Living in the Night - Euro Classic Radio","artist_names":["Blizzard"],"album_name":"Living in the Night","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","position":0,"duration":217472,"release_date":"year:1997 month:3 day:16","track_number":1,"disc_number":1}} Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=trace msg="emitting websocket event: paused" Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","play_origin":"go-librespot"}} Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: {"status":"pause","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:04 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:04 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:04 volumio volumio[1099]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:04 volumio volumio[1099]: verbose: CURRENT POSITION 3 Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::syncState stateService pause Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:04 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:04 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:04 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=trace msg="emitting websocket event: playing" Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","resume":false,"play_origin":"go-librespot"}} Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:04 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:04 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:04 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:04 volumio volumio[1099]: verbose: CURRENT POSITION 3 Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:12:04 volumio go-librespot[1418]: time="2025-09-15T20:12:04+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:04 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:04 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:04 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:04 volumio volumio[1099]: verbose: CURRENT POSITION 3 Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:12:04 volumio volumio[1099]: info: Received an update from plugin. extracting info from payload Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:04 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:04 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:04 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:04 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:04 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:04 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:04 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:09 volumio go-librespot[1418]: time="2025-09-15T20:12:09+02:00" level=trace msg="sent dealer ping" Sep 15 20:12:09 volumio go-librespot[1418]: time="2025-09-15T20:12:09+02:00" level=trace msg="received dealer pong" Sep 15 20:12:10 volumio go-librespot[1418]: time="2025-09-15T20:12:10+02:00" level=trace msg="received accesspoint ping" Sep 15 20:12:10 volumio go-librespot[1418]: time="2025-09-15T20:12:10+02:00" level=trace msg="received accesspoint pong ack" Sep 15 20:12:11 volumio volumio[1099]: info: CoreCommandRouter::volumioSeek Sep 15 20:12:11 volumio volumio[1099]: info: CoreStateMachine::seek Sep 15 20:12:11 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:11 volumio volumio[1099]: info: TRACKBLOCK {"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","service":"spop","name":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","type":"song","duration":217,"albumart":"https://i.scdn.co/image/ab67616d0000b2736df10268bcd2d0e2f61d065c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify","channels":2} Sep 15 20:12:11 volumio volumio[1099]: info: CoreStateMachine::startPlaybackTimer Sep 15 20:12:11 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:11 volumio volumio[1099]: info: Spotify seek to: 43000 Sep 15 20:12:11 volumio volumio[1099]: info: Sending Spotify command with payload to local API: /player/seek Sep 15 20:12:11 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:11 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:11 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:11 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:11 volumio go-librespot[1418]: time="2025-09-15T20:12:11+02:00" level=debug msg="seek track to 43000ms" Sep 15 20:12:11 volumio go-librespot[1418]: time="2025-09-15T20:12:11+02:00" level=trace msg="seek to 43000ms (diff: 97ms, samples: 1896300, bytes: 1980537)" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:11 volumio go-librespot[1418]: time="2025-09-15T20:12:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:11 volumio go-librespot[1418]: time="2025-09-15T20:12:11+02:00" level=trace msg="scheduling prefetch in 144s" Sep 15 20:12:11 volumio go-librespot[1418]: time="2025-09-15T20:12:11+02:00" level=trace msg="emitting websocket event: seek" Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","position":43000,"duration":217472,"play_origin":"go-librespot"}} Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":43000,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:11 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:11 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:11 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":43000,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:11 volumio volumio[1099]: verbose: CURRENT POSITION 3 Sep 15 20:12:11 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:11 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:12:11 volumio volumio[1099]: info: Received an update from plugin. extracting info from payload Sep 15 20:12:11 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:11 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:11 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:11 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:11 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:11 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:11 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:11 volumio go-librespot[1418]: time="2025-09-15T20:12:11+02:00" level=debug msg="fetched chunk 6/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:11 volumio go-librespot[1418]: time="2025-09-15T20:12:11+02:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:11 volumio go-librespot[1418]: time="2025-09-15T20:12:11+02:00" level=debug msg="fetched chunk 5/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:13 volumio go-librespot[1418]: time="2025-09-15T20:12:13+02:00" level=debug msg="fetched chunk 7/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:15 volumio volumio[1099]: info: CoreCommandRouter::volumioGetState Sep 15 20:12:15 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:17 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: spop , getTrack Sep 15 20:12:17 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","service":"spop","name":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","type":"song","duration":217,"albumart":"https://i.scdn.co/image/ab67616d0000b2736df10268bcd2d0e2f61d065c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:17 volumio volumio[1099]: info: Saving local item spotify Sep 15 20:12:17 volumio volumio[1099]: info: Pushing Favourites {"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","favourite":false} Sep 15 20:12:17 volumio volumio[1099]: info: Listing playlists Sep 15 20:12:23 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Sep 15 20:12:24 volumio go-librespot[1418]: time="2025-09-15T20:12:24+02:00" level=debug msg="fetched chunk 8/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:35 volumio go-librespot[1418]: time="2025-09-15T20:12:35+02:00" level=debug msg="fetched chunk 9/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:39 volumio go-librespot[1418]: time="2025-09-15T20:12:39+02:00" level=trace msg="sent dealer ping" Sep 15 20:12:39 volumio go-librespot[1418]: time="2025-09-15T20:12:39+02:00" level=trace msg="received dealer pong" Sep 15 20:12:46 volumio go-librespot[1418]: time="2025-09-15T20:12:46+02:00" level=debug msg="fetched chunk 10/19, size: 524288" uri="spotify:track:6MTsfDyLSejmtQtyD2ORr2" Sep 15 20:12:48 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Sep 15 20:12:48 volumio volumio[1099]: info: In handleBrowseUri, curUri=spotify:artist:0mKtJHTnqoaWno5CegNhvH Sep 15 20:12:48 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:3w9ydXtambQSZiTrk190rx Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:794pD05ZvML3qJEWfbTaXL Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:6Qvu1UMke7H9Gp1MLtDo6y Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:31wLjiT7yI1d5k5Fgm45vA Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:6i4ijjoogwP5gNSFFGyiLH Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:7c7ZnRUOf5tp3H2k6xllOw Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:1oUWfVn9Qe6XGPztjWRHL4 Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:6VQQU8D0Uc7PzZrHJadYhe Sep 15 20:12:48 volumio volumio[1099]: info: Preloading song: spotify:track:5ttWTSSXMi3EajZhoT2X3o Sep 15 20:12:48 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:48 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:48 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:12:48 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:12:48 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:12:48 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:12:48 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:12:50 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::ClearQueue Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::stPlaybackTimer Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::serviceStop Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::serviceStop Sep 15 20:12:50 volumio volumio[1099]: info: Spotify Stop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: SPOTIFY STOP Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: {"status":"play","position":3,"title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d0000b2736df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","codec":"ogg","seek":43000,"duration":217,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":"70","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Sep 15 20:12:50 volumio volumio[1099]: info: Sending Spotify command to local API: /player/pause Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::clearPlayQueue Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:12:50 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:3w9ydXtambQSZiTrk190rx Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:3w9ydXtambQSZiTrk190rx in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:3w9ydXtambQSZiTrk190rx Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:50 volumio go-librespot[1418]: time="2025-09-15T20:12:50+02:00" level=debug msg="pause track at 82333ms" Sep 15 20:12:50 volumio volumio[1099]: info: touch_display: Setting screensaver timeout to 0 seconds. Sep 15 20:12:50 volumio go-librespot[1418]: time="2025-09-15T20:12:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:50 volumio go-librespot[1418]: time="2025-09-15T20:12:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:50 volumio go-librespot[1418]: time="2025-09-15T20:12:50+02:00" level=trace msg="emitting websocket event: paused" Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","play_origin":"go-librespot"}} Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: {"status":"pause","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":82000,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:50 volumio volumio[1099]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Living in the Night - Euro Classic Radio","artist":"Blizzard","album":"Living in the Night","albumart":"https://i.scdn.co/image/ab67616d00001e026df10268bcd2d0e2f61d065c","uri":"spotify:track:6MTsfDyLSejmtQtyD2ORr2","trackType":"spotify","seek":82000,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:50 volumio volumio[1099]: verbose: CURRENT POSITION 3 Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::syncState stateService pause Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3w9ydXtambQSZiTrk190rx","service":"spop","name":"I Wanna Know - Radio Edit","artist":"Master Jam","album":"I Wanna Know","type":"song","duration":236,"albumart":"https://i.scdn.co/image/ab67616d0000b2739f34e704198c4ba6bf6b83cc","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:50 volumio volumio[1099]: info: CoreCommandRouter::volumioPlay Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::play index 0 Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:12:50 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:794pD05ZvML3qJEWfbTaXL Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:794pD05ZvML3qJEWfbTaXL in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:794pD05ZvML3qJEWfbTaXL Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6Qvu1UMke7H9Gp1MLtDo6y Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:6Qvu1UMke7H9Gp1MLtDo6y in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:6Qvu1UMke7H9Gp1MLtDo6y Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:31wLjiT7yI1d5k5Fgm45vA Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:31wLjiT7yI1d5k5Fgm45vA in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:31wLjiT7yI1d5k5Fgm45vA Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6i4ijjoogwP5gNSFFGyiLH Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:6i4ijjoogwP5gNSFFGyiLH in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:6i4ijjoogwP5gNSFFGyiLH Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:7c7ZnRUOf5tp3H2k6xllOw Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:7c7ZnRUOf5tp3H2k6xllOw in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:7c7ZnRUOf5tp3H2k6xllOw Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:1oUWfVn9Qe6XGPztjWRHL4 Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:1oUWfVn9Qe6XGPztjWRHL4 in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:1oUWfVn9Qe6XGPztjWRHL4 Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6VQQU8D0Uc7PzZrHJadYhe Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:6VQQU8D0Uc7PzZrHJadYhe in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:6VQQU8D0Uc7PzZrHJadYhe Sep 15 20:12:50 volumio volumio[1099]: info: Adding Item to queue: spotify:track:5ttWTSSXMi3EajZhoT2X3o Sep 15 20:12:50 volumio volumio[1099]: info: Exploding uri spotify:track:5ttWTSSXMi3EajZhoT2X3o in service spop Sep 15 20:12:50 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:5ttWTSSXMi3EajZhoT2X3o Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::play index undefined Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:12:50 volumio volumio[1099]: info: CoreStateMachine::startPlaybackTimer Sep 15 20:12:50 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:12:50 volumio volumio[1099]: info: [1757959970904] ControllerSpotify::clearAddPlayTrack Sep 15 20:12:50 volumio volumio[1099]: info: Sending Spotify command with payload to local API: /player/play Sep 15 20:12:50 volumio go-librespot[1418]: time="2025-09-15T20:12:50+02:00" level=debug msg="resolved context of track" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:50 volumio go-librespot[1418]: time="2025-09-15T20:12:50+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:50 volumio go-librespot[1418]: time="2025-09-15T20:12:50+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=trace msg="emitting websocket event: will_play" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="selected format OGG_VORBIS_320 (f65c58a96c74bbcf398b5ab517d9c094108647e2)" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="requested aes key for file f65c58a96c74bbcf398b5ab517d9c094108647e2, gid: 3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3w9ydXtambQSZiTrk190rx","play_origin":"go-librespot"}} Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7c7ZnRUOf5tp3H2k6xllOw","service":"spop","name":"Dancin' All Night","artist":"Master Jam","album":"Dancin' All Night","type":"song","duration":418,"albumart":"https://i.scdn.co/image/ab67616d0000b27374b2d1d7eaaa30c9f44ece36","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6Qvu1UMke7H9Gp1MLtDo6y","service":"spop","name":"I Wanna Know - Club Mix","artist":"Master Jam","album":"I Wanna Know","type":"song","duration":373,"albumart":"https://i.scdn.co/image/ab67616d0000b2739f34e704198c4ba6bf6b83cc","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","service":"spop","name":"I Wanna Know - Eurotracks Remix","artist":"Master Jam","album":"I Wanna Know","type":"song","duration":448,"albumart":"https://i.scdn.co/image/ab67616d0000b2739f34e704198c4ba6bf6b83cc","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:794pD05ZvML3qJEWfbTaXL","service":"spop","name":"Rhythm's In Your Mind - Radio Edit","artist":"Master Jam","album":"Rhytm's In Your Mind","type":"song","duration":243,"albumart":"https://i.scdn.co/image/ab67616d0000b273b8977a407dd4ea0242e99022","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1oUWfVn9Qe6XGPztjWRHL4","service":"spop","name":"Rhythm's In Your Mind - Masterjam Mix","artist":"Master Jam","album":"Rhytm's In Your Mind","type":"song","duration":337,"albumart":"https://i.scdn.co/image/ab67616d0000b273b8977a407dd4ea0242e99022","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","service":"spop","name":"Rhythm's In Your Mind - Extended Version","artist":"Master Jam","album":"Rhytm's In Your Mind","type":"song","duration":353,"albumart":"https://i.scdn.co/image/ab67616d0000b273b8977a407dd4ea0242e99022","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5ttWTSSXMi3EajZhoT2X3o","service":"spop","name":"Tarjeta Roja","artist":"Master Jam","album":"Tarjeta Roja","type":"song","duration":216,"albumart":"https://i.scdn.co/image/ab67616d0000b273332c9835f470d5a561f4d9d7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6VQQU8D0Uc7PzZrHJadYhe","service":"spop","name":"Los Balazos Oficial","artist":"Master Jam","album":"Los Balazos Oficial","type":"song","duration":208,"albumart":"https://i.scdn.co/image/ab67616d0000b273137ec980040ec2563aa9f851","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:12:51 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:51 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:51 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:51 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="fetched first chunk of 16, total size is 7904116 bytes" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=info msg="loaded track \"I Wanna Know - Radio Edit\" (paused: false, position: 0ms, duration: 236239ms, prefetched: false)" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=trace msg="scheduling prefetch in 206s" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=trace msg="emitting websocket event: metadata" Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3w9ydXtambQSZiTrk190rx","name":"I Wanna Know - Radio Edit","artist_names":["Master Jam"],"album_name":"I Wanna Know","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","position":0,"duration":236239,"release_date":"year:2016 month:4 day:13","track_number":3,"disc_number":1}} Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=trace msg="emitting websocket event: playing" Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3w9ydXtambQSZiTrk190rx","resume":false,"play_origin":"go-librespot"}} Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"I Wanna Know - Radio Edit","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","uri":"spotify:track:3w9ydXtambQSZiTrk190rx","trackType":"spotify","seek":0,"duration":236,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:51 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:51 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:12:51 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"I Wanna Know - Radio Edit","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","uri":"spotify:track:3w9ydXtambQSZiTrk190rx","trackType":"spotify","seek":0,"duration":236,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:51 volumio volumio[1099]: verbose: CURRENT POSITION 0 Sep 15 20:12:51 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:51 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio go-librespot[1418]: time="2025-09-15T20:12:51+02:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:3w9ydXtambQSZiTrk190rx" Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"I Wanna Know - Radio Edit","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","uri":"spotify:track:3w9ydXtambQSZiTrk190rx","trackType":"spotify","seek":0,"duration":236,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:51 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:51 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:12:51 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"I Wanna Know - Radio Edit","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","uri":"spotify:track:3w9ydXtambQSZiTrk190rx","trackType":"spotify","seek":0,"duration":236,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:51 volumio volumio[1099]: verbose: CURRENT POSITION 0 Sep 15 20:12:51 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:51 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:12:51 volumio volumio[1099]: info: Received an update from plugin. extracting info from payload Sep 15 20:12:51 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:51 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:12:51 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:51 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:51 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:51 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:12:51 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:51 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:53 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:53 volumio volumio[1099]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::ClearQueue Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::stPlaybackTimer Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:12:53 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:53 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::serviceStop Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:12:53 volumio volumio[1099]: info: CoreCommandRouter::serviceStop Sep 15 20:12:53 volumio volumio[1099]: info: Spotify Stop Sep 15 20:12:53 volumio volumio[1099]: SPOTIFY: SPOTIFY STOP Sep 15 20:12:53 volumio volumio[1099]: SPOTIFY: {"status":"play","position":0,"title":"I Wanna Know - Radio Edit","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d0000b2739f34e704198c4ba6bf6b83cc","uri":"spotify:track:3w9ydXtambQSZiTrk190rx","trackType":"spotify","codec":"ogg","seek":0,"duration":236,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":"70","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Sep 15 20:12:53 volumio volumio[1099]: info: Sending Spotify command to local API: /player/pause Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::clearPlayQueue Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:53 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:12:53 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:3w9ydXtambQSZiTrk190rx Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:3w9ydXtambQSZiTrk190rx Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:794pD05ZvML3qJEWfbTaXL Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:794pD05ZvML3qJEWfbTaXL Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6Qvu1UMke7H9Gp1MLtDo6y Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:6Qvu1UMke7H9Gp1MLtDo6y Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:31wLjiT7yI1d5k5Fgm45vA Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:31wLjiT7yI1d5k5Fgm45vA Sep 15 20:12:53 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:53 volumio volumio[1099]: info: CoreCommandRouter::volumioPlay Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::play index 3 Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:12:53 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6i4ijjoogwP5gNSFFGyiLH Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:6i4ijjoogwP5gNSFFGyiLH Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:7c7ZnRUOf5tp3H2k6xllOw Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:7c7ZnRUOf5tp3H2k6xllOw Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:1oUWfVn9Qe6XGPztjWRHL4 Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:1oUWfVn9Qe6XGPztjWRHL4 Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6VQQU8D0Uc7PzZrHJadYhe Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:6VQQU8D0Uc7PzZrHJadYhe Sep 15 20:12:53 volumio volumio[1099]: info: Adding Item to queue: spotify:track:5ttWTSSXMi3EajZhoT2X3o Sep 15 20:12:53 volumio volumio[1099]: info: Using cached record of: spotify:track:5ttWTSSXMi3EajZhoT2X3o Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:53 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::play index undefined Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:53 volumio volumio[1099]: info: CoreStateMachine::startPlaybackTimer Sep 15 20:12:53 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:53 volumio volumio[1099]: info: [1757959973943] ControllerSpotify::clearAddPlayTrack Sep 15 20:12:53 volumio volumio[1099]: info: Sending Spotify command with payload to local API: /player/play Sep 15 20:12:53 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:53 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:53 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:53 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:53 volumio go-librespot[1418]: time="2025-09-15T20:12:53+02:00" level=debug msg="pause track at 2754ms" Sep 15 20:12:53 volumio volumio[1099]: info: touch_display: Setting screensaver timeout to 0 seconds. Sep 15 20:12:53 volumio go-librespot[1418]: time="2025-09-15T20:12:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=trace msg="emitting websocket event: paused" Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3w9ydXtambQSZiTrk190rx","play_origin":"go-librespot"}} Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:54 volumio volumio[1099]: 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} Sep 15 20:12:54 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:54 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:54 volumio volumio[1099]: 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} Sep 15 20:12:54 volumio volumio[1099]: verbose: CURRENT POSITION 3 Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::syncState stateService pause Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:54 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:54 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:54 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="resolved context of track" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=trace msg="emitting websocket event: will_play" Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","play_origin":"go-librespot"}} Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="selected format OGG_VORBIS_320 (bf895407776ea85ee2a35b0aeacb1b59d1ad0a12)" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="requested aes key for file bf895407776ea85ee2a35b0aeacb1b59d1ad0a12, gid: 31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="fetched first chunk of 29, total size is 14716637 bytes" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=info msg="loaded track \"I Wanna Know - Eurotracks Remix\" (paused: false, position: 1ms, duration: 448423ms, prefetched: false)" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=trace msg="scheduling prefetch in 418s" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=trace msg="emitting websocket event: metadata" Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","name":"I Wanna Know - Eurotracks Remix","artist_names":["Master Jam"],"album_name":"I Wanna Know","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","position":1,"duration":448423,"release_date":"year:2016 month:4 day:13","track_number":2,"disc_number":1}} Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="fetched chunk 2/28, size: 524288" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=trace msg="emitting websocket event: playing" Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","resume":false,"play_origin":"go-librespot"}} Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"I Wanna Know - Eurotracks Remix","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","trackType":"spotify","seek":1,"duration":448,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:54 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:54 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:54 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"I Wanna Know - Eurotracks Remix","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","trackType":"spotify","seek":1,"duration":448,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:54 volumio volumio[1099]: verbose: CURRENT POSITION 3 Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="fetched chunk 1/28, size: 524288" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio go-librespot[1418]: time="2025-09-15T20:12:54+02:00" level=debug msg="fetched chunk 3/28, size: 524288" uri="spotify:track:31wLjiT7yI1d5k5Fgm45vA" Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"I Wanna Know - Eurotracks Remix","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","trackType":"spotify","seek":1,"duration":448,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:54 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:54 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:54 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"I Wanna Know - Eurotracks Remix","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d00001e029f34e704198c4ba6bf6b83cc","uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","trackType":"spotify","seek":1,"duration":448,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:54 volumio volumio[1099]: verbose: CURRENT POSITION 3 Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:12:54 volumio volumio[1099]: info: Received an update from plugin. extracting info from payload Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:54 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:54 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:54 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:54 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:54 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:54 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:54 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:58 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:58 volumio volumio[1099]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::ClearQueue Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::stPlaybackTimer Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:58 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:58 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::serviceStop Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::getTrack 3 Sep 15 20:12:58 volumio volumio[1099]: info: CoreCommandRouter::serviceStop Sep 15 20:12:58 volumio volumio[1099]: info: Spotify Stop Sep 15 20:12:58 volumio volumio[1099]: SPOTIFY: SPOTIFY STOP Sep 15 20:12:58 volumio volumio[1099]: SPOTIFY: {"status":"play","position":3,"title":"I Wanna Know - Eurotracks Remix","artist":"Master Jam","album":"I Wanna Know","albumart":"https://i.scdn.co/image/ab67616d0000b2739f34e704198c4ba6bf6b83cc","uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","trackType":"spotify","codec":"ogg","seek":1,"duration":448,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":"70","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Sep 15 20:12:58 volumio volumio[1099]: info: Sending Spotify command to local API: /player/pause Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::clearPlayQueue Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:58 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:12:58 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:3w9ydXtambQSZiTrk190rx Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:3w9ydXtambQSZiTrk190rx Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:794pD05ZvML3qJEWfbTaXL Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:794pD05ZvML3qJEWfbTaXL Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6Qvu1UMke7H9Gp1MLtDo6y Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:6Qvu1UMke7H9Gp1MLtDo6y Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:31wLjiT7yI1d5k5Fgm45vA Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:31wLjiT7yI1d5k5Fgm45vA Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6i4ijjoogwP5gNSFFGyiLH Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:6i4ijjoogwP5gNSFFGyiLH Sep 15 20:12:58 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:58 volumio volumio[1099]: info: CoreCommandRouter::volumioPlay Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::play index 4 Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:12:58 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:7c7ZnRUOf5tp3H2k6xllOw Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:7c7ZnRUOf5tp3H2k6xllOw Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:1oUWfVn9Qe6XGPztjWRHL4 Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:1oUWfVn9Qe6XGPztjWRHL4 Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6VQQU8D0Uc7PzZrHJadYhe Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:6VQQU8D0Uc7PzZrHJadYhe Sep 15 20:12:58 volumio volumio[1099]: info: Adding Item to queue: spotify:track:5ttWTSSXMi3EajZhoT2X3o Sep 15 20:12:58 volumio volumio[1099]: info: Using cached record of: spotify:track:5ttWTSSXMi3EajZhoT2X3o Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:58 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::play index undefined Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:12:58 volumio volumio[1099]: info: CoreStateMachine::startPlaybackTimer Sep 15 20:12:58 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:12:58 volumio volumio[1099]: info: [1757959978984] ControllerSpotify::clearAddPlayTrack Sep 15 20:12:58 volumio volumio[1099]: info: Sending Spotify command with payload to local API: /player/play Sep 15 20:12:58 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:58 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:58 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:58 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="pause track at 4643ms" Sep 15 20:12:59 volumio volumio[1099]: info: touch_display: Setting screensaver timeout to 0 seconds. Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=trace msg="emitting websocket event: paused" Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:31wLjiT7yI1d5k5Fgm45vA","play_origin":"go-librespot"}} Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:59 volumio volumio[1099]: 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} Sep 15 20:12:59 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:59 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:12:59 volumio volumio[1099]: 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} Sep 15 20:12:59 volumio volumio[1099]: verbose: CURRENT POSITION 4 Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::syncState stateService pause Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:59 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:12:59 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:59 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="resolved context of track" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=trace msg="emitting websocket event: will_play" Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","play_origin":"go-librespot"}} Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="selected format OGG_VORBIS_320 (fb9a6109b571e9685dfd2a3efd4235d790bfec14)" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="requested aes key for file fb9a6109b571e9685dfd2a3efd4235d790bfec14, gid: 6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="fetched first chunk of 23, total size is 11844394 bytes" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=info msg="loaded track \"Rhythm's In Your Mind - Extended Version\" (paused: false, position: 0ms, duration: 353105ms, prefetched: false)" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=trace msg="scheduling prefetch in 323s" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=trace msg="emitting websocket event: metadata" Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","name":"Rhythm's In Your Mind - Extended Version","artist_names":["Master Jam"],"album_name":"Rhytm's In Your Mind","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b8977a407dd4ea0242e99022","position":0,"duration":353105,"release_date":"year:2016 month:4 day:20","track_number":2,"disc_number":1}} Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=trace msg="emitting websocket event: playing" Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","resume":false,"play_origin":"go-librespot"}} Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"Rhythm's In Your Mind - Extended Version","artist":"Master Jam","album":"Rhytm's In Your Mind","albumart":"https://i.scdn.co/image/ab67616d00001e02b8977a407dd4ea0242e99022","uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","trackType":"spotify","seek":0,"duration":353,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:59 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:59 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:12:59 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Rhythm's In Your Mind - Extended Version","artist":"Master Jam","album":"Rhytm's In Your Mind","albumart":"https://i.scdn.co/image/ab67616d00001e02b8977a407dd4ea0242e99022","uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","trackType":"spotify","seek":0,"duration":353,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:59 volumio volumio[1099]: verbose: CURRENT POSITION 4 Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio go-librespot[1418]: time="2025-09-15T20:12:59+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:12:59 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"Rhythm's In Your Mind - Extended Version","artist":"Master Jam","album":"Rhytm's In Your Mind","albumart":"https://i.scdn.co/image/ab67616d00001e02b8977a407dd4ea0242e99022","uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","trackType":"spotify","seek":0,"duration":353,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:59 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:12:59 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:12:59 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Rhythm's In Your Mind - Extended Version","artist":"Master Jam","album":"Rhytm's In Your Mind","albumart":"https://i.scdn.co/image/ab67616d00001e02b8977a407dd4ea0242e99022","uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","trackType":"spotify","seek":0,"duration":353,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:12:59 volumio volumio[1099]: verbose: CURRENT POSITION 4 Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:12:59 volumio volumio[1099]: info: Received an update from plugin. extracting info from payload Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:59 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:12:59 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:12:59 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:12:59 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:12:59 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:12:59 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:00 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:00 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:00 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:00 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:00 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:00 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:00 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:00 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:09 volumio go-librespot[1418]: time="2025-09-15T20:13:09+02:00" level=trace msg="sent dealer ping" Sep 15 20:13:09 volumio go-librespot[1418]: time="2025-09-15T20:13:09+02:00" level=trace msg="received dealer pong" Sep 15 20:13:10 volumio volumio[1099]: info: CoreCommandRouter::volumioGetState Sep 15 20:13:10 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:13:12 volumio go-librespot[1418]: time="2025-09-15T20:13:12+02:00" level=debug msg="fetched chunk 4/22, size: 524288" uri="spotify:track:6i4ijjoogwP5gNSFFGyiLH" Sep 15 20:13:17 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Sep 15 20:13:17 volumio volumio[1099]: info: In handleBrowseUri, curUri=spotify:artist:2I1LDWHHp99c2xhxsZR4bK Sep 15 20:13:18 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:18 volumio volumio[1099]: info: Preloading song: spotify:track:6trygdRW0bNMdvNGAEheLW Sep 15 20:13:18 volumio volumio[1099]: info: Preloading song: spotify:track:0PheVdGPO8gYqbuo9rEWP3 Sep 15 20:13:18 volumio volumio[1099]: info: Preloading song: spotify:track:0AH66UKuGPZd8z0wai6ftJ Sep 15 20:13:18 volumio volumio[1099]: info: Preloading song: spotify:track:4wLOWELBlsgb5PEidu5gSu Sep 15 20:13:18 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:18 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:18 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:13:18 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:13:18 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:13:18 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:13:18 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:13:18 volumio volumio[1099]: info: No valid Plugin REST Endpoint Sep 15 20:13:20 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:20 volumio volumio[1099]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 15 20:13:20 volumio volumio[1099]: info: CoreStateMachine::ClearQueue Sep 15 20:13:20 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:13:20 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:20 volumio volumio[1099]: info: CoreStateMachine::stPlaybackTimer Sep 15 20:13:20 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:20 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:20 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:20 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:13:20 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:13:20 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:20 volumio volumio[1099]: info: CoreStateMachine::serviceStop Sep 15 20:13:20 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:13:20 volumio volumio[1099]: info: CoreCommandRouter::serviceStop Sep 15 20:13:20 volumio volumio[1099]: info: Spotify Stop Sep 15 20:13:20 volumio volumio[1099]: SPOTIFY: SPOTIFY STOP Sep 15 20:13:20 volumio volumio[1099]: SPOTIFY: {"status":"play","position":4,"title":"Rhythm's In Your Mind - Extended Version","artist":"Master Jam","album":"Rhytm's In Your Mind","albumart":"https://i.scdn.co/image/ab67616d0000b273b8977a407dd4ea0242e99022","uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","trackType":"spotify","codec":"ogg","seek":0,"duration":353,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":"70","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Sep 15 20:13:20 volumio volumio[1099]: info: Sending Spotify command to local API: /player/pause Sep 15 20:13:20 volumio volumio[1099]: info: CorePlayQueue::clearPlayQueue Sep 15 20:13:20 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:20 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:20 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:13:20 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:13:20 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:20 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6trygdRW0bNMdvNGAEheLW Sep 15 20:13:20 volumio volumio[1099]: info: Exploding uri spotify:track:6trygdRW0bNMdvNGAEheLW in service spop Sep 15 20:13:20 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:6trygdRW0bNMdvNGAEheLW Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="pause track at 21410ms" Sep 15 20:13:21 volumio volumio[1099]: info: touch_display: Setting screensaver timeout to 0 seconds. Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=trace msg="emitting websocket event: paused" Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","play_origin":"go-librespot"}} Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: {"status":"pause","service":"spop","title":"Rhythm's In Your Mind - Extended Version","artist":"Master Jam","album":"Rhytm's In Your Mind","albumart":"https://i.scdn.co/image/ab67616d00001e02b8977a407dd4ea0242e99022","uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","trackType":"spotify","seek":21000,"duration":353,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:21 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:13:21 volumio volumio[1099]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Rhythm's In Your Mind - Extended Version","artist":"Master Jam","album":"Rhytm's In Your Mind","albumart":"https://i.scdn.co/image/ab67616d00001e02b8977a407dd4ea0242e99022","uri":"spotify:track:6i4ijjoogwP5gNSFFGyiLH","trackType":"spotify","seek":21000,"duration":353,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:21 volumio volumio[1099]: verbose: CURRENT POSITION 4 Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::syncState stateService pause Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::getTrack 4 Sep 15 20:13:21 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:13:21 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","service":"spop","name":"I Dream Of You Tonight","artist":"Eurotronic","album":"I Dream Of You Tonight","type":"song","duration":231,"albumart":"https://i.scdn.co/image/ab67616d0000b27336df52085c0afb2345f4f527","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:13:21 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:21 volumio volumio[1099]: info: CoreCommandRouter::volumioPlay Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::play index 0 Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:13:21 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:21 volumio volumio[1099]: info: Adding Item to queue: spotify:track:0PheVdGPO8gYqbuo9rEWP3 Sep 15 20:13:21 volumio volumio[1099]: info: Exploding uri spotify:track:0PheVdGPO8gYqbuo9rEWP3 in service spop Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:0PheVdGPO8gYqbuo9rEWP3 Sep 15 20:13:21 volumio volumio[1099]: info: Adding Item to queue: spotify:track:0AH66UKuGPZd8z0wai6ftJ Sep 15 20:13:21 volumio volumio[1099]: info: Exploding uri spotify:track:0AH66UKuGPZd8z0wai6ftJ in service spop Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:0AH66UKuGPZd8z0wai6ftJ Sep 15 20:13:21 volumio volumio[1099]: info: Adding Item to queue: spotify:track:4wLOWELBlsgb5PEidu5gSu Sep 15 20:13:21 volumio volumio[1099]: info: Exploding uri spotify:track:4wLOWELBlsgb5PEidu5gSu in service spop Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: EXPLODING URI:spotify:track:4wLOWELBlsgb5PEidu5gSu Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::play index undefined Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::startPlaybackTimer Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:13:21 volumio volumio[1099]: info: [1757960001155] ControllerSpotify::clearAddPlayTrack Sep 15 20:13:21 volumio volumio[1099]: info: Sending Spotify command with payload to local API: /player/play Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="resolved context of track" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=trace msg="emitting websocket event: will_play" Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","play_origin":"go-librespot"}} Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0PheVdGPO8gYqbuo9rEWP3","service":"spop","name":"Omen III","artist":"Eurotronic","album":"Omen III","type":"song","duration":212,"albumart":"https://i.scdn.co/image/ab67616d0000b273677274d6704c478835a0fac9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="selected format OGG_VORBIS_320 (72af7e1f6148ec0c9bb2e9d580d20858f76ba079)" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="requested aes key for file 72af7e1f6148ec0c9bb2e9d580d20858f76ba079, gid: 6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","service":"spop","name":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio","album":"Stay with Me 2k21","type":"song","duration":251,"albumart":"https://i.scdn.co/image/ab67616d0000b273ad07fb0fb45ec85b74281981","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4wLOWELBlsgb5PEidu5gSu","service":"spop","name":"Stay With Me 2k21 - Eurotronic Extended Remix","artist":"Fio","album":"Stay with Me 2k21","type":"song","duration":453,"albumart":"https://i.scdn.co/image/ab67616d0000b273ad07fb0fb45ec85b74281981","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Sep 15 20:13:21 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="fetched first chunk of 20, total size is 9994380 bytes" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=info msg="loaded track \"I Dream Of You Tonight\" (paused: false, position: 0ms, duration: 231171ms, prefetched: false)" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=trace msg="scheduling prefetch in 201s" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=trace msg="emitting websocket event: metadata" Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","name":"I Dream Of You Tonight","artist_names":["Eurotronic","Timi Kullai","Zooom"],"album_name":"I Dream Of You Tonight","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0236df52085c0afb2345f4f527","position":0,"duration":231171,"release_date":"year:2021 month:5 day:3","track_number":1,"disc_number":1}} Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=trace msg="emitting websocket event: playing" Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","resume":false,"play_origin":"go-librespot"}} Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:21 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"I Dream Of You Tonight","artist":"Eurotronic, Timi Kullai, Zooom","album":"I Dream Of You Tonight","albumart":"https://i.scdn.co/image/ab67616d00001e0236df52085c0afb2345f4f527","uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","trackType":"spotify","seek":0,"duration":231,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:21 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:21 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:13:21 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"I Dream Of You Tonight","artist":"Eurotronic, Timi Kullai, Zooom","album":"I Dream Of You Tonight","albumart":"https://i.scdn.co/image/ab67616d00001e0236df52085c0afb2345f4f527","uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","trackType":"spotify","seek":0,"duration":231,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:21 volumio volumio[1099]: verbose: CURRENT POSITION 0 Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:13:21 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:21 volumio go-librespot[1418]: time="2025-09-15T20:13:21+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:6trygdRW0bNMdvNGAEheLW" Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"I Dream Of You Tonight","artist":"Eurotronic, Timi Kullai, Zooom","album":"I Dream Of You Tonight","albumart":"https://i.scdn.co/image/ab67616d00001e0236df52085c0afb2345f4f527","uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","trackType":"spotify","seek":0,"duration":231,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:22 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:22 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:13:22 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"I Dream Of You Tonight","artist":"Eurotronic, Timi Kullai, Zooom","album":"I Dream Of You Tonight","albumart":"https://i.scdn.co/image/ab67616d00001e0236df52085c0afb2345f4f527","uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","trackType":"spotify","seek":0,"duration":231,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:22 volumio volumio[1099]: verbose: CURRENT POSITION 0 Sep 15 20:13:22 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:13:22 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:13:22 volumio volumio[1099]: info: Received an update from plugin. extracting info from payload Sep 15 20:13:22 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:22 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:13:22 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:13:22 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:22 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:22 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:13:22 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:22 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:23 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:23 volumio volumio[1099]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::ClearQueue Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::stPlaybackTimer Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:13:23 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:13:23 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::serviceStop Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::getTrack 0 Sep 15 20:13:23 volumio volumio[1099]: info: CoreCommandRouter::serviceStop Sep 15 20:13:23 volumio volumio[1099]: info: Spotify Stop Sep 15 20:13:23 volumio volumio[1099]: SPOTIFY: SPOTIFY STOP Sep 15 20:13:23 volumio volumio[1099]: SPOTIFY: {"status":"play","position":0,"title":"I Dream Of You Tonight","artist":"Eurotronic","album":"I Dream Of You Tonight","albumart":"https://i.scdn.co/image/ab67616d0000b27336df52085c0afb2345f4f527","uri":"spotify:track:6trygdRW0bNMdvNGAEheLW","trackType":"spotify","codec":"ogg","seek":0,"duration":231,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":"70","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Sep 15 20:13:23 volumio volumio[1099]: info: Sending Spotify command to local API: /player/pause Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::clearPlayQueue Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:23 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:13:23 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:23 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6trygdRW0bNMdvNGAEheLW Sep 15 20:13:23 volumio volumio[1099]: info: Using cached record of: spotify:track:6trygdRW0bNMdvNGAEheLW Sep 15 20:13:23 volumio volumio[1099]: info: Adding Item to queue: spotify:track:0PheVdGPO8gYqbuo9rEWP3 Sep 15 20:13:23 volumio volumio[1099]: info: Using cached record of: spotify:track:0PheVdGPO8gYqbuo9rEWP3 Sep 15 20:13:23 volumio volumio[1099]: info: Adding Item to queue: spotify:track:0AH66UKuGPZd8z0wai6ftJ Sep 15 20:13:23 volumio volumio[1099]: info: Using cached record of: spotify:track:0AH66UKuGPZd8z0wai6ftJ Sep 15 20:13:23 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:23 volumio volumio[1099]: info: CoreCommandRouter::volumioPlay Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::play index 2 Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:13:23 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:23 volumio volumio[1099]: info: Adding Item to queue: spotify:track:4wLOWELBlsgb5PEidu5gSu Sep 15 20:13:23 volumio volumio[1099]: info: Using cached record of: spotify:track:4wLOWELBlsgb5PEidu5gSu Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:23 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::play index undefined Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:23 volumio volumio[1099]: info: CoreStateMachine::startPlaybackTimer Sep 15 20:13:23 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:23 volumio volumio[1099]: info: [1757960003973] ControllerSpotify::clearAddPlayTrack Sep 15 20:13:23 volumio volumio[1099]: info: Sending Spotify command with payload to local API: /player/play Sep 15 20:13:23 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:23 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:23 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:23 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="resolved context of track" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio volumio[1099]: info: touch_display: Setting screensaver timeout to 0 seconds. Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=trace msg="emitting websocket event: will_play" Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","play_origin":"go-librespot"}} Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="selected format OGG_VORBIS_320 (eed99cafdb1a084c75b334d6606476fa31f0d7aa)" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="requested aes key for file eed99cafdb1a084c75b334d6606476fa31f0d7aa, gid: 0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="fetched first chunk of 21, total size is 10573176 bytes" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=info msg="loaded track \"Stay With Me 2k21 - Eurotronic Remix\" (paused: false, position: 0ms, duration: 251239ms, prefetched: false)" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=trace msg="scheduling prefetch in 221s" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=trace msg="emitting websocket event: metadata" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="pause track at 6ms" Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","name":"Stay With Me 2k21 - Eurotronic Remix","artist_names":["Fio","Ingrid Simons","Eurotronic"],"album_name":"Stay with Me 2k21","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","position":0,"duration":251239,"release_date":"year:2020 month:11 day:13","track_number":3,"disc_number":1}} Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=trace msg="emitting websocket event: playing" Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","resume":false,"play_origin":"go-librespot"}} Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:24 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:24 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:24 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:24 volumio volumio[1099]: verbose: CURRENT POSITION 2 Sep 15 20:13:24 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:13:24 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:24 volumio go-librespot[1418]: time="2025-09-15T20:13:24+02:00" level=trace msg="emitting websocket event: paused" Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","play_origin":"go-librespot"}} Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: {"status":"pause","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:24 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:24 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:24 volumio volumio[1099]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:24 volumio volumio[1099]: verbose: CURRENT POSITION 2 Sep 15 20:13:24 volumio volumio[1099]: info: CoreStateMachine::syncState stateService pause Sep 15 20:13:24 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:13:24 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:24 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:24 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:13:24 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:24 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:25 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:25 volumio volumio[1099]: SPOTIFY: {"status":"pause","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:25 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:25 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:25 volumio volumio[1099]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:25 volumio volumio[1099]: verbose: CURRENT POSITION 2 Sep 15 20:13:25 volumio volumio[1099]: info: CoreStateMachine::syncState stateService pause Sep 15 20:13:25 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:13:25 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:25 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:25 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:13:25 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:25 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:25 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:25 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:25 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:27 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::ClearQueue Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::stPlaybackTimer Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::serviceStop Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::serviceStop Sep 15 20:13:27 volumio volumio[1099]: info: Spotify Stop Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: SPOTIFY STOP Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: {"status":"play","position":2,"title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d0000b273ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","codec":"ogg","seek":250,"duration":251,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":"70","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Sep 15 20:13:27 volumio volumio[1099]: info: Sending Spotify command to local API: /player/pause Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::clearPlayQueue Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:13:27 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:27 volumio volumio[1099]: info: Adding Item to queue: spotify:track:6trygdRW0bNMdvNGAEheLW Sep 15 20:13:27 volumio volumio[1099]: info: Using cached record of: spotify:track:6trygdRW0bNMdvNGAEheLW Sep 15 20:13:27 volumio volumio[1099]: info: Adding Item to queue: spotify:track:0PheVdGPO8gYqbuo9rEWP3 Sep 15 20:13:27 volumio volumio[1099]: info: Using cached record of: spotify:track:0PheVdGPO8gYqbuo9rEWP3 Sep 15 20:13:27 volumio volumio[1099]: info: Adding Item to queue: spotify:track:0AH66UKuGPZd8z0wai6ftJ Sep 15 20:13:27 volumio volumio[1099]: info: Using cached record of: spotify:track:0AH66UKuGPZd8z0wai6ftJ Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::volumioPlay Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::play index 2 Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::addQueueItems Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::addQueueItems Sep 15 20:13:27 volumio volumio[1099]: info: Preload queue cleared Sep 15 20:13:27 volumio volumio[1099]: info: Adding Item to queue: spotify:track:4wLOWELBlsgb5PEidu5gSu Sep 15 20:13:27 volumio volumio[1099]: info: Using cached record of: spotify:track:4wLOWELBlsgb5PEidu5gSu Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::stop Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::volumioPushQueue Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::saveQueue Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::play index undefined Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::updateTrackBlock Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrackBlock Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::startPlaybackTimer Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:27 volumio volumio[1099]: info: [1757960007294] ControllerSpotify::clearAddPlayTrack Sep 15 20:13:27 volumio volumio[1099]: info: Sending Spotify command with payload to local API: /player/play Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="pause track at 0ms" Sep 15 20:13:27 volumio volumio[1099]: info: touch_display: Setting screensaver timeout to 0 seconds. Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=trace msg="emitting websocket event: paused" Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","play_origin":"go-librespot"}} Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:27 volumio volumio[1099]: 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} Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:27 volumio volumio[1099]: 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} Sep 15 20:13:27 volumio volumio[1099]: verbose: CURRENT POSITION 2 Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::syncState stateService pause Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="resolved context of track" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=trace msg="emitting websocket event: will_play" Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","play_origin":"go-librespot"}} Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="selected format OGG_VORBIS_320 (eed99cafdb1a084c75b334d6606476fa31f0d7aa)" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="requested aes key for file eed99cafdb1a084c75b334d6606476fa31f0d7aa, gid: 0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="fetched first chunk of 21, total size is 10573176 bytes" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=info msg="loaded track \"Stay With Me 2k21 - Eurotronic Remix\" (paused: false, position: 0ms, duration: 251239ms, prefetched: false)" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=trace msg="scheduling prefetch in 221s" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=trace msg="emitting websocket event: metadata" Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","name":"Stay With Me 2k21 - Eurotronic Remix","artist_names":["Fio","Ingrid Simons","Eurotronic"],"album_name":"Stay with Me 2k21","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","position":0,"duration":251239,"release_date":"year:2020 month:11 day:13","track_number":3,"disc_number":1}} Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=trace msg="emitting websocket event: playing" Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","resume":false,"play_origin":"go-librespot"}} Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:27 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:27 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:27 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:27 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:27 volumio volumio[1099]: verbose: CURRENT POSITION 2 Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:13:27 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Sep 15 20:13:27 volumio go-librespot[1418]: time="2025-09-15T20:13:27+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: {"status":"play","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:28 volumio volumio[1099]: info: CoreCommandRouter::servicePushState Sep 15 20:13:28 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:28 volumio volumio[1099]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stay With Me 2k21 - Eurotronic Remix","artist":"Fio, Ingrid Simons, Eurotronic","album":"Stay with Me 2k21","albumart":"https://i.scdn.co/image/ab67616d00001e02ad07fb0fb45ec85b74281981","uri":"spotify:track:0AH66UKuGPZd8z0wai6ftJ","trackType":"spotify","seek":0,"duration":251,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 15 20:13:28 volumio volumio[1099]: verbose: CURRENT POSITION 2 Sep 15 20:13:28 volumio volumio[1099]: info: CoreStateMachine::syncState stateService play Sep 15 20:13:28 volumio volumio[1099]: info: CoreStateMachine::syncState currentStatus play Sep 15 20:13:28 volumio volumio[1099]: info: Received an update from plugin. extracting info from payload Sep 15 20:13:28 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:28 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:28 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 20:13:28 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:28 volumio volumio[1099]: info: CoreStateMachine::pushState Sep 15 20:13:28 volumio volumio[1099]: info: CorePlayQueue::getTrack 2 Sep 15 20:13:28 volumio volumio[1099]: info: CoreCommandRouter::volumioPushState Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: SPOTIFY VOLUME 70 Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: VOLUMIO VOLUME 70 Sep 15 20:13:28 volumio volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: false Sep 15 20:13:38 volumio go-librespot[1418]: time="2025-09-15T20:13:38+02:00" level=debug msg="fetched chunk 4/20, size: 524288" uri="spotify:track:0AH66UKuGPZd8z0wai6ftJ" Sep 15 20:13:39 volumio volumio[1099]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Sep 15 20:13:39 volumio volumio[1099]: info: In handleBrowseUri, curUri=spotify:artist:0JtN1EvimelThBxJ1lhofC Sep 15 20:13:39 volumio go-librespot[1418]: time="2025-09-15T20:13:39+02:00" level=trace msg="sent dealer ping" Sep 15 20:13:39 volumio go-librespot[1418]: time="2025-09-15T20:13:39+02:00" level=trace msg="received dealer pong" Sep 15 20:13:40 volumio volumio[1099]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 15 20:13:40 volumio volumio[1099]: TypeError: Cannot read properties of undefined (reading 'url') Sep 15 20:13:40 volumio volumio[1099]: at /data/plugins/music_service/spop/index.js:2449:60 Sep 15 20:13:40 volumio volumio[1099]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Sep 15 20:13:40 volumio volumio[1099]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 15 20:13:42 volumio sudo[9789]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-09-15 20:12' Sep 15 20:13:42 volumio sudo[9789]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="1da895bfdbb6eb90d965df32a25a3568df7c84ed" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu May 29 13:12:59 UTC 2025" VOLUMIO_VERSION="4.004" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2df63d74196e499fa1e34fb765df1cca"