Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPause Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::pause Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::stPlaybackTimer Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::servicePause Jan 11 10:49:34 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::servicePause Jan 11 10:49:34 volumiorom volumio[1289]: info: ControllerMpd::pause Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand pause Jan 11 10:49:34 volumiorom volumio[1289]: info: Jan 11 10:49:34 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:34 volumiorom volumio[1289]: info: sendMpdCommand pause took 3 milliseconds Jan 11 10:49:34 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:34 volumiorom volumio[1289]: info: Jan 11 10:49:34 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:34 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:34 volumiorom volumio[1289]: info: Jan 11 10:49:34 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:34 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:34 volumiorom volumio[1289]: info: sendMpdCommand status took 4 milliseconds Jan 11 10:49:34 volumiorom volumio[1289]: info: sendMpdCommand status took 4 milliseconds Jan 11 10:49:34 volumiorom volumio[1289]: info: sendMpdCommand status took 2 milliseconds Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:34 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:49:34 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:49:34 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:34 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:34 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:34 volumiorom volumio[1289]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":61668,"duration":217,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"697 Kbps","isStreaming":false,"title":"Break Away","artist":"Art Garfunkel","album":"Breakaway","uri":"USB/82141C98141C9171/English Flac/Art Garfunkel/Breakaway/03 Break Away.flac","trackType":"flac"} Jan 11 10:49:34 volumiorom volumio[1289]: verbose: CURRENT POSITION 2 Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::syncState stateService pause Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::syncState currentStatus pause Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::stPlaybackTimer Jan 11 10:49:34 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:34 volumiorom volumio[1289]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":61668,"duration":217,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"697 Kbps","isStreaming":false,"title":"Break Away","artist":"Art Garfunkel","album":"Breakaway","uri":"USB/82141C98141C9171/English Flac/Art Garfunkel/Breakaway/03 Break Away.flac","trackType":"flac"} Jan 11 10:49:34 volumiorom volumio[1289]: verbose: CURRENT POSITION 2 Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::syncState stateService pause Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::syncState currentStatus pause Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::stPlaybackTimer Jan 11 10:49:34 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:34 volumiorom volumio[1289]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":61668,"duration":217,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"697 Kbps","isStreaming":false,"title":"Break Away","artist":"Art Garfunkel","album":"Breakaway","uri":"USB/82141C98141C9171/English Flac/Art Garfunkel/Breakaway/03 Break Away.flac","trackType":"flac"} Jan 11 10:49:34 volumiorom volumio[1289]: verbose: CURRENT POSITION 2 Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::syncState stateService pause Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::syncState currentStatus pause Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:34 volumiorom volumio[1289]: info: CoreStateMachine::stPlaybackTimer Jan 11 10:49:34 volumiorom volumio[1289]: info: ------------------------------ 61ms Jan 11 10:49:34 volumiorom volumio[1289]: info: ------------------------------ 59ms Jan 11 10:49:34 volumiorom volumio[1289]: info: ------------------------------ 59ms Jan 11 10:49:34 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:34 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:34 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:44 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: 80s80s , handleBrowseUri Jan 11 10:49:44 volumiorom volumio[1289]: info: [1768128584209] [80s80s] handleBrowseUri curUri: 80s80s Jan 11 10:49:44 volumiorom volumio[1289]: info: Preload queue cleared Jan 11 10:49:45 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: 80s80s , handleBrowseUri Jan 11 10:49:45 volumiorom volumio[1289]: info: [1768128585716] [80s80s] handleBrowseUri curUri: 80s80s/nineties Jan 11 10:49:45 volumiorom volumio[1289]: info: [1768128585717] [80s80s] getRadioContent url: nineties Jan 11 10:49:45 volumiorom volumio[1289]: info: Preload queue cleared Jan 11 10:49:46 volumiorom volumio[1289]: info: Preload queue cleared Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::ClearQueue Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::stop Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::updateTrackBlock Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrackBlock Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::stPlaybackTimer Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::serviceStop Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 2 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::serviceStop Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::stop Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand stop Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::clearPlayQueue Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::saveQueue Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushQueue Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::addQueueItems Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::addQueueItems Jan 11 10:49:46 volumiorom volumio[1289]: info: Preload queue cleared Jan 11 10:49:46 volumiorom volumio[1289]: info: Adding Item to queue: webnineties/2 Jan 11 10:49:46 volumiorom volumio[1289]: info: Exploding uri webnineties/2 in service 80s80s Jan 11 10:49:46 volumiorom volumio[1289]: info: [1768128586681] [80s80s] explodeUri: webnineties/2 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushQueue Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::saveQueue Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::updateTrackBlock Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrackBlock Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPlay Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::play index 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::stop Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::play index undefined Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::startPlaybackTimer Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: [1768128586708] [80s80s] clearAddPlayTrack url: http://streams.90s90s.de/eurodance/mp3-192/volumio Jan 11 10:49:46 volumiorom volumio[1289]: info: [1768128586709] [80s80s] getContentOfUrl started with url http://iris-90s90s.loverad.io/flow.json?station=188&count=2 Jan 11 10:49:46 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand stop took 48 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand status took 6 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand status took 4 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand status took 4 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 4 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 8 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:46 volumiorom volumio[1289]: info: ------------------------------ 66ms Jan 11 10:49:46 volumiorom volumio[1289]: info: ------------------------------ 65ms Jan 11 10:49:46 volumiorom volumio[1289]: info: ------------------------------ 63ms Jan 11 10:49:46 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:46 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:46 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:46 volumiorom volumio[1289]: info: [1768128586947] [80s80s] received new event containing 2 songs. Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand stop Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand stop took 1 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand clear Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:46 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand clear took 1 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand consume 1 Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:46 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:46 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:46 volumiorom volumio[1289]: error: updateQueue error: null Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces state update: options Jan 11 10:49:46 volumiorom volumio[1289]: error: updateQueue error: null Jan 11 10:49:46 volumiorom volumio[1289]: error: updateQueue error: null Jan 11 10:49:46 volumiorom volumio[1289]: info: ------------------------------ 7ms Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand consume 1 took 5 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:46 volumiorom volumio[1289]: info: ------------------------------ 4ms Jan 11 10:49:46 volumiorom volumio[1289]: info: ------------------------------ 4ms Jan 11 10:49:46 volumiorom volumio[1289]: info: [1768128586960] [80s80s] adding url: http://streams.90s90s.de/eurodance/mp3-192/volumio Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand add "http://streams.90s90s.de/eurodance/mp3-192/volumio" Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces state update: options Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces state update: options Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:46 volumiorom volumio[1289]: info: Jan 11 10:49:46 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:46 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand status took 7 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand add "http://streams.90s90s.de/eurodance/mp3-192/volumio" took 5 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand status took 4 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: info: sendMpdCommand status took 3 milliseconds Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand play Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:46 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:46 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:49:46 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:46 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:46 volumiorom volumio[1289]: info: ------------------------------ 39ms Jan 11 10:49:47 volumiorom volumio[1289]: info: ------------------------------ 59ms Jan 11 10:49:47 volumiorom volumio[1289]: info: ------------------------------ 58ms Jan 11 10:49:47 volumiorom volumio[1289]: info: Jan 11 10:49:47 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:47 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:47 volumiorom volumio[1289]: info: Jan 11 10:49:47 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:47 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:47 volumiorom volumio[1289]: info: ------------------------------ 61ms Jan 11 10:49:47 volumiorom volumio[1289]: info: sendMpdCommand play took 50 milliseconds Jan 11 10:49:47 volumiorom volumio[1289]: info: ------------------------------ 4ms Jan 11 10:49:47 volumiorom volumio[1289]: info: ------------------------------ 4ms Jan 11 10:49:47 volumiorom volumio[1289]: info: [1768128587027] [80s80s] Pushing the next song state: 2 Unlimited - Tribal Dance Jan 11 10:49:47 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:47 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:47 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:47 volumiorom volumio[1289]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is4-ssl.mzstatic.com/image/thumb/Music115/v4/52/3c/1a/523c1afe-cf19-b7de-b089-e1f767d647bd/source/600x600bb.jpg","name":"2 Unlimited - Tribal Dance","title":"Tribal Dance","artist":"90s90s Dance","album":"","streaming":true,"disableUiControls":true,"duration":"205","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Jan 11 10:49:47 volumiorom volumio[1289]: verbose: CURRENT POSITION 0 Jan 11 10:49:47 volumiorom volumio[1289]: info: CoreStateMachine::syncState stateService play Jan 11 10:49:47 volumiorom volumio[1289]: info: CoreStateMachine::syncState currentStatus stop Jan 11 10:49:47 volumiorom volumio[1289]: info: [1768128587036] [80s80s] PlayNextTrack API delay: 30 Jan 11 10:49:47 volumiorom volumio[1289]: info: [1768128587062] [80s80s] Setting timer to: 205000 milliseconds. Jan 11 10:49:47 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:47 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:47 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:49:47 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:47 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 1 Jan 11 10:49:47 volumiorom volumio[1289]: info: Jan 11 10:49:47 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 5 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 9 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 9 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 8 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 7 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 5 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 21ms Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 10 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 7 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 5 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 28ms Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 26ms Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 25ms Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 21ms Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 8 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 23ms Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:48 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:48 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:49:48 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:49:48 volumiorom volumio[1289]: info: Jan 11 10:49:48 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 14ms Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 11 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 11ms Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 10 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 9ms Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand status took 7 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 5 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 28ms Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 27ms Jan 11 10:49:48 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 13 milliseconds Jan 11 10:49:48 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:49:48 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:49:48 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:49:48 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:49:48 volumiorom volumio[1289]: info: ------------------------------ 37ms Jan 11 10:49:50 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPlay Jan 11 10:49:50 volumiorom volumio[1289]: info: CoreStateMachine::play index undefined Jan 11 10:49:50 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:49:50 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:06 volumiorom volumio[1289]: info: Jan 11 10:50:06 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:06 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:06 volumiorom volumio[1289]: info: Jan 11 10:50:06 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:06 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:06 volumiorom volumio[1289]: info: Jan 11 10:50:06 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:06 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:06 volumiorom volumio[1289]: info: Jan 11 10:50:06 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:06 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:06 volumiorom volumio[1289]: info: Jan 11 10:50:06 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:06 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:06 volumiorom volumio[1289]: info: Jan 11 10:50:06 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:06 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:06 volumiorom volumio[1289]: info: ------------------------------ 6ms Jan 11 10:50:06 volumiorom volumio[1289]: info: sendMpdCommand status took 6 milliseconds Jan 11 10:50:06 volumiorom volumio[1289]: info: ------------------------------ 5ms Jan 11 10:50:06 volumiorom volumio[1289]: info: sendMpdCommand status took 3 milliseconds Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:06 volumiorom volumio[1289]: info: ------------------------------ 6ms Jan 11 10:50:06 volumiorom volumio[1289]: info: sendMpdCommand status took 5 milliseconds Jan 11 10:50:06 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:50:06 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:06 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:06 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:06 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:06 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:06 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:06 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:06 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:06 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:06 volumiorom volumio[1289]: info: ------------------------------ 14ms Jan 11 10:50:06 volumiorom volumio[1289]: info: ------------------------------ 12ms Jan 11 10:50:06 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 4 milliseconds Jan 11 10:50:06 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:06 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:06 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:06 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:06 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:06 volumiorom volumio[1289]: info: ------------------------------ 12ms Jan 11 10:50:08 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPlay Jan 11 10:50:08 volumiorom volumio[1289]: info: CoreStateMachine::play index undefined Jan 11 10:50:08 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:50:08 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: Preload queue cleared Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::ClearQueue Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::stop Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::stPlaybackTimer Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::updateTrackBlock Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrackBlock Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::serviceStop Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::serviceStop Jan 11 10:50:13 volumiorom volumio[1289]: info: ControllerMpd::stop Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand stop Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::clearPlayQueue Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::saveQueue Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushQueue Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::addQueueItems Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::addQueueItems Jan 11 10:50:13 volumiorom volumio[1289]: info: Preload queue cleared Jan 11 10:50:13 volumiorom volumio[1289]: info: Adding Item to queue: webnineties/0 Jan 11 10:50:13 volumiorom volumio[1289]: info: Exploding uri webnineties/0 in service 80s80s Jan 11 10:50:13 volumiorom volumio[1289]: info: [1768128613560] [80s80s] explodeUri: webnineties/0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushQueue Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::saveQueue Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::updateTrackBlock Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrackBlock Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPlay Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::play index 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::stop Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::play index undefined Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::startPlaybackTimer Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: [1768128613592] [80s80s] clearAddPlayTrack url: http://streams.90s90s.de/pop/mp3-192/volumio Jan 11 10:50:13 volumiorom volumio[1289]: info: [1768128613593] [80s80s] getContentOfUrl started with url http://iris-90s90s.loverad.io/flow.json?station=141&count=2 Jan 11 10:50:13 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand stop took 55 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: verbose: STATE SERVICE {"status":"stop","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is4-ssl.mzstatic.com/image/thumb/Music115/v4/52/3c/1a/523c1afe-cf19-b7de-b089-e1f767d647bd/source/600x600bb.jpg","name":"2 Unlimited - Tribal Dance","title":"Tribal Dance","artist":"90s90s Dance","album":"","streaming":true,"disableUiControls":true,"duration":"205","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Jan 11 10:50:13 volumiorom volumio[1289]: verbose: CURRENT POSITION 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::syncState stateService stop Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::syncState currentStatus stop Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:50:13 volumiorom volumio[1289]: info: No code Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:13 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:13 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:13 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:50:13 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:50:13 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand status took 67 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand status took 25 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand status took 23 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 9 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 9 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 9 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:13 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:13 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:13 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 126ms Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 84ms Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 82ms Jan 11 10:50:13 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:50:13 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:50:13 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:50:13 volumiorom volumio[1289]: info: [1768128613884] [80s80s] received new event containing 2 songs. Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand stop Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand stop took 1 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand clear Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:13 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand clear took 3 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand consume 1 Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:13 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:13 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:13 volumiorom volumio[1289]: error: updateQueue error: null Jan 11 10:50:13 volumiorom volumio[1289]: error: updateQueue error: null Jan 11 10:50:13 volumiorom volumio[1289]: error: updateQueue error: null Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 7ms Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand consume 1 took 5 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 4ms Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 3ms Jan 11 10:50:13 volumiorom volumio[1289]: info: [1768128613898] [80s80s] adding url: http://streams.90s90s.de/pop/mp3-192/volumio Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand add "http://streams.90s90s.de/pop/mp3-192/volumio" Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:13 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand add "http://streams.90s90s.de/pop/mp3-192/volumio" took 1 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand play Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:13 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 12ms Jan 11 10:50:13 volumiorom volumio[1289]: info: Jan 11 10:50:13 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:13 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:13 volumiorom volumio[1289]: info: sendMpdCommand play took 8 milliseconds Jan 11 10:50:13 volumiorom volumio[1289]: info: [1768128613919] [80s80s] Pushing the next song state: Madonna - Rain Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is5-ssl.mzstatic.com/image/thumb/Music115/v4/d4/cb/6e/d4cb6ec4-da95-c5d4-5b41-29c7d281bc9e/source/600x600bb.jpg","name":"Madonna - Rain","title":"Rain","artist":"90s90s Hits","album":"","streaming":true,"disableUiControls":true,"duration":"242","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Jan 11 10:50:13 volumiorom volumio[1289]: verbose: CURRENT POSITION 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::syncState stateService play Jan 11 10:50:13 volumiorom volumio[1289]: info: CoreStateMachine::syncState currentStatus stop Jan 11 10:50:13 volumiorom volumio[1289]: info: [1768128613921] [80s80s] PlayNextTrack API delay: 30 Jan 11 10:50:13 volumiorom volumio[1289]: info: [1768128613926] [80s80s] Setting timer to: 25079 milliseconds. Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 17ms Jan 11 10:50:13 volumiorom volumio[1289]: info: ------------------------------ 16ms Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:13 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 1 Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 5 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 7 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 7 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 4 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 4 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 3 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 15ms Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 5 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 21ms Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 19ms Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 17ms Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 15ms Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 8 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 2 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 12ms Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:14 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:14 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:14 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:14 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 11ms Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 10 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 10ms Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:14 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:14 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:14 volumiorom volumio[1289]: info: Jan 11 10:50:14 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 16 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 12ms Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 10 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 12ms Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 10 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 10 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 9ms Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 7 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 8ms Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand status took 6 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 28ms Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 7 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 5 milliseconds Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:14 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:14 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 35ms Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 29ms Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 29ms Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 24ms Jan 11 10:50:14 volumiorom volumio[1289]: info: ------------------------------ 22ms Jan 11 10:50:21 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPlay Jan 11 10:50:21 volumiorom volumio[1289]: info: CoreStateMachine::play index undefined Jan 11 10:50:21 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:50:21 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:33 volumiorom volumio[1289]: info: Jan 11 10:50:33 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:33 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:33 volumiorom volumio[1289]: info: Jan 11 10:50:33 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:33 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:33 volumiorom volumio[1289]: info: Jan 11 10:50:33 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:33 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:33 volumiorom volumio[1289]: info: Jan 11 10:50:33 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:33 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:33 volumiorom volumio[1289]: info: Jan 11 10:50:33 volumiorom volumio[1289]: ---------------------------- MPD announces system playlist update Jan 11 10:50:33 volumiorom volumio[1289]: info: Ignoring MPD Status Update Jan 11 10:50:33 volumiorom volumio[1289]: info: Jan 11 10:50:33 volumiorom volumio[1289]: ---------------------------- MPD announces state update: player Jan 11 10:50:33 volumiorom volumio[1289]: info: ControllerMpd::getState Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand status Jan 11 10:50:33 volumiorom volumio[1289]: info: ------------------------------ 7ms Jan 11 10:50:33 volumiorom volumio[1289]: info: sendMpdCommand status took 7 milliseconds Jan 11 10:50:33 volumiorom volumio[1289]: info: ------------------------------ 6ms Jan 11 10:50:33 volumiorom volumio[1289]: info: sendMpdCommand status took 5 milliseconds Jan 11 10:50:33 volumiorom volumio[1289]: info: ------------------------------ 5ms Jan 11 10:50:33 volumiorom volumio[1289]: info: sendMpdCommand status took 3 milliseconds Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::parseState Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 10:50:33 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:50:33 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:50:33 volumiorom volumio[1289]: info: sendMpdCommand playlistinfo took 3 milliseconds Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:33 volumiorom volumio[1289]: verbose: ControllerMpd::parseTrackInfo Jan 11 10:50:33 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:33 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:33 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:33 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:33 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:33 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:33 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:33 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:33 volumiorom volumio[1289]: info: ControllerMpd::pushState Jan 11 10:50:33 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:33 volumiorom volumio[1289]: info: CorePlayQueue::getTrack 0 Jan 11 10:50:33 volumiorom volumio[1289]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jan 11 10:50:33 volumiorom volumio[1289]: info: ------------------------------ 14ms Jan 11 10:50:33 volumiorom volumio[1289]: info: ------------------------------ 13ms Jan 11 10:50:33 volumiorom volumio[1289]: info: ------------------------------ 11ms Jan 11 10:50:35 volumiorom go-librespot[1595]: time="2026-01-11T10:50:35Z" level=debug msg="obtained new client token: AAA564AGM7IKmau0HDAXsbHFnBOL3q9WHrvUtcxm7j3+E0Dsyhiu07SSDVuEfdA/87U3HNC4bnbXjW7RysDH8jszhftH0Jn7TbDhWsJcYIHxw9CROzIpIrnwrhaFrfw21H/oDFxbGDRPnROC2qNws24/wNy1n253c9T5GJhyE3m5ighmBN4sJ0swOZ1z3mAit+jMchcohGOiIUNOtbYysHiFFpF9bN/vQLgGa5OZYAzUMO8c/XVxz6LwnV4=" Jan 11 10:50:35 volumiorom go-librespot[1595]: time="2026-01-11T10:50:35Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Jan 11 10:50:35 volumiorom go-librespot[1595]: time="2026-01-11T10:50:35Z" level=debug msg="completed keyexchange" Jan 11 10:50:35 volumiorom go-librespot[1595]: time="2026-01-11T10:50:35Z" level=debug msg="completed challenge" Jan 11 10:50:35 volumiorom go-librespot[1595]: time="2026-01-11T10:50:35Z" level=info msg="authenticated AP" username="cl*********************l6" Jan 11 10:50:35 volumiorom go-librespot[1595]: time="2026-01-11T10:50:35Z" level=info msg="authenticated Login5" username="cl*********************l6" Jan 11 10:50:35 volumiorom go-librespot[1595]: time="2026-01-11T10:50:35Z" level=info msg="accepted zeroconf from ION-PC" username="cl*********************l6" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="dealer connection opened" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="starting accesspoint recv loop" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="starting dealer recv loop" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="received accesspoint ping" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="received connection id: ZDczZWIxMzctOTFk...RjFGNEZENDI0Mg==" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="received accesspoint pong ack" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="put connect state because NEW_DEVICE" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="handling transfer player command from 97998e8761ea706700450dbbdc28d45aca72e10f" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DXcBWIGoYBM5M" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DXcBWIGoYBM5M" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="loading track (paused: false, position: 58077973ms)" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="emitting websocket event: will_play" Jan 11 10:50:37 volumiorom volumio[1289]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1DXcBWIGoYBM5M","uri":"spotify:track:1xOqGUkyxGQRdCvGpvWKmL","play_origin":"playlist"}} Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="selected format OGG_VORBIS_320 (98c9694c183359273aafde2c796aab168e91cd28)" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="requested aes key for file 98c9694c183359273aafde2c796aab168e91cd28, gid: 1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="found 2 cdn urls" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1403" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="fetched first chunk of 16, total size is 8069524 bytes" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="fetched chunk 15/15, size: 205204" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="seek to 197226ms (diff: 279ms, samples: 8697666, bytes: 8058413)" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="created new output device" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed setting stream for spotify:track:1xOqGUkyxGQRdCvGpvWKmL: ALSA error at snd_pcm_open: Device or resource busy" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1147" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="handling pause player command from 97998e8761ea706700450dbbdc28d45aca72e10f" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="pause track at 196947ms" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="sending successful reply for dealer request" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 10:50:37 volumiorom go-librespot[1595]: time="2026-01-11T10:50:37Z" level=trace msg="emitting websocket event: paused" Jan 11 10:50:37 volumiorom volumio[1289]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:37i9dQZF1DXcBWIGoYBM5M","uri":"spotify:track:1xOqGUkyxGQRdCvGpvWKmL","play_origin":"playlist"}} Jan 11 10:50:37 volumiorom volumio[1289]: info: Spotify is playing in volatile mode Jan 11 10:50:37 volumiorom volumio[1289]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 10:50:37 volumiorom volumio[1289]: SPOTIFY: UNSET VOLATILE Jan 11 10:50:37 volumiorom volumio[1289]: SPOTIFY: {"status":"stop","position":0,"title":"90s90s Hits","albumart":"/albumart?sourceicon=music_service/80s80s/images/90s90s-hits-cover.png","uri":"http://streams.90s90s.de/pop/mp3-192/volumio","trackType":"80s80s Radio","seek":0,"duration":1000,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":42,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} Jan 11 10:50:37 volumiorom volumio[1289]: SPOTIFY: PUSH STATE SPOTIFY Jan 11 10:50:37 volumiorom volumio[1289]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 11 10:50:37 volumiorom volumio[1289]: info: CoreCommandRouter::servicePushState Jan 11 10:50:37 volumiorom volumio[1289]: info: CoreStateMachine::pushState Jan 11 10:50:37 volumiorom volumio[1289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 10:50:37 volumiorom volumio[1289]: info: CoreCommandRouter::volumioPushState Jan 11 10:50:37 volumiorom volumio[1289]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jan 11 10:50:39 volumiorom volumio[1289]: info: [1768128639006] [80s80s] Pushing the next song state Madonna - Rain and getting next track. Jan 11 10:50:39 volumiorom volumio[1289]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 10:50:39 volumiorom volumio[1289]: TypeError: Cannot set properties of undefined (setting 'name') Jan 11 10:50:39 volumiorom volumio[1289]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Jan 11 10:50:39 volumiorom volumio[1289]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Jan 11 10:50:39 volumiorom volumio[1289]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Jan 11 10:50:39 volumiorom volumio[1289]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Jan 11 10:50:39 volumiorom volumio[1289]: at process.processImmediate (node:internal/timers:478:21) Jan 11 10:50:39 volumiorom volumio[1289]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 10:50:39 volumiorom go-librespot[1595]: time="2026-01-11T10:50:39Z" level=debug msg="handling resume player command from 97998e8761ea706700450dbbdc28d45aca72e10f" Jan 11 10:50:39 volumiorom go-librespot[1595]: time="2026-01-11T10:50:39Z" level=trace msg="seek to 196947ms (diff: 232ms, samples: 8685362, bytes: 8047149)" uri="spotify:track:1xOqGUkyxGQRdCvGpvWKmL" Jan 11 10:50:39 volumiorom go-librespot[1595]: time="2026-01-11T10:50:39Z" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: Device or resource busy" Jan 11 10:50:39 volumiorom sudo[5603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 10:49' Jan 11 10:50:39 volumiorom sudo[5603]: 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="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"