Mar 28 10:10:00 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 10:10:00 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:10:00 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:10:00 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:10:00 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:10:00 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:00 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:00 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:10:01 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:01+01:00" level=trace msg="sent dealer ping" Mar 28 10:10:01 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:01+01:00" level=trace msg="received dealer pong" Mar 28 10:10:07 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:09 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:10:09 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:10:09 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:10:09 musicvolumio volumio[1238]: info: [1774689009070] ControllerSpotify::clearAddPlayTrack Mar 28 10:10:09 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:09 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:09 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10: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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:09 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:09 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:10:09 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:10:09 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:10:09 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:10:09 musicvolumio volumio[1238]: info: [1774689009797] ControllerSpotify::clearAddPlayTrack Mar 28 10:10:09 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:09 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:09 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:09 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:09+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:10 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:10:10 musicvolumio volumio[1238]: info: [1774689010053] ControllerSpotify::clearAddPlayTrack Mar 28 10:10:10 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:10 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:10 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:10 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:10:10 musicvolumio volumio[1238]: info: [1774689010296] ControllerSpotify::clearAddPlayTrack Mar 28 10:10:10 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:10 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:10 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:10 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:10:10 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:10:10 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:10:10 musicvolumio volumio[1238]: info: [1774689010576] ControllerSpotify::clearAddPlayTrack Mar 28 10:10:10 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:10 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:10 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:10 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:10+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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:10 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:11 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:10:11 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:10:11 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:10:11 musicvolumio volumio[1238]: info: [1774689011442] ControllerSpotify::clearAddPlayTrack Mar 28 10:10:11 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:11 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:11 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:11 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:11 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:10:11 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:10:11 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:10:11 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:10:11 musicvolumio volumio[1238]: info: [1774689011745] ControllerSpotify::clearAddPlayTrack Mar 28 10:10:11 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:11 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:11 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:11 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:11+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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:11 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:14 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:10:14 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:10:14 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:10:14 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:10:14 musicvolumio volumio[1238]: info: [1774689014897] ControllerSpotify::clearAddPlayTrack Mar 28 10:10:14 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:10:14 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:14+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:14 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:14+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:14 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:14+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:15 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:15+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:15 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:15+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:15 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:15 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:15 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:15+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:15 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:15+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:15 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:15+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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:15 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:10:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 10:10:15 musicvolumio volumio[1238]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 28 10:10:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 28 10:10:15 musicvolumio volumio[1238]: info: Received Get System Version Mar 28 10:10:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 10:10:15 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:10:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:10:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:10:15 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:10:15 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:10:15 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:10:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:10:23 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:23+01:00" level=debug msg="handling seek_to player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:23 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:23+01:00" level=warning msg="failed handling dealer request" error="failed seeking stream: no primary stream" Mar 28 10:10:24 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:24+01:00" level=debug msg="handling seek_to player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:24 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:24+01:00" level=warning msg="failed handling dealer request" error="failed seeking stream: no primary stream" Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=debug msg="handling seek_to player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=warning msg="failed handling dealer request" error="failed seeking stream: no primary stream" Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=debug msg="handling skip_next player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:25 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:25 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:25 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:25+01:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:0uAnrNNITY7KwmOqdVEsIK): failed creating stream for spotify:track:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:26 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:26+01:00" level=debug msg="handling skip_next player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:26 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:26+01:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:26 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:26+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:26 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:26+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:26 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:26 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:26 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:26+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:26 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:26+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:26 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:26+01:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:0uAnrNNITY7KwmOqdVEsIK): failed creating stream for spotify:track:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:27 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:27+01:00" level=debug msg="handling seek_to player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:27 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:27+01:00" level=warning msg="failed handling dealer request" error="failed seeking stream: no primary stream" Mar 28 10:10:28 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:28+01:00" level=debug msg="handling seek_to player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:28 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:28+01:00" level=warning msg="failed handling dealer request" error="failed seeking stream: no primary stream" Mar 28 10:10:28 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:28+01:00" level=debug msg="handling resume player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:28 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:28+01:00" level=warning msg="failed handling dealer request" error="no primary stream" Mar 28 10:10:31 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:31+01:00" level=trace msg="sent dealer ping" Mar 28 10:10:31 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:31+01:00" level=trace msg="received dealer pong" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=info msg="playback was transferred to 25010PN30G" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1216" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 460" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="put connect state inactive" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=trace msg="emitting websocket event: inactive" Mar 28 10:10:37 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"inactive","data":null} Mar 28 10:10:37 musicvolumio volumio[1238]: error: Failed to decode event: inactive Mar 28 10:10:37 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"inactive","data":null} Mar 28 10:10:37 musicvolumio volumio[1238]: error: Failed to decode event: inactive Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="dealer connection closed" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="dealer recv loop stopped" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="obtained new client token: AADyBNkOgQkd/+mor843i7ljAF9TFZw8a9r+QGEiu2uLBgFEunUgIV2GsWvamqT5nvWj3gjgoQVowT0YjLWJBjJZIjo2E4vEXupm/b7vquh/qsGhjyvvWtTYDn89gVsas9Saa8+D+LBWVtcIlLXMDIgXzvMAWq9gWGxRQ4Fv0O/z5w+me+PBCXWuFpAiiAx/HS4H2N8VuYYJ7sk2YjRLImTQmGFkDT6dxlYO+A1C1eVm139zer7Kny4=" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="completed keyexchange" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="completed challenge" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=info msg="authenticated AP" username="31************************va" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=info msg="authenticated Login5" username="31************************va" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="restored session after logout" username="31************************va" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="dealer connection opened" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=trace msg="starting accesspoint recv loop" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=trace msg="starting dealer recv loop" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=trace msg="received accesspoint ping" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="received connection id: NjE0NThmNTQtOGMw...OEFCODZFRTgwOA==" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=trace msg="received accesspoint pong ack" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="update volume requested to 65535/65535" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 28 10:10:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:37+01:00" level=trace msg="emitting websocket event: volume" Mar 28 10:10:37 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Mar 28 10:10:37 musicvolumio volumio[1238]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Mar 28 10:10:37 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Mar 28 10:10:37 musicvolumio volumio[1238]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="handling transfer player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="loading track (paused: false, position: 2984ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:10:47 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:47 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1162" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 415" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 28 10:10:47 musicvolumio go-librespot[3490]: time="2026-03-28T10:10:47+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 28 10:11:00 musicvolumio volumio5-onboarding[1591]: time=2026-03-28T10:11:00.817+01:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.214:33784,00:00:00:00:00:00%03 @ 0x20a5620" latency=-267.480612ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Mar 28 10:11:01 musicvolumio sudo[3679]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 10:11:01 musicvolumio sudo[3679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:01 musicvolumio sudo[3679]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:01 musicvolumio sudo[3681]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 10:11:01 musicvolumio sudo[3681]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:01 musicvolumio sudo[3681]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:01 musicvolumio volumio[1238]: verbose: New Socket.io Connection to 192.168.0.73 from 192.168.0.214 UA: Mozilla/5.0 (Linux; Android 16; 25010PN30G Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Mar 28 10:11:01 musicvolumio sudo[3685]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 10:11:01 musicvolumio sudo[3685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:01 musicvolumio sudo[3685]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:01 musicvolumio sudo[3687]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 10:11:01 musicvolumio sudo[3687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:01 musicvolumio sudo[3687]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:01 musicvolumio volumio[1238]: verbose: New Socket.io Connection to 192.168.0.73 from 192.168.0.214 UA: Mozilla/5.0 (Linux; Android 16; 25010PN30G Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:01 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 28 10:11:01 musicvolumio volumio[1238]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 28 10:11:01 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:11:01 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:01 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:01 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:01 musicvolumio volumio[1238]: info: Listing playlists Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 10:11:01 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 28 10:11:02 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 10:11:03 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:11:03 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:03 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 10:11:03 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:11:03 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:03 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:03 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:11:04 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetQueue Mar 28 10:11:04 musicvolumio volumio[1238]: info: CoreStateMachine::getQueue Mar 28 10:11:04 musicvolumio volumio[1238]: info: CorePlayQueue::getQueue Mar 28 10:11:05 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:07 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioPlay Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreStateMachine::play index undefined Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 28 10:11:07 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreStateMachine::startPlaybackTimer Mar 28 10:11:07 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:11:07 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 28 10:11:07 musicvolumio volumio[1238]: info: [1774689067499] ControllerSpotify::clearAddPlayTrack Mar 28 10:11:07 musicvolumio volumio[1238]: info: Sending Spotify command with payload to local API: /player/play Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=debug msg="resolved context of track" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=trace msg="emitting websocket event: will_play" Mar 28 10:11:07 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:11:07 musicvolumio volumio[1238]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","uri":"spotify:track:0uAnrNNITY7KwmOqdVEsIK","play_origin":"go-librespot"}} Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=trace msg="sent dealer ping" Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=trace msg="received dealer pong" Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=debug msg="selected format OGG_VORBIS_320 (33c6a82e4c113b74e6c2532373ddb0c0dfcf9733)" uri="spotify:track:0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+01:00" level=debug msg="requested aes key for file 33c6a82e4c113b74e6c2532373ddb0c0dfcf9733, gid: 0uAnrNNITY7KwmOqdVEsIK" Mar 28 10:11:07 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:07+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:0uAnrNNITY7KwmOqdVEsIK: failed retrieving audio key: failed retrieving aes key with code 1" Mar 28 10:11:07 musicvolumio volumio[1238]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 28 10:11:09 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 28 10:11:11 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Mar 28 10:11:15 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Mar 28 10:11:19 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 10:11:19 musicvolumio volumio[1238]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 28 10:11:19 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 28 10:11:19 musicvolumio volumio[1238]: info: Received Get System Version Mar 28 10:11:19 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 10:11:19 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:11:19 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:11:19 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:11:19 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:11:19 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:19 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:19 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:11:22 musicvolumio volumio5-onboarding[1591]: time=2026-03-28T10:11:22.927+01:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.214:33784,00:00:00:00:00:00%03 @ 0x20a5620" latency=-263.940495ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Mar 28 10:11:23 musicvolumio sudo[3736]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 10:11:23 musicvolumio sudo[3736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:23 musicvolumio sudo[3736]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:23 musicvolumio sudo[3738]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 10:11:23 musicvolumio sudo[3738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:23 musicvolumio sudo[3738]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:23 musicvolumio volumio[1238]: verbose: New Socket.io Connection to 192.168.0.73 from 192.168.0.214 UA: Mozilla/5.0 (Linux; Android 16; 25010PN30G Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Mar 28 10:11:23 musicvolumio sudo[3756]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 10:11:23 musicvolumio sudo[3756]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:23 musicvolumio sudo[3756]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:23 musicvolumio sudo[3758]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 10:11:23 musicvolumio sudo[3758]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:23 musicvolumio sudo[3758]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:23 musicvolumio volumio[1238]: verbose: New Socket.io Connection to 192.168.0.73 from 192.168.0.214 UA: Mozilla/5.0 (Linux; Android 16; 25010PN30G Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:23 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 28 10:11:23 musicvolumio volumio[1238]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 28 10:11:23 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:11:23 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:23 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:23 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:23 musicvolumio volumio[1238]: info: Listing playlists Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 10:11:23 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 28 10:11:24 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 28 10:11:24 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 10:11:25 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:11:25 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:25 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 10:11:25 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:11:25 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:25 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:25 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:11:30 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 28 10:11:30 musicvolumio volumio[1238]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 10:11:30 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 28 10:11:30 musicvolumio volumio[1238]: Disk list : [] Mar 28 10:11:30 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 28 10:11:30 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 28 10:11:30 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Mar 28 10:11:30 musicvolumio volumio[1238]: info: Received Get System Version Mar 28 10:11:30 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 10:11:32 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 28 10:11:33 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 28 10:11:36 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 10:11:36 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 28 10:11:36 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 28 10:11:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:37+01:00" level=trace msg="sent dealer ping" Mar 28 10:11:37 musicvolumio go-librespot[3490]: time="2026-03-28T10:11:37+01:00" level=trace msg="received dealer pong" Mar 28 10:11:39 musicvolumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Mar 28 10:11:40 musicvolumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Mar 28 10:11:40 musicvolumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Mar 28 10:11:41 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 10:11:41 musicvolumio volumio[1238]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 28 10:11:41 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 28 10:11:41 musicvolumio volumio[1238]: info: Received Get System Version Mar 28 10:11:41 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 10:11:41 musicvolumio volumio[1238]: info: Received Get System Info Mar 28 10:11:41 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 10:11:41 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 10:11:41 musicvolumio volumio[1238]: info: Discovery: Getting this device information Mar 28 10:11:41 musicvolumio volumio[1238]: info: CoreCommandRouter::volumioGetState Mar 28 10:11:41 musicvolumio volumio[1238]: info: CorePlayQueue::getTrack 0 Mar 28 10:11:41 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 10:11:43 musicvolumio volumio[1238]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 28 10:11:50 musicvolumio volumio[1238]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 10:11:50 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 10:11:50 musicvolumio volumio[1238]: info: Creating Spotify config file Mar 28 10:11:50 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 10:11:50 musicvolumio volumio[1238]: info: Spotify config file written Mar 28 10:11:50 musicvolumio sudo[3850]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 10:11:50 musicvolumio sudo[3850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:50 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 10:11:50 musicvolumio volumio[1238]: info: Connection to go-librespot Websocket closed Mar 28 10:11:50 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 10:11:50 musicvolumio volumio[1238]: info: Connection to go-librespot Websocket closed Mar 28 10:11:50 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:50 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:50 musicvolumio go-librespot[3852]: go-librespot daemon starting... Mar 28 10:11:50 musicvolumio sudo[3850]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:50 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:50+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 10:11:50 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:50+01:00" level=debug msg="app state loaded" Mar 28 10:11:50 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:50+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 10:11:50 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:50+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 28 10:11:50 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:50+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 28 10:11:50 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:50+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 28 10:11:50 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:50+01:00" level=info msg="zeroconf server listening on port 39067" Mar 28 10:11:50 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:50+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 28 10:11:51 musicvolumio ntpd[1042]: PROTO: 172.232.209.103 unlink local addr 192.168.0.73 -> Mar 28 10:11:51 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:51+01:00" level=debug msg="obtained new client token: AACPjwx254FgzwsdXEBiOxVpyf/Q3Ekk1Hucsx84Gj3jocZiNtQrWyMtL28Lrr9SrhC/kiTcCwgaw2fJMmfIl6An9ZEOr2tbxvOikUrKLbhEiWZy09Cyue/gwx3JtJhlnjvVfhS0rlKdhlAU1/FT8fBdAbc84rskXsBcXRVrbIydLP5GGZve2k+KnHgnwsouXgD+ahw1IHVVH8BpX952cmLwMmcdaGqhGEmq3w5UDBxf3INOrNp7598=" Mar 28 10:11:51 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:51+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 10:11:51 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:51+01:00" level=debug msg="completed keyexchange" Mar 28 10:11:51 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:51+01:00" level=debug msg="completed challenge" Mar 28 10:11:51 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:51+01:00" level=info msg="authenticated AP" username="31************************va" Mar 28 10:11:51 musicvolumio volumio[1238]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 10:11:51 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 10:11:51 musicvolumio volumio[1238]: info: Creating Spotify config file Mar 28 10:11:51 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 10:11:51 musicvolumio volumio[1238]: info: Spotify config file written Mar 28 10:11:51 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:51+01:00" level=info msg="authenticated Login5" username="31************************va" Mar 28 10:11:51 musicvolumio go-librespot[3853]: time="2026-03-28T10:11:51+01:00" level=debug msg="initializing zeroconf session" username="31************************va" Mar 28 10:11:51 musicvolumio sudo[3863]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 10:11:51 musicvolumio sudo[3863]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:51 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 10:11:51 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 10:11:51 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:51 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:51 musicvolumio go-librespot[3865]: go-librespot daemon starting... Mar 28 10:11:51 musicvolumio sudo[3863]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:51 musicvolumio go-librespot[3866]: time="2026-03-28T10:11:51+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 10:11:51 musicvolumio go-librespot[3866]: time="2026-03-28T10:11:51+01:00" level=debug msg="app state loaded" Mar 28 10:11:51 musicvolumio go-librespot[3866]: time="2026-03-28T10:11:51+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 10:11:51 musicvolumio volumio[1238]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 10:11:51 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 10:11:51 musicvolumio volumio[1238]: info: Creating Spotify config file Mar 28 10:11:51 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 10:11:51 musicvolumio volumio[1238]: info: Spotify config file written Mar 28 10:11:51 musicvolumio go-librespot[3866]: time="2026-03-28T10:11:51+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 28 10:11:51 musicvolumio go-librespot[3866]: time="2026-03-28T10:11:51+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 28 10:11:51 musicvolumio go-librespot[3866]: time="2026-03-28T10:11:51+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 28 10:11:51 musicvolumio go-librespot[3866]: time="2026-03-28T10:11:51+01:00" level=info msg="zeroconf server listening on port 43219" Mar 28 10:11:51 musicvolumio sudo[3876]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 10:11:51 musicvolumio sudo[3876]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:51 musicvolumio go-librespot[3866]: time="2026-03-28T10:11:51+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 28 10:11:51 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 10:11:51 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 10:11:51 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:51 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:51 musicvolumio sudo[3876]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:51 musicvolumio go-librespot[3878]: go-librespot daemon starting... Mar 28 10:11:51 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:51+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 10:11:51 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:51+01:00" level=debug msg="app state loaded" Mar 28 10:11:51 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:51+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+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 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+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 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+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 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=info msg="zeroconf server listening on port 38065" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="obtained new client token: AADjOpp08x016RYGbZFTDXVBr2tmzJZKmZhiakvuc9oI1MKwqmxpDAWVdOZCyxEfuggcRC8ya1MKkQVilx2QU2M5eBsk1QNwNlB1CYVQiG8QnKhyG+BTyyrUOqVmuWdw02kVbzlJjH6iLZWxsHrZYIXWKoRKWqoOGGtB2To4y94y4Lu6f+FqTsZQSKaZ02HMnP7eCHNhxjcXxok2puNTh6XpFwCoUlKIBLkj+DItQQDZdgYwiQHOQuk=" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="completed keyexchange" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="completed challenge" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=info msg="authenticated AP" username="31************************va" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=info msg="authenticated Login5" username="31************************va" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="initializing zeroconf session" username="31************************va" Mar 28 10:11:52 musicvolumio volumio[1238]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 10:11:52 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 10:11:52 musicvolumio volumio[1238]: info: Creating Spotify config file Mar 28 10:11:52 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 10:11:52 musicvolumio volumio[1238]: info: Spotify config file written Mar 28 10:11:52 musicvolumio sudo[3889]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 10:11:52 musicvolumio sudo[3889]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="dealer connection opened" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=trace msg="starting accesspoint recv loop" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=trace msg="starting dealer recv loop" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=trace msg="received accesspoint ping" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 28 10:11:52 musicvolumio go-librespot[3879]: time="2026-03-28T10:11:52+01:00" level=debug msg="received connection id: NTQ5NTQ4OTctMGZj...MkIzRTREMkZDQQ==" Mar 28 10:11:52 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 10:11:52 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 3884 (go-librespot) with signal SIGKILL. Mar 28 10:11:52 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 10:11:52 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:52 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:52 musicvolumio go-librespot[3891]: go-librespot daemon starting... Mar 28 10:11:52 musicvolumio sudo[3889]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:52 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:52+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 10:11:52 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:52+01:00" level=debug msg="app state loaded" Mar 28 10:11:52 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:52+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 10:11:53 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+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 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+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 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+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 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+01:00" level=info msg="zeroconf server listening on port 39841" Mar 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+01:00" level=debug msg="obtained new client token: AADRM83LTJbGr9yAOZ69NHuRF1pPjrNrfxgZfyXclKKQLOYJbS5/QuPo6GoiBSf9qRp12KeZLjEk7ZAWCpuGp+gpI1EeV8A8txE4dEnBTtsd+fUiygvPm9iwm+q6rc1vQ4SN/R688GsxiEo547i9Lu4VdoENtrDrSeu6Eh4Gjgi7ZdyeWGilmrLdQdZZero0/rXdqC5hWtYGWBA48nmkfYGxhCCQ5u7CSXMFOAvlyzJKXw+JDBCf37c=" Mar 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 28 10:11:53 musicvolumio volumio[1238]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 10:11:53 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 10:11:53 musicvolumio volumio[1238]: info: Creating Spotify config file Mar 28 10:11:53 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 10:11:53 musicvolumio volumio[1238]: info: Spotify config file written Mar 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+01:00" level=debug msg="completed keyexchange" Mar 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+01:00" level=debug msg="completed challenge" Mar 28 10:11:53 musicvolumio sudo[3917]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 10:11:53 musicvolumio sudo[3917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:53 musicvolumio go-librespot[3892]: time="2026-03-28T10:11:53+01:00" level=info msg="authenticated AP" username="31************************va" Mar 28 10:11:53 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 10:11:53 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 10:11:53 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:53 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:53 musicvolumio go-librespot[3919]: go-librespot daemon starting... Mar 28 10:11:53 musicvolumio sudo[3917]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+01:00" level=debug msg="app state loaded" Mar 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 10:11:53 musicvolumio volumio[1238]: info: Initializing connection to go-librespot Websocket Mar 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+01:00" level=debug msg="new websocket client" Mar 28 10:11:53 musicvolumio volumio[1238]: info: Connection to go-librespot Websocket established Mar 28 10:11:53 musicvolumio volumio[1238]: info: go-librespot daemon successfully initialized Mar 28 10:11:53 musicvolumio volumio[1238]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 10:11:53 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 10:11:53 musicvolumio volumio[1238]: info: Creating Spotify config file Mar 28 10:11:53 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 10:11:53 musicvolumio volumio[1238]: info: Spotify config file written Mar 28 10:11:53 musicvolumio sudo[3932]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 10:11:53 musicvolumio sudo[3932]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+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 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+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 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+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 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+01:00" level=info msg="zeroconf server listening on port 41215" Mar 28 10:11:53 musicvolumio go-librespot[3920]: time="2026-03-28T10:11:53+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 28 10:11:53 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 10:11:54 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 3929 (go-librespot) with signal SIGKILL. Mar 28 10:11:54 musicvolumio volumio[1238]: info: Connection to go-librespot Websocket closed Mar 28 10:11:54 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 10:11:54 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:54 musicvolumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 28 10:11:54 musicvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 28 10:11:54 musicvolumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:54 musicvolumio sudo[3932]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:54 musicvolumio volumio[1238]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 28 10:11:54 musicvolumio volumio[1238]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 28 10:11:54 musicvolumio volumio[1238]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 28 10:11:54 musicvolumio volumio[1238]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 28 10:11:54 musicvolumio volumio[1238]: followed by "systemctl start go-librespot-daemon.service" again. Mar 28 10:11:54 musicvolumio volumio[1238]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 28 10:11:54 musicvolumio volumio[1238]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 28 10:11:54 musicvolumio volumio[1238]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 28 10:11:54 musicvolumio volumio[1238]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 28 10:11:54 musicvolumio volumio[1238]: followed by "systemctl start go-librespot-daemon.service" again. Mar 28 10:11:54 musicvolumio volumio[1238]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 10:11:54 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 10:11:54 musicvolumio volumio[1238]: info: Creating Spotify config file Mar 28 10:11:54 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 10:11:54 musicvolumio volumio[1238]: info: Spotify config file written Mar 28 10:11:54 musicvolumio sudo[3939]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 10:11:54 musicvolumio sudo[3939]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:54 musicvolumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 28 10:11:54 musicvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 28 10:11:54 musicvolumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:54 musicvolumio sudo[3939]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:54 musicvolumio volumio[1238]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 28 10:11:54 musicvolumio volumio[1238]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 28 10:11:54 musicvolumio volumio[1238]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 28 10:11:54 musicvolumio volumio[1238]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 28 10:11:54 musicvolumio volumio[1238]: followed by "systemctl start go-librespot-daemon.service" again. Mar 28 10:11:54 musicvolumio volumio[1238]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 28 10:11:54 musicvolumio volumio[1238]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 28 10:11:54 musicvolumio volumio[1238]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 28 10:11:54 musicvolumio volumio[1238]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 28 10:11:54 musicvolumio volumio[1238]: followed by "systemctl start go-librespot-daemon.service" again. Mar 28 10:11:54 musicvolumio volumio[1238]: info: go-librespot daemon successfully initialized Mar 28 10:11:54 musicvolumio volumio[1238]: info: go-librespot daemon successfully initialized Mar 28 10:11:55 musicvolumio ntpd[1042]: PROTO: 162.159.200.123 unlink local addr 192.168.0.73 -> Mar 28 10:11:55 musicvolumio volumio[1238]: info: go-librespot daemon successfully initialized Mar 28 10:11:56 musicvolumio ntpd[1042]: PROTO: 89.46.74.148 unlink local addr 192.168.0.73 -> Mar 28 10:11:56 musicvolumio volumio[1238]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 28 10:11:56 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 28 10:11:56 musicvolumio volumio[1238]: info: Creating Spotify config file Mar 28 10:11:56 musicvolumio volumio[1238]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 10:11:56 musicvolumio volumio[1238]: info: Spotify config file written Mar 28 10:11:56 musicvolumio sudo[3943]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 10:11:56 musicvolumio sudo[3943]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 10:11:56 musicvolumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 28 10:11:56 musicvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 28 10:11:56 musicvolumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 28 10:11:56 musicvolumio sudo[3943]: pam_unix(sudo:session): session closed for user root Mar 28 10:11:56 musicvolumio volumio[1238]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 28 10:11:56 musicvolumio volumio[1238]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 28 10:11:56 musicvolumio volumio[1238]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 28 10:11:56 musicvolumio volumio[1238]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 28 10:11:56 musicvolumio volumio[1238]: followed by "systemctl start go-librespot-daemon.service" again. Mar 28 10:11:56 musicvolumio volumio[1238]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 28 10:11:56 musicvolumio volumio[1238]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 28 10:11:56 musicvolumio volumio[1238]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 28 10:11:56 musicvolumio volumio[1238]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 28 10:11:56 musicvolumio volumio[1238]: followed by "systemctl start go-librespot-daemon.service" again. Mar 28 10:11:56 musicvolumio volumio[1238]: info: go-librespot daemon successfully initialized Mar 28 10:11:56 musicvolumio volumio[1238]: info: Getting Spotify volume Mar 28 10:11:56 musicvolumio volumio[1238]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 10:11:56 musicvolumio volumio[1238]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 10:11:56 musicvolumio volumio[1238]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 28 10:11:56 musicvolumio volumio[1238]: errno: -111, Mar 28 10:11:56 musicvolumio volumio[1238]: code: 'ECONNREFUSED', Mar 28 10:11:56 musicvolumio volumio[1238]: syscall: 'connect', Mar 28 10:11:56 musicvolumio volumio[1238]: address: '127.0.0.1', Mar 28 10:11:56 musicvolumio volumio[1238]: port: 9879, Mar 28 10:11:56 musicvolumio volumio[1238]: response: undefined Mar 28 10:11:56 musicvolumio volumio[1238]: } Mar 28 10:11:56 musicvolumio volumio[1238]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 10:11:57 musicvolumio ntpd[1042]: PROTO: 172.232.208.229 unlink local addr 192.168.0.73 -> Mar 28 10:11:57 musicvolumio sudo[3959]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-28 10:10' Mar 28 10:11:57 musicvolumio sudo[3959]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"