Dec 30 20:21:00 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 30 20:21:00 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 30 20:21:00 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:00+01:00" level=trace msg="sent dealer ping" Dec 30 20:21:00 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:00+01:00" level=trace msg="received dealer pong" Dec 30 20:21:16 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 30 20:21:16 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 30 20:21:30 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:30+01:00" level=trace msg="received accesspoint ping" Dec 30 20:21:30 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:30+01:00" level=trace msg="received accesspoint pong ack" Dec 30 20:21:30 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:30+01:00" level=trace msg="sent dealer ping" Dec 30 20:21:30 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:30+01:00" level=trace msg="received dealer pong" Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPlay Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::play index undefined Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 30 20:21:49 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::startPlaybackTimer Dec 30 20:21:49 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:49 volumio-manu volumio[1179]: info: [1767122509629] ControllerWebradio::clearAddPlayTrack Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand stop Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand stop took 1 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand clear Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces system playlist update Dec 30 20:21:49 volumio-manu volumio[1179]: info: Ignoring MPD Status Update Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand clear took 1 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand add "https://stream.radiofrance.fr/fipcultes/fipcultes_hifi.m3u8?id=radiofrance" Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces system playlist update Dec 30 20:21:49 volumio-manu volumio[1179]: info: Ignoring MPD Status Update Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces system playlist update Dec 30 20:21:49 volumio-manu volumio[1179]: info: Ignoring MPD Status Update Dec 30 20:21:49 volumio-manu volumio[1179]: error: updateQueue error: null Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces system playlist update Dec 30 20:21:49 volumio-manu volumio[1179]: info: Ignoring MPD Status Update Dec 30 20:21:49 volumio-manu volumio[1179]: info: ------------------------------ 4ms Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand add "https://stream.radiofrance.fr/fipcultes/fipcultes_hifi.m3u8?id=radiofrance" took 3 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: info: ------------------------------ 3ms Dec 30 20:21:49 volumio-manu volumio[1179]: info: ------------------------------ 2ms Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::setConsumeUpdateService mpd Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand play Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces system playlist update Dec 30 20:21:49 volumio-manu volumio[1179]: info: Ignoring MPD Status Update Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces system playlist update Dec 30 20:21:49 volumio-manu volumio[1179]: info: Ignoring MPD Status Update Dec 30 20:21:49 volumio-manu volumio[1179]: info: ------------------------------ 5ms Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand play took 4 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: info: ------------------------------ 3ms Dec 30 20:21:49 volumio-manu volumio[1179]: info: ------------------------------ 2ms Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces state update: player Dec 30 20:21:49 volumio-manu volumio[1179]: info: ControllerMpd::getState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces state update: player Dec 30 20:21:49 volumio-manu volumio[1179]: info: ControllerMpd::getState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces state update: player Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces state update: player Dec 30 20:21:49 volumio-manu volumio[1179]: info: ControllerMpd::getState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand status took 6 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: info: ControllerMpd::getState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand status took 5 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::parseState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::parseState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 30 20:21:49 volumio-manu volumio[1179]: info: Dec 30 20:21:49 volumio-manu volumio[1179]: ---------------------------- MPD announces state update: player Dec 30 20:21:49 volumio-manu volumio[1179]: info: ControllerMpd::getState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand status took 6 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand status took 6 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand playlistinfo took 4 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand playlistinfo took 4 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: info: sendMpdCommand status took 2 milliseconds Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::parseState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::parseState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::parseTrackInfo Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::parseTrackInfo Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::parseState Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 30 20:21:49 volumio-manu volumio[1179]: info: ControllerMpd::pushState Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreCommandRouter::servicePushState Dec 30 20:21:49 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"fipcultes_hifi.m3u8?id=radiofrance","artist":null,"album":null,"uri":"https://stream.radiofrance.fr/fipcultes/fipcultes_hifi.m3u8?id=radiofrance","trackType":""} Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: CURRENT POSITION 0 Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::syncState stateService play Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::syncState currentStatus stop Dec 30 20:21:49 volumio-manu volumio[1179]: info: ControllerMpd::pushState Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreCommandRouter::servicePushState Dec 30 20:21:49 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"fipcultes_hifi.m3u8?id=radiofrance","artist":null,"album":null,"uri":"https://stream.radiofrance.fr/fipcultes/fipcultes_hifi.m3u8?id=radiofrance","trackType":""} Dec 30 20:21:49 volumio-manu volumio[1179]: verbose: CURRENT POSITION 0 Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::syncState stateService play Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::syncState currentStatus play Dec 30 20:21:49 volumio-manu volumio[1179]: info: Received an update from plugin. extracting info from payload Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:49 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 20:21:49 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: ------------------------------ 30ms Dec 30 20:21:50 volumio-manu volumio[1179]: info: ------------------------------ 50ms Dec 30 20:21:50 volumio-manu volumio[1179]: info: Dec 30 20:21:50 volumio-manu volumio[1179]: ---------------------------- MPD announces state update: player Dec 30 20:21:50 volumio-manu volumio[1179]: info: ControllerMpd::getState Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand status Dec 30 20:21:50 volumio-manu volumio[1179]: info: sendMpdCommand playlistinfo took 41 milliseconds Dec 30 20:21:50 volumio-manu volumio[1179]: info: sendMpdCommand playlistinfo took 41 milliseconds Dec 30 20:21:50 volumio-manu volumio[1179]: info: sendMpdCommand playlistinfo took 40 milliseconds Dec 30 20:21:50 volumio-manu volumio[1179]: info: sendMpdCommand status took 2 milliseconds Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: ControllerMpd::parseTrackInfo Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: ControllerMpd::parseTrackInfo Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: ControllerMpd::parseTrackInfo Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: ControllerMpd::parseState Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 30 20:21:50 volumio-manu volumio[1179]: info: ControllerMpd::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::servicePushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":210,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"fipcultes_hifi.m3u8?id=radiofrance","artist":null,"album":null,"uri":"https://stream.radiofrance.fr/fipcultes/fipcultes_hifi.m3u8?id=radiofrance","trackType":""} Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: CURRENT POSITION 0 Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::syncState stateService play Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::syncState currentStatus play Dec 30 20:21:50 volumio-manu volumio[1179]: info: Received an update from plugin. extracting info from payload Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: ControllerMpd::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::servicePushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":231,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"fipcultes_hifi.m3u8?id=radiofrance","artist":null,"album":null,"uri":"https://stream.radiofrance.fr/fipcultes/fipcultes_hifi.m3u8?id=radiofrance","trackType":""} Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: CURRENT POSITION 0 Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::syncState stateService play Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::syncState currentStatus play Dec 30 20:21:50 volumio-manu volumio[1179]: info: Received an update from plugin. extracting info from payload Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: ControllerMpd::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::servicePushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":231,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"fipcultes_hifi.m3u8?id=radiofrance","artist":null,"album":null,"uri":"https://stream.radiofrance.fr/fipcultes/fipcultes_hifi.m3u8?id=radiofrance","trackType":""} Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: CURRENT POSITION 0 Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::syncState stateService play Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::syncState currentStatus play Dec 30 20:21:50 volumio-manu volumio[1179]: info: Received an update from plugin. extracting info from payload Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: ------------------------------ 154ms Dec 30 20:21:50 volumio-manu volumio[1179]: info: ------------------------------ 155ms Dec 30 20:21:50 volumio-manu volumio[1179]: info: ------------------------------ 151ms Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: info: sendMpdCommand playlistinfo took 158 milliseconds Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: ControllerMpd::parseTrackInfo Dec 30 20:21:50 volumio-manu volumio[1179]: info: ControllerMpd::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::servicePushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: STATE SERVICE {"status":"play","position":0,"seek":231,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"fipcultes_hifi.m3u8?id=radiofrance","artist":null,"album":null,"uri":"https://stream.radiofrance.fr/fipcultes/fipcultes_hifi.m3u8?id=radiofrance","trackType":""} Dec 30 20:21:50 volumio-manu volumio[1179]: verbose: CURRENT POSITION 0 Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::syncState stateService play Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::syncState currentStatus play Dec 30 20:21:50 volumio-manu volumio[1179]: info: Received an update from plugin. extracting info from payload Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CorePlayQueue::getTrack 0 Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:50 volumio-manu volumio[1179]: info: ------------------------------ 185ms Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:50 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Dec 30 20:21:55 volumio-manu volumio[1179]: info: VolumeController::SetAlsaVolume76 Dec 30 20:21:55 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:55 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 20:21:55 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:55 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 76 Dec 30 20:21:55 volumio-manu volumio[1179]: SPOTIFY: SPOTIFY VOLUME 57 Dec 30 20:21:55 volumio-manu volumio[1179]: SPOTIFY: VOLUMIO VOLUME 76 Dec 30 20:21:55 volumio-manu volumio[1179]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 30 20:21:55 volumio-manu volumio[1179]: info: Setting Spotify Volume from Volumio: 76 Dec 30 20:21:55 volumio-manu volumio[1179]: info: VolumeController::SetAlsaVolume78 Dec 30 20:21:55 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:55 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 20:21:55 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:55 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 Dec 30 20:21:55 volumio-manu volumio[1179]: SPOTIFY: SPOTIFY VOLUME 76 Dec 30 20:21:55 volumio-manu volumio[1179]: SPOTIFY: VOLUMIO VOLUME 78 Dec 30 20:21:55 volumio-manu volumio[1179]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 30 20:21:55 volumio-manu volumio[1179]: info: Setting Spotify Volume from Volumio: 78 Dec 30 20:21:56 volumio-manu volumio[1179]: info: VolumeController::SetAlsaVolume100 Dec 30 20:21:56 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:56 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 20:21:56 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:56 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 20:21:56 volumio-manu volumio[1179]: SPOTIFY: SPOTIFY VOLUME 78 Dec 30 20:21:56 volumio-manu volumio[1179]: SPOTIFY: VOLUMIO VOLUME 100 Dec 30 20:21:56 volumio-manu volumio[1179]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 30 20:21:56 volumio-manu volumio[1179]: info: Setting Spotify Volume from Volumio: 100 Dec 30 20:21:57 volumio-manu volumio[1179]: info: VolumeController::SetAlsaVolume61 Dec 30 20:21:57 volumio-manu volumio[1179]: info: CoreStateMachine::pushState Dec 30 20:21:57 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 20:21:57 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioPushState Dec 30 20:21:57 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Dec 30 20:21:57 volumio-manu volumio[1179]: SPOTIFY: SPOTIFY VOLUME 100 Dec 30 20:21:57 volumio-manu volumio[1179]: SPOTIFY: VOLUMIO VOLUME 61 Dec 30 20:21:57 volumio-manu volumio[1179]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 30 20:21:57 volumio-manu volumio[1179]: info: Setting Spotify Volume from Volumio: 61 Dec 30 20:21:59 volumio-manu volumio[1179]: SPOTIFY: SETTING SPOTIFY VOLUME 61 Dec 30 20:21:59 volumio-manu volumio[1179]: info: Sending Spotify command with payload to local API: /player/volume Dec 30 20:21:59 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:59+01:00" level=debug msg="update volume requested to 39976/65535" Dec 30 20:21:59 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:59+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 30 20:21:59 volumio-manu go-librespot[1528]: time="2025-12-30T20:21:59+01:00" level=trace msg="emitting websocket event: volume" Dec 30 20:21:59 volumio-manu volumio[1179]: SPOTIFY: received: {"type":"volume","data":{"value":61,"max":100}} Dec 30 20:21:59 volumio-manu volumio[1179]: SPOTIFY: RECEIVED SPOTIFY VOLUME 61 Dec 30 20:22:00 volumio-manu go-librespot[1528]: time="2025-12-30T20:22:00+01:00" level=trace msg="sent dealer ping" Dec 30 20:22:00 volumio-manu go-librespot[1528]: time="2025-12-30T20:22:00+01:00" level=trace msg="received dealer pong" Dec 30 20:22:11 volumio-manu volumio[1179]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 30 20:22:30 volumio-manu go-librespot[1528]: time="2025-12-30T20:22:30+01:00" level=trace msg="sent dealer ping" Dec 30 20:22:30 volumio-manu go-librespot[1528]: time="2025-12-30T20:22:30+01:00" level=trace msg="received dealer pong" Dec 30 20:22:33 volumio-manu volumio[1179]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 30 20:22:33 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 30 20:22:33 volumio-manu volumio[1179]: info: Creating Spotify config file Dec 30 20:22:33 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 20:22:33 volumio-manu volumio[1179]: info: Spotify config file written Dec 30 20:22:33 volumio-manu sudo[6907]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 20:22:33 volumio-manu sudo[6907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 20:22:33 volumio-manu systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 20:22:33 volumio-manu systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 20:22:33 volumio-manu systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:33 volumio-manu systemd[1]: go-librespot-daemon.service: Consumed 1.256s CPU time. Dec 30 20:22:33 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket closed Dec 30 20:22:33 volumio-manu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:33 volumio-manu go-librespot[6909]: go-librespot daemon starting... Dec 30 20:22:33 volumio-manu sudo[6907]: pam_unix(sudo:session): session closed for user root Dec 30 20:22:33 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:33+01:00" level=info msg="running go-librespot 0.4.0" Dec 30 20:22:33 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:33+01:00" level=debug msg="app state loaded" Dec 30 20:22:33 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=info msg="zeroconf server listening on port 36553" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="obtained new client token: AAAYpInQB2tAuluDavNPPzq3uf2oOvJHh8pgjhCTkz6SpzN8ekAP063FoHda3SWs8hg9lw0kfjLM9qi5SrsiaWFjO9KUo4CSgZ9GJo6Qn22/CETYdYNJQQzrEfnRYSCWbN0usmyDULoHO4rIJVWyg+o2u3thtptp9kYqAYnsvRMJz9P56UzZQeuFC7vkEyWSg1y/sImRJG0jZ5kj/wk0RIEGmatLoITrjjugrZJboVdbKzlNWqCUsA==" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="completed keyexchange" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="completed challenge" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=info msg="authenticated AP" username="31************************my" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=info msg="authenticated Login5" username="31************************my" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="initializing zeroconf session" username="31************************my" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="dealer connection opened" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=trace msg="starting accesspoint recv loop" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=trace msg="starting dealer recv loop" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=trace msg="received accesspoint ping" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="received connection id: NjQzNGNhNDEtMGI2...QjU0MDFCMTI4Rg==" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=trace msg="received accesspoint pong ack" Dec 30 20:22:34 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:34+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 30 20:22:36 volumio-manu volumio[1179]: info: Initializing connection to go-librespot Websocket Dec 30 20:22:36 volumio-manu go-librespot[6910]: time="2025-12-30T20:22:36+01:00" level=debug msg="new websocket client" Dec 30 20:22:36 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket established Dec 30 20:22:36 volumio-manu volumio[1179]: info: go-librespot daemon successfully initialized Dec 30 20:22:37 volumio-manu volumio[1179]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 30 20:22:37 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 30 20:22:37 volumio-manu volumio[1179]: info: Creating Spotify config file Dec 30 20:22:37 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 20:22:37 volumio-manu volumio[1179]: info: Spotify config file written Dec 30 20:22:37 volumio-manu sudo[6930]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 20:22:37 volumio-manu sudo[6930]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 20:22:37 volumio-manu systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 20:22:37 volumio-manu systemd[1]: go-librespot-daemon.service: Killing process 6915 (go-librespot) with signal SIGKILL. Dec 30 20:22:37 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket closed Dec 30 20:22:37 volumio-manu systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 20:22:37 volumio-manu systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:37 volumio-manu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:37 volumio-manu go-librespot[6933]: go-librespot daemon starting... Dec 30 20:22:37 volumio-manu sudo[6930]: pam_unix(sudo:session): session closed for user root Dec 30 20:22:37 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:37+01:00" level=info msg="running go-librespot 0.4.0" Dec 30 20:22:37 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:37+01:00" level=debug msg="app state loaded" Dec 30 20:22:37 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 20:22:37 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 30 20:22:37 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:37+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 30 20:22:37 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:37+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 30 20:22:37 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:37+01:00" level=info msg="zeroconf server listening on port 44289" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="obtained new client token: AAAH0wcke0rlUnrCyTTHrtFopulzt0x1BAaQ3aiXM6TSDxuyOLD9IBuJWRLav3W/2F84kUY3CciwxlUXgwdLrcnsenNjCLLHa51zM8y7PAGNFgw5ehpLsMVvlntIMQ6WwRZKRGXZ1xpz0qJSvz1sySfBCcm13SLhPZ2CVDF/gFDlH7+pMTkVfn7p/KXuxtTytCH1bSMOHsIjLjjlPunlIkwqT+ZKFtDdIMBKHS2/NspofjF33Eiuyw==" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="completed keyexchange" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="completed challenge" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=info msg="authenticated AP" username="31************************my" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=info msg="authenticated Login5" username="31************************my" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="initializing zeroconf session" username="31************************my" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="dealer connection opened" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=trace msg="starting accesspoint recv loop" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=trace msg="starting dealer recv loop" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=trace msg="received accesspoint ping" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="received connection id: MDg5YTBkMzUtMmRj...ODZCNzVBNDNDMA==" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=trace msg="received accesspoint pong ack" Dec 30 20:22:38 volumio-manu go-librespot[6934]: time="2025-12-30T20:22:38+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 30 20:22:38 volumio-manu volumio[1179]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 30 20:22:38 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 30 20:22:38 volumio-manu volumio[1179]: info: Creating Spotify config file Dec 30 20:22:38 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 20:22:38 volumio-manu volumio[1179]: info: Spotify config file written Dec 30 20:22:38 volumio-manu sudo[6944]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 20:22:38 volumio-manu sudo[6944]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 20:22:38 volumio-manu systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 20:22:38 volumio-manu systemd[1]: go-librespot-daemon.service: Killing process 6936 (go-librespot) with signal SIGKILL. Dec 30 20:22:38 volumio-manu systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 20:22:38 volumio-manu systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:38 volumio-manu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:38 volumio-manu go-librespot[6946]: go-librespot daemon starting... Dec 30 20:22:38 volumio-manu sudo[6944]: pam_unix(sudo:session): session closed for user root Dec 30 20:22:38 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:38+01:00" level=info msg="running go-librespot 0.4.0" Dec 30 20:22:38 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:38+01:00" level=debug msg="app state loaded" Dec 30 20:22:38 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:38+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=info msg="zeroconf server listening on port 42755" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="obtained new client token: AAAFDqcwBa+IDM4d3UJor3q+xlFrYLgns8xdMeQ75AcjDXxzMOiKrMNxgP02qjuDs6dOo5PwxxQiXgH0CkPOWb3mEHKnjuQ9umEnz+81YwcUAJoh0ypMLI5YUbN3+qi/HMMTQpSFPoeZRw6Da7dZMGjAWz/7tIQmuxxJ09p1D+If4SIljah6XDSumLL0Yvqg6siZn+YNz72CnL1EQqvsSyG7DsSvUjlRwfB9DIsScQLCjuQypnmXjg==" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="completed keyexchange" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="completed challenge" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=info msg="authenticated AP" username="31************************my" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=info msg="authenticated Login5" username="31************************my" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="initializing zeroconf session" username="31************************my" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="dealer connection opened" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=trace msg="starting accesspoint recv loop" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=trace msg="starting dealer recv loop" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=trace msg="received accesspoint ping" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="received connection id: NDAwZjBkYTAtOGFk...REMwN0JGMkQ5MQ==" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=trace msg="received accesspoint pong ack" Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 30 20:22:39 volumio-manu volumio[1179]: info: Getting Spotify volume Dec 30 20:22:39 volumio-manu volumio[1179]: info: Spotify volume: 100 Dec 30 20:22:39 volumio-manu volumio[1179]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 30 20:22:39 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioGetState Dec 30 20:22:39 volumio-manu volumio[1179]: info: Initializing connection to go-librespot Websocket Dec 30 20:22:39 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Dec 30 20:22:39 volumio-manu volumio[1179]: SPOTIFY: SPOTIFY VOLUME 100 Dec 30 20:22:39 volumio-manu volumio[1179]: SPOTIFY: VOLUMIO VOLUME 61 Dec 30 20:22:39 volumio-manu volumio[1179]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 30 20:22:39 volumio-manu volumio[1179]: info: Setting Spotify Volume from Volumio: 61 Dec 30 20:22:39 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:39+01:00" level=debug msg="new websocket client" Dec 30 20:22:39 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket established Dec 30 20:22:40 volumio-manu volumio[1179]: info: Initializing connection to go-librespot Websocket Dec 30 20:22:40 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:40+01:00" level=debug msg="new websocket client" Dec 30 20:22:40 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket established Dec 30 20:22:40 volumio-manu volumio[1179]: info: go-librespot daemon successfully initialized Dec 30 20:22:41 volumio-manu volumio[1179]: SPOTIFY: SETTING SPOTIFY VOLUME 61 Dec 30 20:22:41 volumio-manu volumio[1179]: info: Sending Spotify command with payload to local API: /player/volume Dec 30 20:22:41 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:41+01:00" level=debug msg="update volume requested to 39976/65535" Dec 30 20:22:41 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:41+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 30 20:22:41 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:41+01:00" level=trace msg="emitting websocket event: volume" Dec 30 20:22:41 volumio-manu volumio[1179]: SPOTIFY: received: {"type":"volume","data":{"value":61,"max":100}} Dec 30 20:22:41 volumio-manu volumio[1179]: SPOTIFY: RECEIVED SPOTIFY VOLUME 61 Dec 30 20:22:41 volumio-manu volumio[1179]: SPOTIFY: received: {"type":"volume","data":{"value":61,"max":100}} Dec 30 20:22:41 volumio-manu volumio[1179]: SPOTIFY: RECEIVED SPOTIFY VOLUME 61 Dec 30 20:22:41 volumio-manu volumio[1179]: info: go-librespot daemon successfully initialized Dec 30 20:22:42 volumio-manu volumio[1179]: info: Getting Spotify volume Dec 30 20:22:42 volumio-manu volumio[1179]: info: Spotify volume: 61 Dec 30 20:22:42 volumio-manu volumio[1179]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 30 20:22:43 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioGetState Dec 30 20:22:43 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Dec 30 20:22:43 volumio-manu volumio[1179]: info: Getting Spotify volume Dec 30 20:22:43 volumio-manu volumio[1179]: info: Spotify volume: 61 Dec 30 20:22:43 volumio-manu volumio[1179]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 30 20:22:43 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioGetState Dec 30 20:22:43 volumio-manu volumio[1179]: info: Initializing connection to go-librespot Websocket Dec 30 20:22:43 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Dec 30 20:22:43 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:43+01:00" level=debug msg="new websocket client" Dec 30 20:22:43 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket established Dec 30 20:22:44 volumio-manu volumio[1179]: info: Initializing connection to go-librespot Websocket Dec 30 20:22:44 volumio-manu go-librespot[6947]: time="2025-12-30T20:22:44+01:00" level=debug msg="new websocket client" Dec 30 20:22:44 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket established Dec 30 20:22:46 volumio-manu volumio[1179]: info: Getting Spotify volume Dec 30 20:22:46 volumio-manu volumio[1179]: info: Spotify volume: 61 Dec 30 20:22:46 volumio-manu volumio[1179]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 30 20:22:46 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioGetState Dec 30 20:22:46 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Dec 30 20:22:46 volumio-manu volumio[1179]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 30 20:22:46 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 30 20:22:46 volumio-manu volumio[1179]: info: Creating Spotify config file Dec 30 20:22:46 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 20:22:46 volumio-manu volumio[1179]: info: Spotify config file written Dec 30 20:22:46 volumio-manu sudo[6987]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 20:22:46 volumio-manu sudo[6987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 20:22:46 volumio-manu systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 20:22:46 volumio-manu systemd[1]: go-librespot-daemon.service: Killing process 6948 (go-librespot) with signal SIGKILL. Dec 30 20:22:46 volumio-manu systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 20:22:46 volumio-manu systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:46 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket closed Dec 30 20:22:46 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket closed Dec 30 20:22:46 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket closed Dec 30 20:22:46 volumio-manu volumio[1179]: info: Connection to go-librespot Websocket closed Dec 30 20:22:46 volumio-manu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:46 volumio-manu go-librespot[6989]: go-librespot daemon starting... Dec 30 20:22:46 volumio-manu sudo[6987]: pam_unix(sudo:session): session closed for user root Dec 30 20:22:46 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:46+01:00" level=info msg="running go-librespot 0.4.0" Dec 30 20:22:46 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:46+01:00" level=debug msg="app state loaded" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=info msg="zeroconf server listening on port 35091" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=debug msg="obtained new client token: AADPuU11EOryVtEVRuxJftLgJOXvdtCOhmSbWWig7SL4arOXhpEt2vOp4Sqf1TGfmg9QhSYhDa5lIweucyomdNcKQMB+Rqjfn1NF5EfT+RQXFcKwdKo3iJsWfr9uR+Z1PILiWfgAA8wtthgCkcVoFQws9CmWH0UVlE5118ZltDmxSlNqBiuSrFxQONWWETH4mplZ7YcrHHP8PxD4s/H1Rorldc5Mm/ua/A3UDu6J40StJ3frX6yIcg==" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=debug msg="completed keyexchange" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=debug msg="completed challenge" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=info msg="authenticated AP" username="31************************my" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=info msg="authenticated Login5" username="31************************my" Dec 30 20:22:47 volumio-manu go-librespot[6990]: time="2025-12-30T20:22:47+01:00" level=debug msg="initializing zeroconf session" username="31************************my" Dec 30 20:22:47 volumio-manu volumio[1179]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 30 20:22:47 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 30 20:22:47 volumio-manu volumio[1179]: info: Creating Spotify config file Dec 30 20:22:47 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 20:22:47 volumio-manu volumio[1179]: info: Spotify config file written Dec 30 20:22:47 volumio-manu sudo[7000]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 20:22:47 volumio-manu sudo[7000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 20:22:47 volumio-manu systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 20:22:47 volumio-manu systemd[1]: go-librespot-daemon.service: Killing process 6996 (go-librespot) with signal SIGKILL. Dec 30 20:22:47 volumio-manu systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 20:22:47 volumio-manu systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:47 volumio-manu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:47 volumio-manu go-librespot[7002]: go-librespot daemon starting... Dec 30 20:22:47 volumio-manu sudo[7000]: pam_unix(sudo:session): session closed for user root Dec 30 20:22:47 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:47+01:00" level=info msg="running go-librespot 0.4.0" Dec 30 20:22:47 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:47+01:00" level=debug msg="app state loaded" Dec 30 20:22:47 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:47+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 20:22:47 volumio-manu volumio[1179]: info: Getting Spotify volume Dec 30 20:22:47 volumio-manu volumio[1179]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 30 20:22:47 volumio-manu volumio[1179]: info: CoreCommandRouter::volumioGetState Dec 30 20:22:47 volumio-manu volumio[1179]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Dec 30 20:22:47 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:47+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 30 20:22:47 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:47+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 30 20:22:47 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:47+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 30 20:22:48 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:48+01:00" level=info msg="zeroconf server listening on port 33891" Dec 30 20:22:48 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:48+01:00" level=debug msg="obtained new client token: AAAX5jRhuVw5Efh/Zz7iBiklKZZr7AGcZXZK7DPv0n3tmUN2Whw0GBRp1GldiGl8IRSMOdLFe2/aL9vNXaY6zY3gUnjWM2YfOeoLPXA14I5sKrVgYVLnCanSbjBSDdOcCgfm89uNI1Rso3aNUCOzh/Nh4LCZC2YYmxGyRsTjR1hKt/+8rMuWIs7v98VS5n4k5xVckWcd65ND0mEwULlnQ3voaTUux8mIHU/J64prGgfjtVgxWtkcjg==" Dec 30 20:22:48 volumio-manu go-librespot[7003]: time="2025-12-30T20:22:48+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 30 20:22:48 volumio-manu volumio[1179]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 30 20:22:48 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 30 20:22:48 volumio-manu volumio[1179]: info: Creating Spotify config file Dec 30 20:22:48 volumio-manu volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 20:22:48 volumio-manu volumio[1179]: info: Spotify config file written Dec 30 20:22:48 volumio-manu sudo[7011]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 20:22:48 volumio-manu sudo[7011]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 20:22:48 volumio-manu systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 20:22:48 volumio-manu systemd[1]: go-librespot-daemon.service: Killing process 7004 (go-librespot) with signal SIGKILL. Dec 30 20:22:48 volumio-manu systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 20:22:48 volumio-manu systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:48 volumio-manu volumio[1179]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 20:22:48 volumio-manu volumio[1179]: Error: socket hang up Dec 30 20:22:48 volumio-manu volumio[1179]: at connResetException (node:internal/errors:720:14) Dec 30 20:22:48 volumio-manu volumio[1179]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 30 20:22:48 volumio-manu volumio[1179]: at Socket.emit (node:events:526:35) Dec 30 20:22:48 volumio-manu volumio[1179]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 30 20:22:48 volumio-manu volumio[1179]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 30 20:22:48 volumio-manu volumio[1179]: code: 'ECONNRESET', Dec 30 20:22:48 volumio-manu volumio[1179]: response: undefined Dec 30 20:22:48 volumio-manu volumio[1179]: } Dec 30 20:22:48 volumio-manu volumio[1179]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 20:22:48 volumio-manu systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 20:22:48 volumio-manu go-librespot[7013]: go-librespot daemon starting... Dec 30 20:22:48 volumio-manu sudo[7011]: pam_unix(sudo:session): session closed for user root Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=info msg="running go-librespot 0.4.0" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=debug msg="app state loaded" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=info msg="zeroconf server listening on port 40989" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=debug msg="obtained new client token: AAC83BS0GGQqxTB8lHc7u3u3oqxoM3uReoqm0m4ggTQ2HyTv4qfBkZ/9w4h6j8kF66t7jxhA134C3t6/hnGnVPIY5/BWX3l2HHGIVa2WZSme5ce+eltRV3Xw+fwMtMfI4FHW3aKu/PQ83ztsrldruAvEq2OUItjYUniVGK4M+aVlsBlj7mxP7QgBHP2huWe8KhJAq/tPFTuQLWHmgcXI56oQNFwPKQxr/C/eaAQC4tjP3a8ta1R7KeTd" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=debug msg="completed keyexchange" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=debug msg="completed challenge" Dec 30 20:22:48 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:48+01:00" level=info msg="authenticated AP" username="31************************my" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=info msg="authenticated Login5" username="31************************my" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="initializing zeroconf session" username="31************************my" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="dealer connection opened" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=trace msg="starting accesspoint recv loop" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=trace msg="received accesspoint ping" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=trace msg="starting dealer recv loop" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="received connection id: MjQ1MWNlMzktNGRi...REI4RERFQkNBMg==" Dec 30 20:22:49 volumio-manu sudo[7035]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 20:21' Dec 30 20:22:49 volumio-manu sudo[7035]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=trace msg="received accesspoint pong ack" Dec 30 20:22:49 volumio-manu go-librespot[7020]: time="2025-12-30T20:22:49+01:00" level=debug msg="put connect state because NEW_DEVICE" 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"