Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: touch_display: Setting screensaver timeout to 0 seconds. Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="resolved context of track" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="emitting websocket event: will_play" Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:72L8UQeMli1iSDTslvU2Qa","uri":"spotify:track:72L8UQeMli1iSDTslvU2Qa","play_origin":"go-librespot"}} Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="selected format OGG_VORBIS_320 (98ec03c8a746da1082f2a724c9bac3b0727be23c)" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="requested aes key for file 98ec03c8a746da1082f2a724c9bac3b0727be23c, gid: 5RoKb2RGNJ2H7h55qogVFB" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="sent dealer ping" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="received dealer pong" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="fetched first chunk of 11, total size is 5715269 bytes" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=info msg="loaded track \"Dove of Peace\" (paused: false, position: 0ms, duration: 153548ms, prefetched: false)" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="scheduling prefetch in 123s" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="emitting websocket event: metadata" Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5RoKb2RGNJ2H7h55qogVFB","name":"Dove of Peace","artist_names":["Lola Lexy"],"album_name":"Dove of Peace","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0206e5763e37a20753b839701c","position":0,"duration":153548,"release_date":"year:2026 month:3 day:20","track_number":1,"disc_number":1}} Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="emitting websocket event: paused" Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:72L8UQeMli1iSDTslvU2Qa","uri":"spotify:track:72L8UQeMli1iSDTslvU2Qa","play_origin":"go-librespot"}} Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"pause","service":"spop","title":"Dove of Peace","artist":"Lola Lexy","album":"Dove of Peace","albumart":"https://i.scdn.co/image/ab67616d00001e0206e5763e37a20753b839701c","uri":"spotify:track:5RoKb2RGNJ2H7h55qogVFB","trackType":"spotify","seek":0,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 2 Jun 01 23:15:00 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Dove of Peace","artist":"Lola Lexy","album":"Dove of Peace","albumart":"https://i.scdn.co/image/ab67616d00001e0206e5763e37a20753b839701c","uri":"spotify:track:5RoKb2RGNJ2H7h55qogVFB","trackType":"spotify","seek":0,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:00 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 2 Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:72L8UQeMli1iSDTslvU2Qa" Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService pause Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus stop Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 2 Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:00+03:00" level=trace msg="emitting websocket event: playing" Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:72L8UQeMli1iSDTslvU2Qa","uri":"spotify:track:72L8UQeMli1iSDTslvU2Qa","resume":false,"play_origin":"go-librespot"}} Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","service":"spop","title":"Dove of Peace","artist":"Lola Lexy","album":"Dove of Peace","albumart":"https://i.scdn.co/image/ab67616d00001e0206e5763e37a20753b839701c","uri":"spotify:track:5RoKb2RGNJ2H7h55qogVFB","trackType":"spotify","seek":0,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 2 Jun 01 23:15:00 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Dove of Peace","artist":"Lola Lexy","album":"Dove of Peace","albumart":"https://i.scdn.co/image/ab67616d00001e0206e5763e37a20753b839701c","uri":"spotify:track:5RoKb2RGNJ2H7h55qogVFB","trackType":"spotify","seek":0,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:00 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 2 Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService play Jun 01 23:15:00 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus stop Jun 01 23:15:00 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:01 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:01 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","service":"spop","title":"Dove of Peace","artist":"Lola Lexy","album":"Dove of Peace","albumart":"https://i.scdn.co/image/ab67616d00001e0206e5763e37a20753b839701c","uri":"spotify:track:5RoKb2RGNJ2H7h55qogVFB","trackType":"spotify","seek":0,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 2 Jun 01 23:15:01 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Dove of Peace","artist":"Lola Lexy","album":"Dove of Peace","albumart":"https://i.scdn.co/image/ab67616d00001e0206e5763e37a20753b839701c","uri":"spotify:track:5RoKb2RGNJ2H7h55qogVFB","trackType":"spotify","seek":0,"duration":153,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:01 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 2 Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService play Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus play Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: Received an update from plugin. extracting info from payload Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 2 Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 2 Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:01 volumio-pi4 volumio[1273]: info: [LastFM] Current track has sufficient metadata: title (Dove of Peace) and artist (Lola Lexy) passed on explicitly Jun 01 23:15:01 volumio-pi4 volumio[1273]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) Jun 01 23:15:01 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:01 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioNext Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::next Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::stop Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::stPlaybackTimer Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::updateTrackBlock Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrackBlock Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 2 Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::serviceStop Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 2 Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreCommandRouter::serviceStop Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: Spotify Stop Jun 01 23:15:03 volumio-pi4 volumio[1273]: SPOTIFY: SPOTIFY STOP Jun 01 23:15:03 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","position":2,"title":"Dove of Peace","artist":"Lola Lexy","album":"Dove of Peace","albumart":"https://i.scdn.co/image/ab67616d0000b27306e5763e37a20753b839701c","uri":"spotify:track:72L8UQeMli1iSDTslvU2Qa","trackType":"spotify","codec":"ogg","seek":0,"duration":153,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: Sending Spotify command to local API: /player/pause Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::play index undefined Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::startPlaybackTimer Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: [1780344903880] ControllerSpotify::clearAddPlayTrack Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: Sending Spotify command with payload to local API: /player/play Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CoreStateMachine::updateTrackBlock Jun 01 23:15:03 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrackBlock Jun 01 23:15:03 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:03 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:03+03:00" level=debug msg="pause track at 3990ms" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: touch_display: Setting screensaver timeout to 0 seconds. Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="resolved context of track" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=trace msg="emitting websocket event: will_play" Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3MyY2fT1M8AjyGJd7cNOSj","uri":"spotify:track:3MyY2fT1M8AjyGJd7cNOSj","play_origin":"go-librespot"}} Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="selected format OGG_VORBIS_320 (d49185ec239b875befe05543c4a5b78ad0127fd7)" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="requested aes key for file d49185ec239b875befe05543c4a5b78ad0127fd7, gid: 7L4JZxKiGcuyziSvLTpOsX" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="fetched first chunk of 10, total size is 5132302 bytes" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=info msg="loaded track \"Bread and Circuses\" (paused: false, position: 0ms, duration: 145263ms, prefetched: false)" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="fetched chunk 1/9, size: 524288" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=trace msg="scheduling prefetch in 115s" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=trace msg="emitting websocket event: metadata" Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7L4JZxKiGcuyziSvLTpOsX","name":"Bread and Circuses","artist_names":["Lola Lexy"],"album_name":"Bread and Circuses","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027a2fc21608cbb188ac7d30db","position":0,"duration":145263,"release_date":"year:2026 month:4 day:1","track_number":1,"disc_number":1}} Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="fetched chunk 2/9, size: 524288" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=trace msg="emitting websocket event: paused" Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:3MyY2fT1M8AjyGJd7cNOSj","uri":"spotify:track:3MyY2fT1M8AjyGJd7cNOSj","play_origin":"go-librespot"}} Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"pause","service":"spop","title":"Bread and Circuses","artist":"Lola Lexy","album":"Bread and Circuses","albumart":"https://i.scdn.co/image/ab67616d00001e027a2fc21608cbb188ac7d30db","uri":"spotify:track:7L4JZxKiGcuyziSvLTpOsX","trackType":"spotify","seek":0,"duration":145,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:04 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Bread and Circuses","artist":"Lola Lexy","album":"Bread and Circuses","albumart":"https://i.scdn.co/image/ab67616d00001e027a2fc21608cbb188ac7d30db","uri":"spotify:track:7L4JZxKiGcuyziSvLTpOsX","trackType":"spotify","seek":0,"duration":145,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:04 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 3 Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService pause Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus stop Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="fetched chunk 3/9, size: 524288" uri="spotify:track:3MyY2fT1M8AjyGJd7cNOSj" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:04 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:04+03:00" level=trace msg="emitting websocket event: playing" Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:3MyY2fT1M8AjyGJd7cNOSj","uri":"spotify:track:3MyY2fT1M8AjyGJd7cNOSj","resume":false,"play_origin":"go-librespot"}} Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:04 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","service":"spop","title":"Bread and Circuses","artist":"Lola Lexy","album":"Bread and Circuses","albumart":"https://i.scdn.co/image/ab67616d00001e027a2fc21608cbb188ac7d30db","uri":"spotify:track:7L4JZxKiGcuyziSvLTpOsX","trackType":"spotify","seek":0,"duration":145,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:04 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Bread and Circuses","artist":"Lola Lexy","album":"Bread and Circuses","albumart":"https://i.scdn.co/image/ab67616d00001e027a2fc21608cbb188ac7d30db","uri":"spotify:track:7L4JZxKiGcuyziSvLTpOsX","trackType":"spotify","seek":0,"duration":145,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:04 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 3 Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService play Jun 01 23:15:04 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus stop Jun 01 23:15:05 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:05 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","service":"spop","title":"Bread and Circuses","artist":"Lola Lexy","album":"Bread and Circuses","albumart":"https://i.scdn.co/image/ab67616d00001e027a2fc21608cbb188ac7d30db","uri":"spotify:track:7L4JZxKiGcuyziSvLTpOsX","trackType":"spotify","seek":0,"duration":145,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:05 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Bread and Circuses","artist":"Lola Lexy","album":"Bread and Circuses","albumart":"https://i.scdn.co/image/ab67616d00001e027a2fc21608cbb188ac7d30db","uri":"spotify:track:7L4JZxKiGcuyziSvLTpOsX","trackType":"spotify","seek":0,"duration":145,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:05 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 3 Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService play Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus play Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: Received an update from plugin. extracting info from payload Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:05 volumio-pi4 volumio[1273]: info: [LastFM] Current track has sufficient metadata: title (Bread and Circuses) and artist (Lola Lexy) passed on explicitly Jun 01 23:15:05 volumio-pi4 volumio[1273]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) Jun 01 23:15:05 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:05 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioNext Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::next Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::stop Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::stPlaybackTimer Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::updateTrackBlock Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrackBlock Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::serviceStop Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 3 Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreCommandRouter::serviceStop Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: Spotify Stop Jun 01 23:15:08 volumio-pi4 volumio[1273]: SPOTIFY: SPOTIFY STOP Jun 01 23:15:08 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","position":3,"title":"Bread and Circuses","artist":"Lola Lexy","album":"Bread and Circuses","albumart":"https://i.scdn.co/image/ab67616d0000b2737a2fc21608cbb188ac7d30db","uri":"spotify:track:3MyY2fT1M8AjyGJd7cNOSj","trackType":"spotify","codec":"ogg","seek":0,"duration":145,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: Sending Spotify command to local API: /player/pause Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::play index undefined Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::startPlaybackTimer Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: [1780344908348] ControllerSpotify::clearAddPlayTrack Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: Sending Spotify command with payload to local API: /player/play Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CoreStateMachine::updateTrackBlock Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrackBlock Jun 01 23:15:08 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=debug msg="pause track at 4581ms" Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:08 volumio-pi4 volumio[1273]: info: touch_display: Setting screensaver timeout to 0 seconds. Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=debug msg="resolved context of track" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=trace msg="emitting websocket event: will_play" Jun 01 23:15:08 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","play_origin":"go-librespot"}} Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=debug msg="selected format OGG_VORBIS_320 (3d701ddf1fa31140b85c58f4e3fe48fd852ebce1)" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=debug msg="requested aes key for file 3d701ddf1fa31140b85c58f4e3fe48fd852ebce1, gid: 3jcF0PpDB79IFgtAtP9mdL" Jun 01 23:15:08 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:08+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=debug msg="fetched first chunk of 14, total size is 7196533 bytes" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=info msg="loaded track \"No Kings\" (paused: false, position: 0ms, duration: 200280ms, prefetched: false)" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=trace msg="scheduling prefetch in 170s" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=trace msg="emitting websocket event: metadata" Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3jcF0PpDB79IFgtAtP9mdL","name":"No Kings","artist_names":["Lola Lexy"],"album_name":"No Kings","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02499c2605d80f163ff308d958","position":0,"duration":200280,"release_date":"year:2026 month:4 day:16","track_number":1,"disc_number":1}} Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=trace msg="emitting websocket event: paused" Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","play_origin":"go-librespot"}} Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"pause","service":"spop","title":"No Kings","artist":"Lola Lexy","album":"No Kings","albumart":"https://i.scdn.co/image/ab67616d00001e02499c2605d80f163ff308d958","uri":"spotify:track:3jcF0PpDB79IFgtAtP9mdL","trackType":"spotify","seek":0,"duration":200,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"No Kings","artist":"Lola Lexy","album":"No Kings","albumart":"https://i.scdn.co/image/ab67616d00001e02499c2605d80f163ff308d958","uri":"spotify:track:3jcF0PpDB79IFgtAtP9mdL","trackType":"spotify","seek":0,"duration":200,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:09 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService pause Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus stop Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:3wkYsf4QrDhqPBDJS4rXoE" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:09 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:09+03:00" level=trace msg="emitting websocket event: playing" Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","resume":false,"play_origin":"go-librespot"}} Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","service":"spop","title":"No Kings","artist":"Lola Lexy","album":"No Kings","albumart":"https://i.scdn.co/image/ab67616d00001e02499c2605d80f163ff308d958","uri":"spotify:track:3jcF0PpDB79IFgtAtP9mdL","trackType":"spotify","seek":0,"duration":200,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"No Kings","artist":"Lola Lexy","album":"No Kings","albumart":"https://i.scdn.co/image/ab67616d00001e02499c2605d80f163ff308d958","uri":"spotify:track:3jcF0PpDB79IFgtAtP9mdL","trackType":"spotify","seek":0,"duration":200,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:09 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService play Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus stop Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","service":"spop","title":"No Kings","artist":"Lola Lexy","album":"No Kings","albumart":"https://i.scdn.co/image/ab67616d00001e02499c2605d80f163ff308d958","uri":"spotify:track:3jcF0PpDB79IFgtAtP9mdL","trackType":"spotify","seek":0,"duration":200,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"No Kings","artist":"Lola Lexy","album":"No Kings","albumart":"https://i.scdn.co/image/ab67616d00001e02499c2605d80f163ff308d958","uri":"spotify:track:3jcF0PpDB79IFgtAtP9mdL","trackType":"spotify","seek":0,"duration":200,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:09 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService play Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus play Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: Received an update from plugin. extracting info from payload Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:09 volumio-pi4 volumio[1273]: info: [LastFM] Current track has sufficient metadata: title (No Kings) and artist (Lola Lexy) passed on explicitly Jun 01 23:15:09 volumio-pi4 volumio[1273]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:09 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioNext Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::next Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::stop Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::stPlaybackTimer Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::updateTrackBlock Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrackBlock Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::serviceStop Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 4 Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreCommandRouter::serviceStop Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: Spotify Stop Jun 01 23:15:12 volumio-pi4 volumio[1273]: SPOTIFY: SPOTIFY STOP Jun 01 23:15:12 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","position":4,"title":"No Kings","artist":"Lola Lexy","album":"No Kings","albumart":"https://i.scdn.co/image/ab67616d0000b273499c2605d80f163ff308d958","uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","trackType":"spotify","codec":"ogg","seek":0,"duration":200,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: Sending Spotify command to local API: /player/pause Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::play index undefined Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::startPlaybackTimer Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: [1780344912399] ControllerSpotify::clearAddPlayTrack Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: Sending Spotify command with payload to local API: /player/play Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::updateTrackBlock Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrackBlock Jun 01 23:15:12 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=debug msg="pause track at 3841ms" Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: touch_display: Setting screensaver timeout to 0 seconds. Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=trace msg="emitting websocket event: paused" Jun 01 23:15:12 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","uri":"spotify:track:3wkYsf4QrDhqPBDJS4rXoE","play_origin":"go-librespot"}} Jun 01 23:15:12 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:12 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:12 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:12 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 5 Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService pause Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus stop Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:12 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=debug msg="resolved context of track" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:12 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=trace msg="emitting websocket event: will_play" Jun 01 23:15:12 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","play_origin":"go-librespot"}} Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=debug msg="selected format OGG_VORBIS_320 (83c2e97e5c46473b0db29fff342ee49aec123584)" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:12 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:12+03:00" level=debug msg="requested aes key for file 83c2e97e5c46473b0db29fff342ee49aec123584, gid: 5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=debug msg="fetched first chunk of 14, total size is 6952428 bytes" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=info msg="loaded track \"Cetera\" (paused: false, position: 1ms, duration: 161740ms, prefetched: false)" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=trace msg="scheduling prefetch in 132s" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=trace msg="emitting websocket event: metadata" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:13 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","name":"Cetera","artist_names":["Feli"],"album_name":"Jurnal","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02daf3d164b65b4b8e8c37bf1f","position":1,"duration":161740,"release_date":"year:2026 month:3 day:6","track_number":6,"disc_number":1}} Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=trace msg="emitting websocket event: playing" Jun 01 23:15:13 volumio-pi4 volumio[1273]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","resume":false,"play_origin":"go-librespot"}} Jun 01 23:15:13 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:13 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","service":"spop","title":"Cetera","artist":"Feli","album":"Jurnal","albumart":"https://i.scdn.co/image/ab67616d00001e02daf3d164b65b4b8e8c37bf1f","uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","trackType":"spotify","seek":1,"duration":161,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:13 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Cetera","artist":"Feli","album":"Jurnal","albumart":"https://i.scdn.co/image/ab67616d00001e02daf3d164b65b4b8e8c37bf1f","uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","trackType":"spotify","seek":1,"duration":161,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:13 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 5 Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService play Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus stop Jun 01 23:15:13 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:13+03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:13 volumio-pi4 volumio[1273]: SPOTIFY: PUSH STATE SPOTIFY Jun 01 23:15:13 volumio-pi4 volumio[1273]: SPOTIFY: {"status":"play","service":"spop","title":"Cetera","artist":"Feli","album":"Jurnal","albumart":"https://i.scdn.co/image/ab67616d00001e02daf3d164b65b4b8e8c37bf1f","uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","trackType":"spotify","seek":1,"duration":161,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreCommandRouter::servicePushState Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:13 volumio-pi4 volumio[1273]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Cetera","artist":"Feli","album":"Jurnal","albumart":"https://i.scdn.co/image/ab67616d00001e02daf3d164b65b4b8e8c37bf1f","uri":"spotify:track:5MVwdhr04bLrZuBz9TCN1N","trackType":"spotify","seek":1,"duration":161,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 01 23:15:13 volumio-pi4 volumio[1273]: verbose: CURRENT POSITION 5 Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState stateService play Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreStateMachine::syncState currentStatus play Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: Received an update from plugin. extracting info from payload Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreStateMachine::pushState Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioPushState Jun 01 23:15:13 volumio-pi4 volumio[1273]: info: [LastFM] Current track has sufficient metadata: title (Cetera) and artist (Feli) passed on explicitly Jun 01 23:15:13 volumio-pi4 volumio[1273]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) Jun 01 23:15:13 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:13 volumio-pi4 volumio[1273]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 01 23:15:19 volumio-pi4 volumio5-onboarding[1661]: time=2026-06-01T23:15:19.780+03:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.136:54204 Jun 01 23:15:20 volumio-pi4 sudo[2373]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 23:15:20 volumio-pi4 sudo[2373]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:15:20 volumio-pi4 sudo[2375]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 23:15:20 volumio-pi4 sudo[2375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:15:20 volumio-pi4 sudo[2373]: pam_unix(sudo:session): session closed for user root Jun 01 23:15:20 volumio-pi4 sudo[2375]: pam_unix(sudo:session): session closed for user root Jun 01 23:15:20 volumio-pi4 volumio[1273]: verbose: New Socket.io Connection to 192.168.1.137 from 192.168.1.136 UA: Mozilla/5.0 (Linux; Android 16; 25010PN30G Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.178 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Jun 01 23:15:21 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 01 23:15:21 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 01 23:15:21 volumio-pi4 sudo[2395]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 23:15:21 volumio-pi4 sudo[2395]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:15:21 volumio-pi4 sudo[2395]: pam_unix(sudo:session): session closed for user root Jun 01 23:15:21 volumio-pi4 sudo[2393]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 23:15:21 volumio-pi4 sudo[2393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:15:21 volumio-pi4 sudo[2393]: pam_unix(sudo:session): session closed for user root Jun 01 23:15:21 volumio-pi4 volumio[1273]: verbose: New Socket.io Connection to 192.168.1.137 from 192.168.1.136 UA: Mozilla/5.0 (Linux; Android 16; 25010PN30G Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.178 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Jun 01 23:15:21 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioGetVisibleSources Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioGetState Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: Received Get System Info Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: Discovery: Getting this device information Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioGetState Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioGetState Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: Listing playlists Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 01 23:15:22 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: Received Get System Info Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: Discovery: Getting this device information Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioGetState Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 23:15:23 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 01 23:15:24 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 01 23:15:24 volumio-pi4 volumio[1273]: info: Received Get System Info Jun 01 23:15:24 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 23:15:24 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 23:15:24 volumio-pi4 volumio[1273]: info: Discovery: Getting this device information Jun 01 23:15:24 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioGetState Jun 01 23:15:24 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:24 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 23:15:25 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 01 23:15:25 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 01 23:15:26 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:26+03:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:30 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:30+03:00" level=trace msg="sent dealer ping" Jun 01 23:15:30 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:30+03:00" level=trace msg="received dealer pong" Jun 01 23:15:31 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 01 23:15:32 volumio-pi4 volumio[1273]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 01 23:15:38 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:38+03:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: Received Get System Version Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: Received Get System Info Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: Discovery: Getting this device information Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CoreCommandRouter::volumioGetState Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CorePlayQueue::getTrack 5 Jun 01 23:15:39 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 23:15:46 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:46+03:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:15:57 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:15:57+03:00" level=debug msg="fetched chunk 7/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:16:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:16:00+03:00" level=trace msg="received accesspoint ping" Jun 01 23:16:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:16:00+03:00" level=trace msg="received accesspoint pong ack" Jun 01 23:16:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:16:00+03:00" level=trace msg="sent dealer ping" Jun 01 23:16:00 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:16:00+03:00" level=trace msg="received dealer pong" Jun 01 23:16:06 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:16:06+03:00" level=debug msg="fetched chunk 8/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:16:11 volumio-pi4 volumio[1273]: info: CALLMETHOD: system_hardware rotaryencoder2 updateEncoder [object Object] Jun 01 23:16:11 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: rotaryencoder2 , updateEncoder Jun 01 23:16:11 volumio-pi4 sudo[2459]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Jun 01 23:16:11 volumio-pi4 sudo[2459]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:11 volumio-pi4 sudo[2459]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:11 volumio-pi4 sudo[2462]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -r 1 Jun 01 23:16:11 volumio-pi4 sudo[2462]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:12 volumio-pi4 sudo[2462]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:12 volumio-pi4 sudo[2473]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Jun 01 23:16:12 volumio-pi4 sudo[2473]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:12 volumio-pi4 sudo[2473]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:12 volumio-pi4 sudo[2476]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -r 0 Jun 01 23:16:12 volumio-pi4 sudo[2476]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:12 volumio-pi4 sudo[2476]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:13 volumio-pi4 sudo[2484]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay rotary-encoder pin_a=17 pin_b=27 relative_axis=true steps-per-period=1 Jun 01 23:16:13 volumio-pi4 sudo[2484]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:13 volumio-pi4 kernel: rotary-encoder rotary@11: gray Jun 01 23:16:13 volumio-pi4 kernel: input: rotary@11 as /devices/platform/rotary@11/input/input8 Jun 01 23:16:13 volumio-pi4 sudo[2484]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:13 volumio-pi4 sudo[2508]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-key gpio=22 active_low=true gpio_pull=up keycode=20 Jun 01 23:16:13 volumio-pi4 sudo[2508]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:13 volumio-pi4 kernel: gpio-keys button@16: error -EBUSY: failed to get gpio Jun 01 23:16:13 volumio-pi4 kernel: gpio-keys button@16: probe with driver gpio-keys failed with error -16 Jun 01 23:16:13 volumio-pi4 sudo[2508]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:15 volumio-pi4 volumio[1273]: info: CALLMETHOD: system_hardware rotaryencoder2 updateEncoder [object Object] Jun 01 23:16:15 volumio-pi4 volumio[1273]: info: CoreCommandRouter::executeOnPlugin: rotaryencoder2 , updateEncoder Jun 01 23:16:15 volumio-pi4 sudo[2515]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Jun 01 23:16:15 volumio-pi4 sudo[2515]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:16 volumio-pi4 sudo[2515]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:16 volumio-pi4 sudo[2518]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -r 1 Jun 01 23:16:16 volumio-pi4 sudo[2518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:16 volumio-pi4 sudo[2518]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:16 volumio-pi4 sudo[2525]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Jun 01 23:16:16 volumio-pi4 sudo[2525]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:16 volumio-pi4 sudo[2525]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:16 volumio-pi4 sudo[2528]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -r 0 Jun 01 23:16:16 volumio-pi4 sudo[2528]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:16 volumio-pi4 sudo[2528]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:16 volumio-pi4 go-librespot[1846]: time="2026-06-01T23:16:16+03:00" level=debug msg="fetched chunk 9/13, size: 524288" uri="spotify:track:5MVwdhr04bLrZuBz9TCN1N" Jun 01 23:16:17 volumio-pi4 sudo[2535]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay rotary-encoder pin_a=17 pin_b=27 relative_axis=true steps-per-period=1 Jun 01 23:16:17 volumio-pi4 sudo[2535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:17 volumio-pi4 kernel: rotary-encoder rotary@11: gray Jun 01 23:16:17 volumio-pi4 kernel: input: rotary@11 as /devices/platform/rotary@11/input/input10 Jun 01 23:16:17 volumio-pi4 sudo[2535]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:17 volumio-pi4 volumio[1273]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 23:16:17 volumio-pi4 volumio[1273]: Error: Unable to resolve or reject the same promise twice Jun 01 23:16:17 volumio-pi4 volumio[1273]: at Promise.resolve (/data/plugins/system_hardware/rotaryencoder2/node_modules/kew/kew.js:140:43) Jun 01 23:16:17 volumio-pi4 volumio[1273]: at /data/plugins/system_hardware/rotaryencoder2/index.js:1017:23 Jun 01 23:16:17 volumio-pi4 volumio[1273]: at FSReqCallback.oncomplete (node:fs:190:23) Jun 01 23:16:17 volumio-pi4 sudo[2545]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-key gpio=22 active_low=true gpio_pull=up keycode=20 Jun 01 23:16:17 volumio-pi4 sudo[2545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 23:16:17 volumio-pi4 volumio[1273]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 23:16:17 volumio-pi4 sudo[2545]: pam_unix(sudo:session): session closed for user root Jun 01 23:16:17 volumio-pi4 kernel: gpio-keys button@16: error -EBUSY: failed to get gpio Jun 01 23:16:17 volumio-pi4 kernel: gpio-keys button@16: probe with driver gpio-keys failed with error -16 Jun 01 23:16:21 volumio-pi4 sudo[2565]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-06-01 23:15' Jun 01 23:16:21 volumio-pi4 sudo[2565]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"