-- Logs begin at Fri 2025-12-05 14:18:25 CET, end at Wed 2026-01-28 20:58:36 CET. -- Jan 28 20:57:06 volumio go-librespot[26041]: time="2026-01-28T20:57:06+01:00" level=debug msg="fetched chunk 5/16, size: 524288" uri="spotify:track:2tDFV7OUKHsFbD2xbPSYsL" Jan 28 20:57:09 volumio go-librespot[26041]: time="2026-01-28T20:57:09+01:00" level=trace msg="sent dealer ping" Jan 28 20:57:09 volumio go-librespot[26041]: time="2026-01-28T20:57:09+01:00" level=trace msg="received dealer pong" Jan 28 20:57:10 volumio wpa_supplicant[1092]: RRM: Ignoring radio measurement request: Not RRM network Jan 28 20:57:18 volumio go-librespot[26041]: time="2026-01-28T20:57:18+01:00" level=debug msg="fetched chunk 6/16, size: 524288" uri="spotify:track:2tDFV7OUKHsFbD2xbPSYsL" Jan 28 20:57:30 volumio wpa_supplicant[1092]: RRM: Ignoring radio measurement request: Not RRM network Jan 28 20:57:32 volumio go-librespot[26041]: time="2026-01-28T20:57:32+01:00" level=debug msg="fetched chunk 7/16, size: 524288" uri="spotify:track:2tDFV7OUKHsFbD2xbPSYsL" Jan 28 20:57:39 volumio go-librespot[26041]: time="2026-01-28T20:57:39+01:00" level=trace msg="received accesspoint ping" Jan 28 20:57:39 volumio go-librespot[26041]: time="2026-01-28T20:57:39+01:00" level=trace msg="received accesspoint pong ack" Jan 28 20:57:39 volumio go-librespot[26041]: time="2026-01-28T20:57:39+01:00" level=trace msg="sent dealer ping" Jan 28 20:57:39 volumio go-librespot[26041]: time="2026-01-28T20:57:39+01:00" level=trace msg="received dealer pong" Jan 28 20:57:42 volumio wpa_supplicant[1092]: RRM: Ignoring radio measurement request: Not RRM network Jan 28 20:57:46 volumio go-librespot[26041]: time="2026-01-28T20:57:46+01:00" level=debug msg="fetched chunk 8/16, size: 524288" uri="spotify:track:2tDFV7OUKHsFbD2xbPSYsL" Jan 28 20:57:51 volumio volumio[25794]: error: error Jan 28 20:57:51 volumio volumio[25794]: error: error Jan 28 20:57:54 volumio wpa_supplicant[1092]: RRM: Ignoring radio measurement request: Not RRM network Jan 28 20:57:55 volumio volumio[25794]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jan 28 20:57:55 volumio volumio[25794]: info: In handleBrowseUri, curUri=spotify:artist:5Mbm3otSC2eWtbfbwOBgw4 Jan 28 20:57:56 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:5xro8nNwHvY070Dk8OGIG2 Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:1NshPlJdoU5SYiDjBEdxfz Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:0jVsMpF6RFUECMzYoiYiW7 Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:6mWg85eewfYatzZdSZVNrk Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:4MnNFRQlt3IJOaGrypZlel Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:0gOjJpOQIs2KdiOggfaf0f Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:6lnBOCc0vgdPg3j8VPUkB9 Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:1SOcYRPkGQBBFpryJmjNJY Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:3dRaEOtE05MTrr0B40198v Jan 28 20:57:56 volumio volumio[25794]: info: Preloading song: spotify:track:4IfaZcrhNI690i1cZHAs1s Jan 28 20:57:56 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:57:56 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:57:56 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::ClearQueue Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::stop Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::stPlaybackTimer Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::updateTrackBlock Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::getTrackBlock Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::pushState Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::volumioPushState Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::serviceStop Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::serviceStop Jan 28 20:57:56 volumio volumio[25794]: info: Spotify Stop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: SPOTIFY STOP Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: {"status":"play","position":0,"title":"Anděl na útěku","artist":"Aramon","album":"Anděl na útěku","albumart":"https://i.scdn.co/image/ab67616d0000b273725a4a46569f80614f163042","uri":"spotify:track:2tDFV7OUKHsFbD2xbPSYsL","trackType":"spotify","codec":"ogg","seek":0,"duration":217,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":55,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jan 28 20:57:56 volumio volumio[25794]: info: Sending Spotify command to local API: /player/pause Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::clearPlayQueue Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::saveQueue Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::volumioPushQueue Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::addQueueItems Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::addQueueItems Jan 28 20:57:56 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:5xro8nNwHvY070Dk8OGIG2 Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:5xro8nNwHvY070Dk8OGIG2 in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:5xro8nNwHvY070Dk8OGIG2 Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:1NshPlJdoU5SYiDjBEdxfz Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:1NshPlJdoU5SYiDjBEdxfz in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:1NshPlJdoU5SYiDjBEdxfz Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:0jVsMpF6RFUECMzYoiYiW7 Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:0jVsMpF6RFUECMzYoiYiW7 in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:0jVsMpF6RFUECMzYoiYiW7 Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:6mWg85eewfYatzZdSZVNrk Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:6mWg85eewfYatzZdSZVNrk in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:6mWg85eewfYatzZdSZVNrk Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:4MnNFRQlt3IJOaGrypZlel Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:4MnNFRQlt3IJOaGrypZlel in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:4MnNFRQlt3IJOaGrypZlel Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:0gOjJpOQIs2KdiOggfaf0f Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:0gOjJpOQIs2KdiOggfaf0f in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:0gOjJpOQIs2KdiOggfaf0f Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:6lnBOCc0vgdPg3j8VPUkB9 Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:6lnBOCc0vgdPg3j8VPUkB9 in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:6lnBOCc0vgdPg3j8VPUkB9 Jan 28 20:57:56 volumio volumio[25794]: info: [ASDebug] CurState: stop PrevState: play Jan 28 20:57:56 volumio volumio[25794]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Jan 28 20:57:56 volumio volumio[25794]: info: ONKYO-CONTROL: New state: {"status":"stop","position":0,"title":"Anděl na útěku","artist":"Aramon","album":"Anděl na útěku","albumart":"https://i.scdn.co/image/ab67616d0000b273725a4a46569f80614f163042","uri":"spotify:track:2tDFV7OUKHsFbD2xbPSYsL","trackType":"spotify","codec":"ogg","seek":0,"duration":217,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":55,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.0.179","model":"TX-NR636"} Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Jan 28 20:57:56 volumio go-librespot[26041]: time="2026-01-28T20:57:56+01:00" level=debug msg="pause track at 77269ms" Jan 28 20:57:56 volumio volumio[25794]: info: touch_display: Setting screensaver timeout to 0 seconds. Jan 28 20:57:56 volumio go-librespot[26041]: time="2026-01-28T20:57:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:57:56 volumio go-librespot[26041]: time="2026-01-28T20:57:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:57:56 volumio go-librespot[26041]: time="2026-01-28T20:57:56+01:00" level=trace msg="emitting websocket event: paused" Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:2tDFV7OUKHsFbD2xbPSYsL","uri":"spotify:track:2tDFV7OUKHsFbD2xbPSYsL","play_origin":"go-librespot"}} Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: PUSH STATE SPOTIFY Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: {"status":"pause","service":"spop","title":"Anděl na útěku","artist":"Aramon","album":"Anděl na útěku","albumart":"https://i.scdn.co/image/ab67616d00001e02725a4a46569f80614f163042","uri":"spotify:track:2tDFV7OUKHsFbD2xbPSYsL","trackType":"spotify","seek":77000,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::servicePushState Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:57:56 volumio volumio[25794]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Anděl na útěku","artist":"Aramon","album":"Anděl na útěku","albumart":"https://i.scdn.co/image/ab67616d00001e02725a4a46569f80614f163042","uri":"spotify:track:2tDFV7OUKHsFbD2xbPSYsL","trackType":"spotify","seek":77000,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:57:56 volumio volumio[25794]: verbose: CURRENT POSITION 0 Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::syncState stateService pause Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::syncState currentStatus stop Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::pushState Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::volumioPushState Jan 28 20:57:56 volumio volumio[25794]: info: [ASDebug] CurState: stop PrevState: play Jan 28 20:57:56 volumio volumio[25794]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Jan 28 20:57:56 volumio volumio[25794]: info: ONKYO-CONTROL: New state: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":55,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":false,"repeat":null,"repeatSingle":false,"consume":false} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.0.179","model":"TX-NR636"} Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5xro8nNwHvY070Dk8OGIG2","service":"spop","name":"Rise Again","artist":"Apocalyptica","album":"Rise Again","type":"song","duration":319,"albumart":"https://i.scdn.co/image/ab67616d0000b273fbda8bef81d228d97fa7b2ea","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6mWg85eewfYatzZdSZVNrk","service":"spop","name":"R.E.D.","artist":"Simone Simons","album":"Vermillion","type":"song","duration":243,"albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0gOjJpOQIs2KdiOggfaf0f","service":"spop","name":"Aeterna","artist":"Simone Simons","album":"Vermillion","type":"song","duration":362,"albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0jVsMpF6RFUECMzYoiYiW7","service":"spop","name":"Cradle To The Grave","artist":"Simone Simons","album":"Vermillion","type":"song","duration":239,"albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","service":"spop","name":"Vermillion Dreams","artist":"Simone Simons","album":"Vermillion","type":"song","duration":276,"albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1NshPlJdoU5SYiDjBEdxfz","service":"spop","name":"Dopamine (feat. Simone Simons)","artist":"Charlotte Wessels","album":"The Obsession","type":"song","duration":216,"albumart":"https://i.scdn.co/image/ab67616d0000b2732ee5cc051d7068250ea0ec89","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4MnNFRQlt3IJOaGrypZlel","service":"spop","name":"In Love We Rust","artist":"Simone Simons","album":"Vermillion","type":"song","duration":286,"albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::volumioPushQueue Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::saveQueue Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::updateTrackBlock Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::getTrackBlock Jan 28 20:57:56 volumio volumio[25794]: info: CoreCommandRouter::volumioPlay Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::play index 6 Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::addQueueItems Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::addQueueItems Jan 28 20:57:56 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:1SOcYRPkGQBBFpryJmjNJY Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:1SOcYRPkGQBBFpryJmjNJY in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:1SOcYRPkGQBBFpryJmjNJY Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:3dRaEOtE05MTrr0B40198v Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:3dRaEOtE05MTrr0B40198v in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:3dRaEOtE05MTrr0B40198v Jan 28 20:57:56 volumio volumio[25794]: info: Adding Item to queue: spotify:track:4IfaZcrhNI690i1cZHAs1s Jan 28 20:57:56 volumio volumio[25794]: info: Exploding uri spotify:track:4IfaZcrhNI690i1cZHAs1s in service spop Jan 28 20:57:56 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:4IfaZcrhNI690i1cZHAs1s Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::stop Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::play index undefined Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:57:56 volumio volumio[25794]: info: CoreStateMachine::startPlaybackTimer Jan 28 20:57:56 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:57:56 volumio volumio[25794]: info: [1769630276934] ControllerSpotify::clearAddPlayTrack Jan 28 20:57:56 volumio volumio[25794]: info: Sending Spotify command with payload to local API: /player/play Jan 28 20:57:56 volumio go-librespot[26041]: time="2026-01-28T20:57:56+01:00" level=debug msg="resolved context of track" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:56 volumio go-librespot[26041]: time="2026-01-28T20:57:56+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:56 volumio go-librespot[26041]: time="2026-01-28T20:57:56+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=trace msg="emitting websocket event: will_play" Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","play_origin":"go-librespot"}} Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4IfaZcrhNI690i1cZHAs1s","service":"spop","name":"Dopamine (feat. Simone Simons) - Dreamscape Version","artist":"Charlotte Wessels","album":"The Obsession (Deluxe Edition)","type":"song","duration":227,"albumart":"https://i.scdn.co/image/ab67616d0000b273ec88fe824b65b368958645e5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="selected format OGG_VORBIS_320 (d6c59f8e4770ce8d706f9c24e8a3562989f9c903)" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="requested aes key for file d6c59f8e4770ce8d706f9c24e8a3562989f9c903, gid: 6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3dRaEOtE05MTrr0B40198v","service":"spop","name":"The Core","artist":"Simone Simons","album":"Vermillion","type":"song","duration":235,"albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1SOcYRPkGQBBFpryJmjNJY","service":"spop","name":"Weight of My World","artist":"Simone Simons","album":"Vermillion","type":"song","duration":260,"albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:57:57 volumio volumio[25794]: info: CoreCommandRouter::volumioPushQueue Jan 28 20:57:57 volumio volumio[25794]: info: CorePlayQueue::saveQueue Jan 28 20:57:57 volumio volumio[25794]: info: CoreStateMachine::updateTrackBlock Jan 28 20:57:57 volumio volumio[25794]: info: CorePlayQueue::getTrackBlock Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="fetched first chunk of 20, total size is 10400772 bytes" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=info msg="loaded track \"Vermillion Dreams\" (paused: false, position: 0ms, duration: 276306ms, prefetched: false)" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=trace msg="scheduling prefetch in 246s" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=trace msg="emitting websocket event: metadata" Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","name":"Vermillion Dreams","artist_names":["Simone Simons","Ayreon"],"album_name":"Vermillion","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fd72e8c4706a70a0cb97df05","position":0,"duration":276306,"release_date":"year:2024 month:8 day:23","track_number":6,"disc_number":1}} Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=trace msg="emitting websocket event: playing" Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","resume":false,"play_origin":"go-librespot"}} Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: PUSH STATE SPOTIFY Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: {"status":"play","service":"spop","title":"Vermillion Dreams","artist":"Simone Simons, Ayreon","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d00001e02fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:57:57 volumio volumio[25794]: info: CoreCommandRouter::servicePushState Jan 28 20:57:57 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:57:57 volumio volumio[25794]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Vermillion Dreams","artist":"Simone Simons, Ayreon","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d00001e02fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:57:57 volumio volumio[25794]: verbose: CURRENT POSITION 6 Jan 28 20:57:57 volumio volumio[25794]: info: CoreStateMachine::syncState stateService play Jan 28 20:57:57 volumio volumio[25794]: info: CoreStateMachine::syncState currentStatus stop Jan 28 20:57:57 volumio volumio[25794]: info: [ASDebug] Togle GPIO: OFF Jan 28 20:57:57 volumio go-librespot[26041]: time="2026-01-28T20:57:57+01:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: PUSH STATE SPOTIFY Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: {"status":"play","service":"spop","title":"Vermillion Dreams","artist":"Simone Simons, Ayreon","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d00001e02fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:57:57 volumio volumio[25794]: info: CoreCommandRouter::servicePushState Jan 28 20:57:57 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:57:57 volumio volumio[25794]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Vermillion Dreams","artist":"Simone Simons, Ayreon","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d00001e02fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:57:57 volumio volumio[25794]: verbose: CURRENT POSITION 6 Jan 28 20:57:57 volumio volumio[25794]: info: CoreStateMachine::syncState stateService play Jan 28 20:57:57 volumio volumio[25794]: info: CoreStateMachine::syncState currentStatus play Jan 28 20:57:57 volumio volumio[25794]: info: Received an update from plugin. extracting info from payload Jan 28 20:57:57 volumio volumio[25794]: info: CoreStateMachine::pushState Jan 28 20:57:57 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:57:57 volumio volumio[25794]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 20:57:57 volumio volumio[25794]: info: CoreCommandRouter::volumioPushState Jan 28 20:57:57 volumio volumio[25794]: info: CoreStateMachine::pushState Jan 28 20:57:57 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:57:57 volumio volumio[25794]: info: CoreCommandRouter::volumioPushState Jan 28 20:57:57 volumio volumio[25794]: info: [ASDebug] CurState: play PrevState: stop Jan 28 20:57:57 volumio volumio[25794]: info: [ASDebug] Togle GPIO: ON Jan 28 20:57:57 volumio volumio[25794]: info: [ASDebug] CurState: play PrevState: play Jan 28 20:57:57 volumio volumio[25794]: info: ONKYO-CONTROL: New state: {"status":"play","position":6,"title":"Vermillion Dreams","artist":"Simone Simons","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","codec":"ogg","seek":0,"duration":276,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":55,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.0.179","model":"TX-NR636"} Jan 28 20:57:57 volumio volumio[25794]: info: ONKYO-CONTROL: New state: {"status":"play","position":6,"title":"Vermillion Dreams","artist":"Simone Simons","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","codec":"ogg","seek":0,"duration":276,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":55,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.0.179","model":"TX-NR636"} Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Jan 28 20:57:57 volumio volumio[25794]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Jan 28 20:58:01 volumio wpa_supplicant[1092]: RRM: Ignoring radio measurement request: Not RRM network Jan 28 20:58:09 volumio go-librespot[26041]: time="2026-01-28T20:58:09+01:00" level=trace msg="sent dealer ping" Jan 28 20:58:09 volumio go-librespot[26041]: time="2026-01-28T20:58:09+01:00" level=trace msg="received dealer pong" Jan 28 20:58:10 volumio go-librespot[26041]: time="2026-01-28T20:58:10+01:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:6lnBOCc0vgdPg3j8VPUkB9" Jan 28 20:58:13 volumio volumio[25794]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jan 28 20:58:13 volumio volumio[25794]: info: In handleBrowseUri, curUri=spotify:album:6GIIE5AwJY3FJVwKinolTl Jan 28 20:58:14 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:58:14 volumio volumio[25794]: info: Preloading song: spotify:track:1i02PIDgVFoDNcTVZv4Ccd Jan 28 20:58:14 volumio volumio[25794]: info: Preloading song: spotify:track:3n8SZtJtwxUb2QGIsVNalG Jan 28 20:58:14 volumio volumio[25794]: info: Preloading song: spotify:track:2JVbHTHZ9aLcWwnOkt6JZ0 Jan 28 20:58:14 volumio volumio[25794]: info: Exploding uri spotify:track:1i02PIDgVFoDNcTVZv4Ccd in service spop Jan 28 20:58:14 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:1i02PIDgVFoDNcTVZv4Ccd Jan 28 20:58:14 volumio volumio[25794]: info: Exploding uri spotify:track:3n8SZtJtwxUb2QGIsVNalG in service spop Jan 28 20:58:14 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:3n8SZtJtwxUb2QGIsVNalG Jan 28 20:58:14 volumio volumio[25794]: info: Exploding uri spotify:track:2JVbHTHZ9aLcWwnOkt6JZ0 in service spop Jan 28 20:58:14 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:track:2JVbHTHZ9aLcWwnOkt6JZ0 Jan 28 20:58:14 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","service":"spop","name":"R.E.D.","artist":"Simone Simons","album":"R.E.D.","type":"song","duration":243,"albumart":"https://i.scdn.co/image/ab67616d0000b27305db4354c0e0f93b6d7b3b28","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:58:14 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3n8SZtJtwxUb2QGIsVNalG","service":"spop","name":"In Love We Rust","artist":"Simone Simons","album":"R.E.D.","type":"song","duration":286,"albumart":"https://i.scdn.co/image/ab67616d0000b27305db4354c0e0f93b6d7b3b28","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:58:14 volumio volumio[25794]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2JVbHTHZ9aLcWwnOkt6JZ0","service":"spop","name":"Aeterna","artist":"Simone Simons","album":"R.E.D.","type":"song","duration":362,"albumart":"https://i.scdn.co/image/ab67616d0000b27305db4354c0e0f93b6d7b3b28","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 28 20:58:14 volumio wpa_supplicant[1092]: RRM: Ignoring radio measurement request: Not RRM network Jan 28 20:58:17 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::ClearQueue Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::stop Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::stPlaybackTimer Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::updateTrackBlock Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::getTrackBlock Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::pushState Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::volumioPushState Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::serviceStop Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::serviceStop Jan 28 20:58:17 volumio volumio[25794]: info: Spotify Stop Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: SPOTIFY STOP Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: {"status":"play","position":6,"title":"Vermillion Dreams","artist":"Simone Simons","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","codec":"ogg","seek":0,"duration":276,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":55,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jan 28 20:58:17 volumio volumio[25794]: info: Sending Spotify command to local API: /player/pause Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::clearPlayQueue Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::saveQueue Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::volumioPushQueue Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::addQueueItems Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::addQueueItems Jan 28 20:58:17 volumio volumio[25794]: info: Preload queue cleared Jan 28 20:58:17 volumio volumio[25794]: info: Adding Item to queue: spotify:album:6GIIE5AwJY3FJVwKinolTl Jan 28 20:58:17 volumio volumio[25794]: info: Exploding uri spotify:album:6GIIE5AwJY3FJVwKinolTl in service spop Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: EXPLODING URI:spotify:album:6GIIE5AwJY3FJVwKinolTl Jan 28 20:58:17 volumio volumio[25794]: info: [ASDebug] CurState: stop PrevState: play Jan 28 20:58:17 volumio volumio[25794]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Jan 28 20:58:17 volumio volumio[25794]: info: ONKYO-CONTROL: New state: {"status":"stop","position":6,"title":"Vermillion Dreams","artist":"Simone Simons","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d0000b273fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","codec":"ogg","seek":0,"duration":276,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":55,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.0.179","model":"TX-NR636"} Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=debug msg="pause track at 20368ms" Jan 28 20:58:17 volumio volumio[25794]: info: touch_display: Setting screensaver timeout to 0 seconds. Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=trace msg="emitting websocket event: paused" Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","play_origin":"go-librespot"}} Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: PUSH STATE SPOTIFY Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: {"status":"pause","service":"spop","title":"Vermillion Dreams","artist":"Simone Simons, Ayreon","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d00001e02fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","seek":20000,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::servicePushState Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:58:17 volumio volumio[25794]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Vermillion Dreams","artist":"Simone Simons, Ayreon","album":"Vermillion","albumart":"https://i.scdn.co/image/ab67616d00001e02fd72e8c4706a70a0cb97df05","uri":"spotify:track:6lnBOCc0vgdPg3j8VPUkB9","trackType":"spotify","seek":20000,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:58:17 volumio volumio[25794]: verbose: CURRENT POSITION 6 Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::syncState stateService pause Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::syncState currentStatus stop Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::pushState Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::getTrack 6 Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::volumioPushState Jan 28 20:58:17 volumio volumio[25794]: info: [ASDebug] CurState: stop PrevState: play Jan 28 20:58:17 volumio volumio[25794]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Jan 28 20:58:17 volumio volumio[25794]: info: ONKYO-CONTROL: New state: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":55,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":false,"repeat":null,"repeatSingle":false,"consume":false} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.0.179","model":"TX-NR636"} Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::volumioPushQueue Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::saveQueue Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::updateTrackBlock Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::getTrackBlock Jan 28 20:58:17 volumio volumio[25794]: info: CoreCommandRouter::volumioPlay Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::play index 0 Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::stop Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::play index undefined Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:58:17 volumio volumio[25794]: info: CoreStateMachine::startPlaybackTimer Jan 28 20:58:17 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:58:17 volumio volumio[25794]: info: [1769630297853] ControllerSpotify::clearAddPlayTrack Jan 28 20:58:17 volumio volumio[25794]: info: Sending Spotify command with payload to local API: /player/play Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=debug msg="resolved context of track" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:58:17 volumio go-librespot[26041]: time="2026-01-28T20:58:17+01:00" level=trace msg="emitting websocket event: will_play" Jan 28 20:58:17 volumio volumio[25794]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","play_origin":"go-librespot"}} Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="selected format OGG_VORBIS_320 (b47f78aafb9141fc5cfebf59a86a3ca241a1f2b1)" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="requested aes key for file b47f78aafb9141fc5cfebf59a86a3ca241a1f2b1, gid: 1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="fetched first chunk of 20, total size is 9999511 bytes" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=info msg="loaded track \"R.E.D.\" (paused: false, position: 0ms, duration: 243960ms, prefetched: false)" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=trace msg="scheduling prefetch in 214s" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=trace msg="emitting websocket event: metadata" Jan 28 20:58:18 volumio volumio[25794]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","name":"R.E.D.","artist_names":["Simone Simons","Ayreon"],"album_name":"R.E.D.","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0205db4354c0e0f93b6d7b3b28","position":0,"duration":243960,"release_date":"year:2024 month:7 day:18","track_number":1,"disc_number":1}} Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 28 20:58:18 volumio go-librespot[26041]: time="2026-01-28T20:58:18+01:00" level=trace msg="emitting websocket event: playing" Jan 28 20:58:18 volumio volumio[25794]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","resume":false,"play_origin":"go-librespot"}} Jan 28 20:58:18 volumio volumio[25794]: SPOTIFY: PUSH STATE SPOTIFY Jan 28 20:58:18 volumio volumio[25794]: SPOTIFY: {"status":"play","service":"spop","title":"R.E.D.","artist":"Simone Simons, Ayreon","album":"R.E.D.","albumart":"https://i.scdn.co/image/ab67616d00001e0205db4354c0e0f93b6d7b3b28","uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","trackType":"spotify","seek":0,"duration":243,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:58:18 volumio volumio[25794]: info: CoreCommandRouter::servicePushState Jan 28 20:58:18 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:58:18 volumio volumio[25794]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"R.E.D.","artist":"Simone Simons, Ayreon","album":"R.E.D.","albumart":"https://i.scdn.co/image/ab67616d00001e0205db4354c0e0f93b6d7b3b28","uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","trackType":"spotify","seek":0,"duration":243,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:58:18 volumio volumio[25794]: verbose: CURRENT POSITION 0 Jan 28 20:58:18 volumio volumio[25794]: info: CoreStateMachine::syncState stateService play Jan 28 20:58:18 volumio volumio[25794]: info: CoreStateMachine::syncState currentStatus stop Jan 28 20:58:18 volumio volumio[25794]: info: [ASDebug] Togle GPIO: OFF Jan 28 20:58:18 volumio volumio[25794]: SPOTIFY: PUSH STATE SPOTIFY Jan 28 20:58:18 volumio volumio[25794]: SPOTIFY: {"status":"play","service":"spop","title":"R.E.D.","artist":"Simone Simons, Ayreon","album":"R.E.D.","albumart":"https://i.scdn.co/image/ab67616d00001e0205db4354c0e0f93b6d7b3b28","uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","trackType":"spotify","seek":0,"duration":243,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:58:18 volumio volumio[25794]: info: CoreCommandRouter::servicePushState Jan 28 20:58:18 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:58:18 volumio volumio[25794]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"R.E.D.","artist":"Simone Simons, Ayreon","album":"R.E.D.","albumart":"https://i.scdn.co/image/ab67616d00001e0205db4354c0e0f93b6d7b3b28","uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","trackType":"spotify","seek":0,"duration":243,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 28 20:58:18 volumio volumio[25794]: verbose: CURRENT POSITION 0 Jan 28 20:58:18 volumio volumio[25794]: info: CoreStateMachine::syncState stateService play Jan 28 20:58:18 volumio volumio[25794]: info: CoreStateMachine::syncState currentStatus play Jan 28 20:58:18 volumio volumio[25794]: info: Received an update from plugin. extracting info from payload Jan 28 20:58:18 volumio volumio[25794]: info: CoreStateMachine::pushState Jan 28 20:58:18 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:58:18 volumio volumio[25794]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 20:58:18 volumio volumio[25794]: info: CoreCommandRouter::volumioPushState Jan 28 20:58:18 volumio volumio[25794]: info: CoreStateMachine::pushState Jan 28 20:58:18 volumio volumio[25794]: info: CorePlayQueue::getTrack 0 Jan 28 20:58:18 volumio volumio[25794]: info: CoreCommandRouter::volumioPushState Jan 28 20:58:18 volumio volumio[25794]: info: [ASDebug] CurState: play PrevState: stop Jan 28 20:58:18 volumio volumio[25794]: info: [ASDebug] Togle GPIO: ON Jan 28 20:58:18 volumio volumio[25794]: info: [ASDebug] CurState: play PrevState: play Jan 28 20:58:18 volumio volumio[25794]: info: ONKYO-CONTROL: New state: {"status":"play","position":0,"title":"R.E.D.","artist":"Simone Simons","album":"R.E.D.","albumart":"https://i.scdn.co/image/ab67616d0000b27305db4354c0e0f93b6d7b3b28","uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","trackType":"spotify","codec":"ogg","seek":0,"duration":243,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":55,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.0.179","model":"TX-NR636"} Jan 28 20:58:18 volumio volumio[25794]: info: ONKYO-CONTROL: New state: {"status":"play","position":0,"title":"R.E.D.","artist":"Simone Simons","album":"R.E.D.","albumart":"https://i.scdn.co/image/ab67616d0000b27305db4354c0e0f93b6d7b3b28","uri":"spotify:track:1i02PIDgVFoDNcTVZv4Ccd","trackType":"spotify","codec":"ogg","seek":0,"duration":243,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":null,"repeatSingle":false,"consume":false,"volume":55,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.0.179","model":"TX-NR636"} Jan 28 20:58:18 volumio volumio[25794]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Jan 28 20:58:18 volumio volumio[25794]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Jan 28 20:58:28 volumio go-librespot[26041]: time="2026-01-28T20:58:28+01:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:1i02PIDgVFoDNcTVZv4Ccd" Jan 28 20:58:36 volumio volumio[25794]: info: ___________ PLUGINS: Run Shutdown Tasks ___________ Jan 28 20:58:36 volumio volumio[25794]: info: PLUGIN onShutdown : networkfs Jan 28 20:58:36 volumio sudo[27123]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount -f /mnt/NAS/music Jan 28 20:58:36 volumio sudo[27123]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 28 20:58:36 volumio sudo[27123]: pam_unix(sudo:session): session closed for user root Jan 28 20:58:36 volumio volumio[25794]: umount: /mnt/NAS/music: not mounted. Jan 28 20:58:36 volumio volumio[25794]: error: Cannot umount share music : Error: Command failed: /usr/bin/sudo /bin/umount -f /mnt/NAS/music Jan 28 20:58:36 volumio volumio[25794]: umount: /mnt/NAS/music: not mounted. Jan 28 20:58:36 volumio sudo[27126]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount -f /mnt/NAS/Video_-_Hudební_videoclip Jan 28 20:58:36 volumio sudo[27126]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 28 20:58:36 volumio systemd[1]: mnt-NAS-Video_\x2d_Hudebn\xc3\xad_videoclip.mount: Succeeded. Jan 28 20:58:36 volumio sudo[27126]: pam_unix(sudo:session): session closed for user root Jan 28 20:58:36 volumio sudo[27130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount -f /mnt/NAS/Video_-_Koncerty Jan 28 20:58:36 volumio sudo[27130]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 28 20:58:36 volumio systemd[1]: mnt-NAS-Video_\x2d_Koncerty.mount: Succeeded. Jan 28 20:58:36 volumio sudo[27130]: pam_unix(sudo:session): session closed for user root Jan 28 20:58:36 volumio volumio[25794]: info: PLUGIN onShutdown : audiophonicsonoff Jan 28 20:58:36 volumio volumio[25794]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 20:58:36 volumio volumio[25794]: TypeError: Cannot read property 'writeSync' of undefined Jan 28 20:58:36 volumio volumio[25794]: at ControllerAudiophonicsOnOff.onVolumioShutdown (/data/plugins/system_hardware/audiophonicsonoff/index.js:48:25) Jan 28 20:58:36 volumio volumio[25794]: at PluginManager.onVolumioShutdownPlugin (/volumio/app/pluginmanager.js:638:30) Jan 28 20:58:36 volumio volumio[25794]: at HashMap. (/volumio/app/pluginmanager.js:621:31) Jan 28 20:58:36 volumio volumio[25794]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Jan 28 20:58:36 volumio volumio[25794]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Jan 28 20:58:36 volumio volumio[25794]: at PluginManager.onVolumioShutdown (/volumio/app/pluginmanager.js:619:20) Jan 28 20:58:36 volumio volumio[25794]: at CoreCommandRouter.shutdown (/volumio/app/index.js:1328:22) Jan 28 20:58:36 volumio volumio[25794]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:859:33) Jan 28 20:58:36 volumio volumio[25794]: at Socket.emit (events.js:315:20) Jan 28 20:58:36 volumio volumio[25794]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Jan 28 20:58:36 volumio volumio[25794]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Jan 28 20:58:36 volumio volumio[25794]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 20:58:36 volumio sudo[27141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-01-28 20:57 Jan 28 20:58:36 volumio sudo[27141]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"