Mar 25 00:03:00 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 25 00:03:00 musicvolumio volumio[4061]: info: In handleBrowseUri, curUri=spotify Mar 25 00:03:00 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:00 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:00 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:00 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 25 00:03:01 musicvolumio volumio[4061]: info: In handleBrowseUri, curUri=spotify/playlists Mar 25 00:03:02 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:03 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 25 00:03:03 musicvolumio volumio[4061]: info: In handleBrowseUri, curUri=spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:03 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:03 musicvolumio volumio[4061]: info: Preloading song: spotify:track:7J1uxwnxfQLu4APicE5Rnj Mar 25 00:03:03 musicvolumio volumio[4061]: info: Exploding uri spotify:track:7J1uxwnxfQLu4APicE5Rnj in service spop Mar 25 00:03:03 musicvolumio volumio[4061]: SPOTIFY: EXPLODING URI:spotify:track:7J1uxwnxfQLu4APicE5Rnj Mar 25 00:03:04 musicvolumio volumio[4061]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","service":"spop","name":"Billie Jean","artist":"Michael Jackson","album":"Thriller","type":"song","duration":293,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Mar 25 00:03:05 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::ClearQueue Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::stPlaybackTimer Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::updateTrackBlock Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrackBlock Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 1 Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::serviceStop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 1 Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::serviceStop Mar 25 00:03:05 musicvolumio volumio[4061]: info: [1774393385392] ControllerTidal::stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::stop Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::clearPlayQueue Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::saveQueue Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushQueue Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::addQueueItems Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::addQueueItems Mar 25 00:03:05 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:05 musicvolumio volumio[4061]: info: Adding Item to queue: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:05 musicvolumio volumio[4061]: info: Exploding uri spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 in service spop Mar 25 00:03:05 musicvolumio volumio[4061]: SPOTIFY: EXPLODING URI:spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.396Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_STOPPED positionMs=0 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.396Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio[4061]: info: Mar 25 00:03:05 musicvolumio volumio[4061]: ---------------------------- MPD announces state update: player Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand stop took 45 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::getState Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand status Mar 25 00:03:05 musicvolumio volumio[4061]: info: Mar 25 00:03:05 musicvolumio volumio[4061]: ---------------------------- MPD announces state update: player Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::getState Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand status Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand status took 2 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand status took 1 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::parseState Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::parseState Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 25 00:03:05 musicvolumio volumio[4061]: info: Mar 25 00:03:05 musicvolumio volumio[4061]: ---------------------------- MPD announces state update: player Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::getState Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand status Mar 25 00:03:05 musicvolumio volumio[4061]: info: Mar 25 00:03:05 musicvolumio volumio[4061]: ---------------------------- MPD announces state update: player Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::getState Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand status Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand playlistinfo took 3 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand playlistinfo took 3 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand status took 2 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand status took 1 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::parseTrackInfo Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::parseTrackInfo Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::parseState Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::parseState Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::servicePushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 1 Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1774396882~MGEwNDkyYzVmZDlkN2QxZTY1OWMxNGY0YjU4NTFlZWM3NWNkNTgyZA==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEic4Y2E0NTY5ZTVmYzhmYjU5NWU3YzdiNzNiMDlhZGQ0OF82MS5tcDQ/0.flac?token=1774396882~MGEwNDkyYzVmZDlkN2QxZTY1OWMxNGY0YjU4NTFlZWM3NWNkNTgyZA==","trackType":"tidal"} Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: CURRENT POSITION 1 Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::syncState stateService stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::syncState currentStatus stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: No code Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::servicePushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 1 Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1774396882~MGEwNDkyYzVmZDlkN2QxZTY1OWMxNGY0YjU4NTFlZWM3NWNkNTgyZA==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEic4Y2E0NTY5ZTVmYzhmYjU5NWU3YzdiNzNiMDlhZGQ0OF82MS5tcDQ/0.flac?token=1774396882~MGEwNDkyYzVmZDlkN2QxZTY1OWMxNGY0YjU4NTFlZWM3NWNkNTgyZA==","trackType":"tidal"} Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: CURRENT POSITION 1 Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::syncState stateService stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::syncState currentStatus stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: No code Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.464Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=0 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.464Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.465Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=0 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.466Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.467Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=0 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.467Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.468Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=0 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.469Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.469Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=0 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.470Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.471Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=0 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.471Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio[4061]: info: ------------------------------ 50ms Mar 25 00:03:05 musicvolumio volumio[4061]: info: ------------------------------ 49ms Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand playlistinfo took 45 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: info: sendMpdCommand playlistinfo took 44 milliseconds Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::parseTrackInfo Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: ControllerMpd::parseTrackInfo Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::servicePushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 1 Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1774396882~MGEwNDkyYzVmZDlkN2QxZTY1OWMxNGY0YjU4NTFlZWM3NWNkNTgyZA==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEic4Y2E0NTY5ZTVmYzhmYjU5NWU3YzdiNzNiMDlhZGQ0OF82MS5tcDQ/0.flac?token=1774396882~MGEwNDkyYzVmZDlkN2QxZTY1OWMxNGY0YjU4NTFlZWM3NWNkNTgyZA==","trackType":"tidal"} Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: CURRENT POSITION 1 Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::syncState stateService stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::syncState currentStatus stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: No code Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: ControllerMpd::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::servicePushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 1 Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1774396882~MGEwNDkyYzVmZDlkN2QxZTY1OWMxNGY0YjU4NTFlZWM3NWNkNTgyZA==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEic4Y2E0NTY5ZTVmYzhmYjU5NWU3YzdiNzNiMDlhZGQ0OF82MS5tcDQ/0.flac?token=1774396882~MGEwNDkyYzVmZDlkN2QxZTY1OWMxNGY0YjU4NTFlZWM3NWNkNTgyZA==","trackType":"tidal"} Mar 25 00:03:05 musicvolumio volumio[4061]: verbose: CURRENT POSITION 1 Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::syncState stateService stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::syncState currentStatus stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: No code Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.507Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=2065 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.508Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.508Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=2065 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.509Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.510Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=2065 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.510Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.511Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=2065 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.512Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.516Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=2065 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.516Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.518Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_PLAYING positionMs=2065 volume=100 Mar 25 00:03:05 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:05.518Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=tidal://song/9890173 title="Stimela (The Coal Train)" Mar 25 00:03:05 musicvolumio volumio[4061]: info: ------------------------------ 118ms Mar 25 00:03:05 musicvolumio volumio[4061]: info: ------------------------------ 119ms Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushQueue Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::saveQueue Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::updateTrackBlock Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrackBlock Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioGetState Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPlay Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::play index 0 Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::stop Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::play index undefined Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:05 musicvolumio volumio[4061]: info: CoreStateMachine::startPlaybackTimer Mar 25 00:03:05 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:05 musicvolumio volumio[4061]: info: [1774393385743] ControllerSpotify::clearAddPlayTrack Mar 25 00:03:05 musicvolumio volumio[4061]: info: Sending Spotify command with payload to local API: /player/play Mar 25 00:03:05 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:05+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:05 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:05+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:05 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:05+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:05 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:05+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 00:03:05 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:05+01:00" level=trace msg="emitting websocket event: will_play" Mar 25 00:03:05 musicvolumio volumio[4061]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 25 00:03:06 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:06+01:00" level=debug msg="selected format OGG_VORBIS_320 (524dadb925288ef98d9e9b35a6b1598133df21e3)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:06 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:06+01:00" level=debug msg="requested aes key for file 524dadb925288ef98d9e9b35a6b1598133df21e3, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:06 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:06+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 25 00:03:06 musicvolumio volumio[4061]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 25 00:03:07 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 25 00:03:08 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::ClearQueue Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::stop Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:08 musicvolumio volumio[4061]: info: CorePlayQueue::clearPlayQueue Mar 25 00:03:08 musicvolumio volumio[4061]: info: CorePlayQueue::saveQueue Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushQueue Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::addQueueItems Mar 25 00:03:08 musicvolumio volumio[4061]: info: CorePlayQueue::addQueueItems Mar 25 00:03:08 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:08 musicvolumio volumio[4061]: info: Adding Item to queue: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:08 musicvolumio volumio[4061]: info: Using cached record of: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushQueue Mar 25 00:03:08 musicvolumio volumio[4061]: info: CorePlayQueue::saveQueue Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::updateTrackBlock Mar 25 00:03:08 musicvolumio volumio[4061]: info: CorePlayQueue::getTrackBlock Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioGetState Mar 25 00:03:08 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPlay Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::play index 0 Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::stop Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::play index undefined Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:08 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:08 musicvolumio volumio[4061]: info: CoreStateMachine::startPlaybackTimer Mar 25 00:03:08 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:08 musicvolumio volumio[4061]: info: [1774393388681] ControllerSpotify::clearAddPlayTrack Mar 25 00:03:08 musicvolumio volumio[4061]: info: Sending Spotify command with payload to local API: /player/play Mar 25 00:03:08 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:08+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:08 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:08+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:08 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:08+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:08 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:08+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 00:03:08 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:08+01:00" level=trace msg="emitting websocket event: will_play" Mar 25 00:03:08 musicvolumio volumio[4061]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 25 00:03:08 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:08+01:00" level=debug msg="selected format OGG_VORBIS_320 (524dadb925288ef98d9e9b35a6b1598133df21e3)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:08 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:08+01:00" level=debug msg="requested aes key for file 524dadb925288ef98d9e9b35a6b1598133df21e3, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:08 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:08+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 25 00:03:08 musicvolumio volumio[4061]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 25 00:03:09 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::ClearQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::stop Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::clearPlayQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::saveQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::addQueueItems Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::addQueueItems Mar 25 00:03:09 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:09 musicvolumio volumio[4061]: info: Adding Item to queue: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:09 musicvolumio volumio[4061]: info: Using cached record of: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::saveQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::updateTrackBlock Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::getTrackBlock Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioGetState Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPlay Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::play index 0 Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::stop Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::play index undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::startPlaybackTimer Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:09 musicvolumio volumio[4061]: info: [1774393389235] ControllerSpotify::clearAddPlayTrack Mar 25 00:03:09 musicvolumio volumio[4061]: info: Sending Spotify command with payload to local API: /player/play Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=trace msg="emitting websocket event: will_play" Mar 25 00:03:09 musicvolumio volumio[4061]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="selected format OGG_VORBIS_320 (524dadb925288ef98d9e9b35a6b1598133df21e3)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="requested aes key for file 524dadb925288ef98d9e9b35a6b1598133df21e3, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 25 00:03:09 musicvolumio volumio[4061]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 25 00:03:09 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::ClearQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::stop Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::clearPlayQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::saveQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::addQueueItems Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::addQueueItems Mar 25 00:03:09 musicvolumio volumio[4061]: info: Preload queue cleared Mar 25 00:03:09 musicvolumio volumio[4061]: info: Adding Item to queue: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:09 musicvolumio volumio[4061]: info: Using cached record of: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::saveQueue Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::updateTrackBlock Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::getTrackBlock Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioGetState Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPlay Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::play index 0 Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::stop Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::play index undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:09 musicvolumio volumio[4061]: info: CoreStateMachine::startPlaybackTimer Mar 25 00:03:09 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:09 musicvolumio volumio[4061]: info: [1774393389555] ControllerSpotify::clearAddPlayTrack Mar 25 00:03:09 musicvolumio volumio[4061]: info: Sending Spotify command with payload to local API: /player/play Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=trace msg="emitting websocket event: will_play" Mar 25 00:03:09 musicvolumio volumio[4061]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="selected format OGG_VORBIS_320 (524dadb925288ef98d9e9b35a6b1598133df21e3)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=debug msg="requested aes key for file 524dadb925288ef98d9e9b35a6b1598133df21e3, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:09 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:09+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 25 00:03:09 musicvolumio volumio[4061]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 25 00:03:15 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 25 00:03:15 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:15+01:00" level=trace msg="sent dealer ping" Mar 25 00:03:15 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:15+01:00" level=trace msg="received dealer pong" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=info msg="playback was transferred to 25010PN30G" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 460" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1230" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="put connect state inactive" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=trace msg="emitting websocket event: inactive" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=trace msg="emitting websocket event: stopped" Mar 25 00:03:20 musicvolumio volumio[4061]: SPOTIFY: received: {"type":"inactive","data":null} Mar 25 00:03:20 musicvolumio volumio[4061]: error: Failed to decode event: inactive Mar 25 00:03:20 musicvolumio volumio[4061]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Mar 25 00:03:20 musicvolumio volumio[4061]: SPOTIFY: PUSH STATE SPOTIFY Mar 25 00:03:20 musicvolumio volumio[4061]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreCommandRouter::servicePushState Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:20 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:20 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:20 musicvolumio volumio[4061]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 25 00:03:20 musicvolumio volumio[4061]: verbose: CURRENT POSITION 0 Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreStateMachine::syncState stateService stop Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreStateMachine::syncState currentStatus stop Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:20 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:20 musicvolumio volumio[4061]: info: No code Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreStateMachine::pushState Mar 25 00:03:20 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:03:20 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioPushState Mar 25 00:03:20 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:20.191Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_STOPPED positionMs=10504 volume=100 Mar 25 00:03:20 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:20.191Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=spotify:track:7J1uxwnxfQLu4APicE5Rnj title="Billie Jean" Mar 25 00:03:20 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:20.192Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_STOPPED positionMs=10504 volume=100 Mar 25 00:03:20 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:20.193Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=spotify:track:7J1uxwnxfQLu4APicE5Rnj title="Billie Jean" Mar 25 00:03:20 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:20.194Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" state=STATUS_STOPPED positionMs=10504 volume=100 Mar 25 00:03:20 musicvolumio volumio5-onboarding[1891]: time=2026-03-24T23:03:20.194Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.0.214:57286 @ 0x2206c60" id=spotify:track:7J1uxwnxfQLu4APicE5Rnj title="Billie Jean" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="dealer connection closed" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="dealer recv loop stopped" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="obtained new client token: AAAliciSxfLa5Mz8beaOsGVGwNghoykUMCXgTxkb2FZIQSxhLNlwsJj6zD/nkDITX7da0HvMv+fyKKnJHPr7XFuZQyi7g5XGJ/YhtU5g+Jk/QvYlBst4S2ANrVRUWmKNT7dulPQsP7vcV8blLcpDTBlaIyTziAu+MlRS6y9Pg3BAMuBWY+1PD41DqMhw3wEXbYJy671MVhll02zkPkekTqYW3Onh2Zc/Dy7WXReU+WXXTXljoq9XYgM=" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="completed keyexchange" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="completed challenge" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=info msg="authenticated AP" username="31************************va" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=info msg="authenticated Login5" username="31************************va" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="restored session after logout" username="31************************va" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="dealer connection opened" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=trace msg="starting accesspoint recv loop" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=trace msg="starting dealer recv loop" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=trace msg="received accesspoint ping" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="received connection id: ZGRhZmI1NzctNDhl...ODE5RTZFQTBDMw==" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=trace msg="received accesspoint pong ack" Mar 25 00:03:20 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:20+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 25 00:03:21 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 25 00:03:26 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:26+01:00" level=debug msg="handling transfer player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 25 00:03:26 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:26+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:26 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:26+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:26 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:26+01:00" level=debug msg="loading track (paused: false, position: 3027ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=trace msg="emitting websocket event: will_play" Mar 25 00:03:27 musicvolumio volumio[4061]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 310" Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1173" Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=debug msg="selected format OGG_VORBIS_320 (524dadb925288ef98d9e9b35a6b1598133df21e3)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=debug msg="requested aes key for file 524dadb925288ef98d9e9b35a6b1598133df21e3, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 25 00:03:27 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:27+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 25 00:03:27 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 25 00:03:50 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:50+01:00" level=trace msg="sent dealer ping" Mar 25 00:03:50 musicvolumio go-librespot[4268]: time="2026-03-25T00:03:50+01:00" level=trace msg="received dealer pong" Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 25 00:04:01 musicvolumio volumio[4061]: info: Discovery: Getting this device information Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioGetState Mar 25 00:04:01 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 25 00:04:01 musicvolumio volumio[4061]: verbose: New Socket.io Connection to 192.168.0.75:3000 from 192.168.0.214 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 25 00:04:01 musicvolumio volumio[4061]: info: Discovery: Getting this device information Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::volumioGetState Mar 25 00:04:01 musicvolumio volumio[4061]: info: CorePlayQueue::getTrack 0 Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 25 00:04:01 musicvolumio volumio[4061]: verbose: New Socket.io Connection to 192.168.0.75:3000 from 192.168.0.214 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 25 00:04:01 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 25 00:04:08 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 25 00:04:08 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 25 00:04:10 musicvolumio volumio[4061]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 25 00:04:11 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 25 00:04:16 musicvolumio volumio[4061]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 25 00:04:16 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 25 00:04:16 musicvolumio volumio[4061]: info: Creating Spotify config file Mar 25 00:04:16 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 00:04:16 musicvolumio volumio[4061]: info: Spotify config file written Mar 25 00:04:16 musicvolumio sudo[6083]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 25 00:04:16 musicvolumio sudo[6083]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 00:04:16 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 25 00:04:16 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 25 00:04:16 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:16 musicvolumio volumio[4061]: info: Connection to go-librespot Websocket closed Mar 25 00:04:16 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:16 musicvolumio go-librespot[6085]: go-librespot daemon starting... Mar 25 00:04:16 musicvolumio sudo[6083]: pam_unix(sudo:session): session closed for user root Mar 25 00:04:16 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:16+01:00" level=info msg="running go-librespot 0.7.1" Mar 25 00:04:16 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:16+01:00" level=debug msg="app state loaded" Mar 25 00:04:16 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:16+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 00:04:17 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 00:04:17 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:17+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 00:04:17 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:17+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 00:04:17 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:17+01:00" level=info msg="zeroconf server listening on port 46209" Mar 25 00:04:17 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:17+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 25 00:04:17 musicvolumio volumio[4061]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 25 00:04:17 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 25 00:04:17 musicvolumio volumio[4061]: info: Creating Spotify config file Mar 25 00:04:17 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 00:04:17 musicvolumio volumio[4061]: info: Spotify config file written Mar 25 00:04:17 musicvolumio sudo[6096]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 25 00:04:17 musicvolumio sudo[6096]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 00:04:17 musicvolumio go-librespot[6086]: time="2026-03-25T00:04:17+01:00" level=debug msg="obtained new client token: AABj3TEIm2O7W5STJImGZk1WnMkNySXs2QiVTvzrhKr2ri/qC+G9RpFcmlKYA96siIaoF0b2qQfHkwIkRm9wNJo7/oze5mOOCIYM8mjAZ9+e7A99RCo3zEmuW3AGMTJzT8bcyzjMqII4YTFatVY31yDVpsvE3UNLRmvOZjp6XOV/Mw+AyfRuNxgIVpAY43hp8FumS0dggJcPAyCdkrzTGlxhhTry/Y8jI7yYcz9ZkDXBvZc0sk7I" Mar 25 00:04:17 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 25 00:04:17 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 6092 (go-librespot) with signal SIGKILL. Mar 25 00:04:17 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 25 00:04:17 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:17 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:17 musicvolumio go-librespot[6098]: go-librespot daemon starting... Mar 25 00:04:17 musicvolumio sudo[6096]: pam_unix(sudo:session): session closed for user root Mar 25 00:04:17 musicvolumio go-librespot[6099]: time="2026-03-25T00:04:17+01:00" level=info msg="running go-librespot 0.7.1" Mar 25 00:04:17 musicvolumio go-librespot[6099]: time="2026-03-25T00:04:17+01:00" level=debug msg="app state loaded" Mar 25 00:04:17 musicvolumio go-librespot[6099]: time="2026-03-25T00:04:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 00:04:17 musicvolumio volumio[4061]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 25 00:04:17 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 25 00:04:17 musicvolumio volumio[4061]: info: Creating Spotify config file Mar 25 00:04:17 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 00:04:17 musicvolumio volumio[4061]: info: Spotify config file written Mar 25 00:04:17 musicvolumio sudo[6108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 25 00:04:17 musicvolumio sudo[6108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 00:04:17 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 25 00:04:17 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 25 00:04:17 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:17 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:17 musicvolumio go-librespot[6110]: go-librespot daemon starting... Mar 25 00:04:17 musicvolumio sudo[6108]: pam_unix(sudo:session): session closed for user root Mar 25 00:04:17 musicvolumio volumio[4061]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 25 00:04:17 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 25 00:04:17 musicvolumio volumio[4061]: info: Creating Spotify config file Mar 25 00:04:17 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 00:04:17 musicvolumio volumio[4061]: info: Spotify config file written Mar 25 00:04:17 musicvolumio go-librespot[6111]: time="2026-03-25T00:04:17+01:00" level=info msg="running go-librespot 0.7.1" Mar 25 00:04:17 musicvolumio go-librespot[6111]: time="2026-03-25T00:04:17+01:00" level=debug msg="app state loaded" Mar 25 00:04:17 musicvolumio sudo[6118]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 25 00:04:17 musicvolumio sudo[6118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 00:04:17 musicvolumio go-librespot[6111]: time="2026-03-25T00:04:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 00:04:17 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 25 00:04:17 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 25 00:04:17 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:17 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:17 musicvolumio go-librespot[6123]: go-librespot daemon starting... Mar 25 00:04:17 musicvolumio sudo[6118]: pam_unix(sudo:session): session closed for user root Mar 25 00:04:17 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:17+01:00" level=info msg="running go-librespot 0.7.1" Mar 25 00:04:17 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:17+01:00" level=debug msg="app state loaded" Mar 25 00:04:17 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=info msg="zeroconf server listening on port 36723" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="obtained new client token: AAAZ7CM66U/oENdDDA6AHx/+xjPHH7ORMbpCzEkE9J+eQuVgvIfMQv26Cd2SjaFgSCAQmmvRlz19mWrGi5mSdNpo5Y2P7d4TftfzkvP8t7dvQg90JDVIC81qKeBC+8jS//bnH9mfkc2NDv6Jj/NeRM5O/X0slzy9UlQXUcgPa0AbQ+L0ZYAFg+m4qL1dJX4hK4FwkWiDKHv2qaqkpB4rg5Ke4g2BAJMj3qjPRoUFVdMfqvptn+1D" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="completed keyexchange" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="completed challenge" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=info msg="authenticated AP" username="31************************va" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=info msg="authenticated Login5" username="31************************va" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="initializing zeroconf session" username="31************************va" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="dealer connection opened" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=trace msg="starting accesspoint recv loop" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=trace msg="starting dealer recv loop" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=trace msg="received accesspoint ping" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="received connection id: ZjFiZGFiN2YtNzdm...NTMyNkIwRTA5Mw==" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=trace msg="received accesspoint pong ack" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="update volume requested to 65535/65535" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 25 00:04:18 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:18+01:00" level=trace msg="emitting websocket event: volume" Mar 25 00:04:19 musicvolumio volumio[4061]: info: Initializing connection to go-librespot Websocket Mar 25 00:04:19 musicvolumio go-librespot[6124]: time="2026-03-25T00:04:19+01:00" level=debug msg="new websocket client" Mar 25 00:04:19 musicvolumio volumio[4061]: info: Connection to go-librespot Websocket established Mar 25 00:04:19 musicvolumio volumio[4061]: info: go-librespot daemon successfully initialized Mar 25 00:04:20 musicvolumio volumio[4061]: info: go-librespot daemon successfully initialized Mar 25 00:04:20 musicvolumio volumio[4061]: info: go-librespot daemon successfully initialized Mar 25 00:04:20 musicvolumio volumio[4061]: info: go-librespot daemon successfully initialized Mar 25 00:04:22 musicvolumio volumio[4061]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 25 00:04:22 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 25 00:04:22 musicvolumio volumio[4061]: info: Creating Spotify config file Mar 25 00:04:22 musicvolumio volumio[4061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 25 00:04:22 musicvolumio volumio[4061]: info: Spotify config file written Mar 25 00:04:22 musicvolumio sudo[6149]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 25 00:04:22 musicvolumio sudo[6149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 00:04:22 musicvolumio volumio[4061]: info: Getting Spotify volume Mar 25 00:04:22 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 25 00:04:22 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 6127 (go-librespot) with signal SIGKILL. Mar 25 00:04:22 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 25 00:04:22 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:22 musicvolumio volumio[4061]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 00:04:22 musicvolumio volumio[4061]: Error: socket hang up Mar 25 00:04:22 musicvolumio volumio[4061]: at connResetException (node:internal/errors:720:14) Mar 25 00:04:22 musicvolumio volumio[4061]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 25 00:04:22 musicvolumio volumio[4061]: at Socket.emit (node:events:526:35) Mar 25 00:04:22 musicvolumio volumio[4061]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 25 00:04:22 musicvolumio volumio[4061]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 25 00:04:22 musicvolumio volumio[4061]: code: 'ECONNRESET', Mar 25 00:04:22 musicvolumio volumio[4061]: response: undefined Mar 25 00:04:22 musicvolumio volumio[4061]: } Mar 25 00:04:22 musicvolumio volumio[4061]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 25 00:04:22 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 25 00:04:22 musicvolumio go-librespot[6151]: go-librespot daemon starting... Mar 25 00:04:22 musicvolumio sudo[6149]: pam_unix(sudo:session): session closed for user root Mar 25 00:04:22 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:22+01:00" level=info msg="running go-librespot 0.7.1" Mar 25 00:04:22 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:22+01:00" level=debug msg="app state loaded" Mar 25 00:04:22 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=info msg="zeroconf server listening on port 44843" Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=debug msg="obtained new client token: AACPwPlwpeZ3plNfFqJPHTipzeovyHnNbXCzso+4mnuwcuD2f9FeBFEwpJucOMFnxDMyRAyg/+f/5rNyxsGVaNABH+p/oyFztNR+oPu3O96qcF9P3gyU4v2WCpm8AorivWC596zc286oQYPU2YHhPlmB21RbAsK+pZwVJojfz2irf1hUckkqG3YEwWzZ1AM/ewHyOoTkH0gWNmCNTpRH+NXXfL4YZIyhNkzPJQZYrVPob3vFBQqf" Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 25 00:04:23 musicvolumio sudo[6176]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-25 00:03' Mar 25 00:04:23 musicvolumio sudo[6176]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=debug msg="completed keyexchange" Mar 25 00:04:23 musicvolumio go-librespot[6163]: time="2026-03-25T00:04:23+01:00" level=debug msg="completed challenge" 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="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"