jul 19 13:41:02 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri jul 19 13:41:02 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:02 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$7 jul 19 13:41:02 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$7 in service upnp_browser jul 19 13:41:04 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri jul 19 13:41:04 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:04 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$0 jul 19 13:41:04 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$1 jul 19 13:41:04 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$2 jul 19 13:41:04 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$3 jul 19 13:41:04 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$4 jul 19 13:41:04 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$5 jul 19 13:41:04 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$6 jul 19 13:41:04 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$7 jul 19 13:41:04 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$0 in service upnp_browser jul 19 13:41:04 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$1 in service upnp_browser jul 19 13:41:04 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$2 in service upnp_browser jul 19 13:41:04 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$3 in service upnp_browser jul 19 13:41:04 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$4 in service upnp_browser jul 19 13:41:04 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$5 in service upnp_browser jul 19 13:41:05 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$6 in service upnp_browser jul 19 13:41:05 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0$7 in service upnp_browser jul 19 13:41:07 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioReplaceandPlayItems jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::ClearQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::stop jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::stPlaybackTimer jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::updateTrackBlock jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrackBlock jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrack 2 jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::serviceStop jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrack 2 jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::serviceStop jul 19 13:41:07 freespirit volumio[1095]: info: [1752925267236] ControllerUPNPBrowser::stop jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::clearPlayQueue jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::saveQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::addQueueItems jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::addQueueItems jul 19 13:41:07 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:07 freespirit volumio[1095]: info: Adding Item to queue: upnp/folder/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0 jul 19 13:41:07 freespirit volumio[1095]: info: Exploding uri upnp/folder/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$D$0 in service upnp_browser jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushQueue jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::saveQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::updateTrackBlock jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrackBlock jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioPlay jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::play index 0 jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::stop jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::play index undefined jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::startPlaybackTimer jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:07 freespirit volumio[1095]: info: [1752925267255] ControllerUPNPBrowser::clearAddPlayTrack jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop jul 19 13:41:07 freespirit volumio[1095]: info: jul 19 13:41:07 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand stop took 19 milliseconds jul 19 13:41:07 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand stop took 0 milliseconds jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand clear jul 19 13:41:07 freespirit volumio[1095]: info: jul 19 13:41:07 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:07 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand status took 3 milliseconds jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand clear took 2 milliseconds jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.0.106:8200/MediaItems/38960.mp3" jul 19 13:41:07 freespirit volumio[1095]: error: updateQueue error: null jul 19 13:41:07 freespirit volumio[1095]: info: ------------------------------ 0ms jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 1 milliseconds jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:07 freespirit volumio[1095]: error: ControllerMpd::pushError: TypeError: Cannot read properties of undefined (reading 'split') jul 19 13:41:07 freespirit volumio[1095]: info: ------------------------------ 4ms jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.0.106:8200/MediaItems/38960.mp3" jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand add "http://192.168.0.106:8200/MediaItems/38960.mp3" took 0 milliseconds jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService mpd jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand play jul 19 13:41:07 freespirit volumio[1095]: info: jul 19 13:41:07 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:07 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand play took 0 milliseconds jul 19 13:41:07 freespirit volumio[1095]: info: ------------------------------ 1ms jul 19 13:41:07 freespirit volumio[1095]: info: jul 19 13:41:07 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:07 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:07 freespirit volumio[1095]: info: jul 19 13:41:07 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand status took 4 milliseconds jul 19 13:41:07 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:07 freespirit volumio[1095]: info: jul 19 13:41:07 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:07 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:07 freespirit volumio[1095]: info: jul 19 13:41:07 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand status took 6 milliseconds jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 7 milliseconds jul 19 13:41:07 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:07 freespirit volumio[1095]: info: ControllerMpd::pushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::servicePushState jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:07 freespirit volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":196,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Белый плащик","artist":"t.A.T.u.","album":"Белый плащик","uri":"http://192.168.0.106:8200/MediaItems/38960.mp3","trackType":"mp3"} jul 19 13:41:07 freespirit volumio[1095]: verbose: CURRENT POSITION 0 jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::syncState stateService play jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::syncState currentStatus stop jul 19 13:41:07 freespirit volumio[1095]: info: ------------------------------ 15ms jul 19 13:41:07 freespirit volumio[1095]: info: ------------------------------ 7ms jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand status took 6 milliseconds jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 6 milliseconds jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:07 freespirit volumio[1095]: info: ControllerMpd::pushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::servicePushState jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:07 freespirit volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":196,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Белый плащик","artist":"t.A.T.u.","album":"Белый плащик","uri":"http://192.168.0.106:8200/MediaItems/38960.mp3","trackType":"mp3"} jul 19 13:41:07 freespirit volumio[1095]: verbose: CURRENT POSITION 0 jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::syncState stateService play jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::syncState currentStatus play jul 19 13:41:07 freespirit volumio[1095]: info: Received an update from plugin. extracting info from payload jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:07 freespirit volumio[1095]: info: ------------------------------ 31ms jul 19 13:41:07 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 19 milliseconds jul 19 13:41:07 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:07 freespirit volumio[1095]: info: ControllerMpd::pushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::servicePushState jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:07 freespirit volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":844,"duration":196,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Белый плащик","artist":"t.A.T.u.","album":"Белый плащик","uri":"http://192.168.0.106:8200/MediaItems/38960.mp3","trackType":"mp3"} jul 19 13:41:07 freespirit volumio[1095]: verbose: CURRENT POSITION 0 jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::syncState stateService play jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::syncState currentStatus play jul 19 13:41:07 freespirit volumio[1095]: info: Received an update from plugin. extracting info from payload jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:07 freespirit volumio[1095]: info: ------------------------------ 45ms jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioGetQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::getQueue jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioGetQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::getQueue jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioGetQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::getQueue jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreCommandRouter::volumioGetQueue jul 19 13:41:07 freespirit volumio[1095]: info: CoreStateMachine::getQueue jul 19 13:41:07 freespirit volumio[1095]: info: CorePlayQueue::getQueue jul 19 13:41:18 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri jul 19 13:41:18 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:18 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$7 jul 19 13:41:18 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$7 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri jul 19 13:41:20 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$0 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$1 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$2 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$3 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$4 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$5 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$6 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$7 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$8 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$9 jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$A jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$B jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$C jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$D jul 19 13:41:20 freespirit volumio[1095]: info: Preloading song: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$E jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$0 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$1 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$2 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$3 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$4 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$5 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$6 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$7 in service upnp_browser jul 19 13:41:20 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$8 in service upnp_browser jul 19 13:41:21 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$9 in service upnp_browser jul 19 13:41:21 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$A in service upnp_browser jul 19 13:41:21 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$B in service upnp_browser jul 19 13:41:21 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$C in service upnp_browser jul 19 13:41:21 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$D in service upnp_browser jul 19 13:41:21 freespirit volumio[1095]: info: Exploding uri upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$E in service upnp_browser jul 19 13:41:22 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioReplaceandPlayItems jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::ClearQueue jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::stop jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::stPlaybackTimer jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::updateTrackBlock jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrackBlock jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::serviceStop jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::serviceStop jul 19 13:41:22 freespirit volumio[1095]: info: [1752925282679] ControllerUPNPBrowser::stop jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::clearPlayQueue jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::saveQueue jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushQueue jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::addQueueItems jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::addQueueItems jul 19 13:41:22 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:22 freespirit volumio[1095]: info: Adding Item to queue: upnp/folder/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0 jul 19 13:41:22 freespirit volumio[1095]: info: Exploding uri upnp/folder/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0 in service upnp_browser jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushQueue jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::saveQueue jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::updateTrackBlock jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrackBlock jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioPlay jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::play index 0 jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::stop jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::play index undefined jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::startPlaybackTimer jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:22 freespirit volumio[1095]: info: [1752925282694] ControllerUPNPBrowser::clearAddPlayTrack jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop jul 19 13:41:22 freespirit volumio[1095]: info: jul 19 13:41:22 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand stop took 17 milliseconds jul 19 13:41:22 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand stop took 2 milliseconds jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand clear jul 19 13:41:22 freespirit volumio[1095]: info: jul 19 13:41:22 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:22 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand status took 1 milliseconds jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand clear took 0 milliseconds jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.0.106:8200/MediaItems/38988.mp3" jul 19 13:41:22 freespirit volumio[1095]: error: updateQueue error: null jul 19 13:41:22 freespirit volumio[1095]: info: ------------------------------ 2ms jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 2 milliseconds jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:22 freespirit volumio[1095]: error: ControllerMpd::pushError: TypeError: Cannot read properties of undefined (reading 'split') jul 19 13:41:22 freespirit volumio[1095]: info: ------------------------------ 3ms jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.0.106:8200/MediaItems/38988.mp3" jul 19 13:41:22 freespirit volumio[1095]: info: jul 19 13:41:22 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:22 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand add "http://192.168.0.106:8200/MediaItems/38988.mp3" took 0 milliseconds jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService mpd jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand play jul 19 13:41:22 freespirit volumio[1095]: info: ------------------------------ 1ms jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand play took 2 milliseconds jul 19 13:41:22 freespirit volumio[1095]: info: jul 19 13:41:22 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:22 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:22 freespirit volumio[1095]: info: jul 19 13:41:22 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand status took 6 milliseconds jul 19 13:41:22 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand status took 3 milliseconds jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 5 milliseconds jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:22 freespirit volumio[1095]: info: ControllerMpd::pushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::servicePushState jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:22 freespirit volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":190,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"38988.mp3","artist":null,"album":null,"uri":"http://192.168.0.106:8200/MediaItems/38988.mp3","trackType":"mp3"} jul 19 13:41:22 freespirit volumio[1095]: verbose: CURRENT POSITION 0 jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::syncState stateService play jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::syncState currentStatus stop jul 19 13:41:22 freespirit volumio[1095]: info: ------------------------------ 22ms jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 8 milliseconds jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:22 freespirit volumio[1095]: info: ControllerMpd::pushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::servicePushState jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:22 freespirit volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":190,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"38988.mp3","artist":null,"album":null,"uri":"http://192.168.0.106:8200/MediaItems/38988.mp3","trackType":"mp3"} jul 19 13:41:22 freespirit volumio[1095]: verbose: CURRENT POSITION 0 jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::syncState stateService play jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::syncState currentStatus play jul 19 13:41:22 freespirit volumio[1095]: info: Received an update from plugin. extracting info from payload jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:22 freespirit volumio[1095]: info: ------------------------------ 26ms jul 19 13:41:22 freespirit volumio[1095]: info: jul 19 13:41:22 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:22 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:22 freespirit volumio[1095]: info: jul 19 13:41:22 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:22 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:22 freespirit volumio[1095]: info: ------------------------------ 5ms jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand status took 9 milliseconds jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:22 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 1 milliseconds jul 19 13:41:22 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:22 freespirit volumio[1095]: info: ControllerMpd::pushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::servicePushState jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:22 freespirit volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":844,"duration":190,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"White Robe","artist":"t.A.T.u.","album":"Waste Management","uri":"http://192.168.0.106:8200/MediaItems/38988.mp3","trackType":"mp3"} jul 19 13:41:22 freespirit volumio[1095]: verbose: CURRENT POSITION 0 jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::syncState stateService play jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::syncState currentStatus play jul 19 13:41:22 freespirit volumio[1095]: info: Received an update from plugin. extracting info from payload jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:22 freespirit volumio[1095]: info: ------------------------------ 17ms jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioGetQueue jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::getQueue jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getQueue jul 19 13:41:22 freespirit volumio[1095]: info: CoreCommandRouter::volumioGetQueue jul 19 13:41:22 freespirit volumio[1095]: info: CoreStateMachine::getQueue jul 19 13:41:22 freespirit volumio[1095]: info: CorePlayQueue::getQueue jul 19 13:41:28 freespirit go-librespot[18318]: time="2025-07-19T13:41:28+02:00" level=trace msg="sent dealer ping" jul 19 13:41:28 freespirit go-librespot[18318]: time="2025-07-19T13:41:28+02:00" level=trace msg="received dealer pong" jul 19 13:41:28 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioReplaceandPlayItems jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::ClearQueue jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::stop jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::stPlaybackTimer jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::updateTrackBlock jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrackBlock jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::serviceStop jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrack 0 jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::serviceStop jul 19 13:41:28 freespirit volumio[1095]: info: [1752925288832] ControllerUPNPBrowser::stop jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::clearPlayQueue jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::saveQueue jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushQueue jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::addQueueItems jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::addQueueItems jul 19 13:41:28 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$0 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$0 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$1 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$1 jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushQueue jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::saveQueue jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::updateTrackBlock jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrackBlock jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioPlay jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::play index 1 jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::addQueueItems jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::addQueueItems jul 19 13:41:28 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$2 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$2 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$3 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$3 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$4 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$4 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$5 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$5 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$6 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$6 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$7 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$7 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$8 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$8 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$9 jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$9 jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$A jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$A jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$B jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$B jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$C jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$C jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$D jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$D jul 19 13:41:28 freespirit volumio[1095]: info: Adding Item to queue: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$E jul 19 13:41:28 freespirit volumio[1095]: info: Using cached record of: upnp/http://192.168.0.106:8200/ctl/ContentDir@64$1$323$F$0$E jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::stop jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushQueue jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::saveQueue jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::play index undefined jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::updateTrackBlock jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrackBlock jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrack 1 jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::startPlaybackTimer jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrack 1 jul 19 13:41:28 freespirit volumio[1095]: info: [1752925288841] ControllerUPNPBrowser::clearAddPlayTrack jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand stop took 16 milliseconds jul 19 13:41:28 freespirit volumio[1095]: info: jul 19 13:41:28 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:28 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand stop took 8 milliseconds jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand clear jul 19 13:41:28 freespirit volumio[1095]: info: jul 19 13:41:28 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:28 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand status took 2 milliseconds jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand clear took 1 milliseconds jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.0.106:8200/MediaItems/38990.mp3" jul 19 13:41:28 freespirit volumio[1095]: error: updateQueue error: null jul 19 13:41:28 freespirit volumio[1095]: info: ------------------------------ 9ms jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 9 milliseconds jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.0.106:8200/MediaItems/38990.mp3" jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:28 freespirit volumio[1095]: error: ControllerMpd::pushError: TypeError: Cannot read properties of undefined (reading 'split') jul 19 13:41:28 freespirit volumio[1095]: info: ------------------------------ 13ms jul 19 13:41:28 freespirit volumio[1095]: info: jul 19 13:41:28 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:28 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand add "http://192.168.0.106:8200/MediaItems/38990.mp3" took 1 milliseconds jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::setConsumeUpdateService mpd jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand play jul 19 13:41:28 freespirit volumio[1095]: info: ------------------------------ 2ms jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand play took 1 milliseconds jul 19 13:41:28 freespirit volumio[1095]: info: jul 19 13:41:28 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:28 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:28 freespirit volumio[1095]: info: jul 19 13:41:28 freespirit volumio[1095]: ---------------------------- MPD announces state update: player jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand status took 20 milliseconds jul 19 13:41:28 freespirit volumio[1095]: info: ControllerMpd::getState jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand status jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:28 freespirit volumio[1095]: info: jul 19 13:41:28 freespirit volumio[1095]: ---------------------------- MPD announces system playlist update jul 19 13:41:28 freespirit volumio[1095]: info: Ignoring MPD Status Update jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand status took 3 milliseconds jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 3 milliseconds jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::parseState jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:28 freespirit volumio[1095]: info: ControllerMpd::pushState jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::servicePushState jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrack 1 jul 19 13:41:28 freespirit volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":268,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"You and I","artist":"t.A.T.u.","album":"Waste Management","uri":"http://192.168.0.106:8200/MediaItems/38990.mp3","trackType":"mp3"} jul 19 13:41:28 freespirit volumio[1095]: verbose: CURRENT POSITION 1 jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::syncState stateService play jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::syncState currentStatus stop jul 19 13:41:28 freespirit volumio[1095]: info: ------------------------------ 25ms jul 19 13:41:28 freespirit volumio[1095]: info: ------------------------------ 1ms jul 19 13:41:28 freespirit volumio[1095]: info: sendMpdCommand playlistinfo took 1 milliseconds jul 19 13:41:28 freespirit volumio[1095]: verbose: ControllerMpd::parseTrackInfo jul 19 13:41:28 freespirit volumio[1095]: info: ControllerMpd::pushState jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::servicePushState jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getTrack 1 jul 19 13:41:28 freespirit volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":844,"duration":268,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"You and I","artist":"t.A.T.u.","album":"Waste Management","uri":"http://192.168.0.106:8200/MediaItems/38990.mp3","trackType":"mp3"} jul 19 13:41:28 freespirit volumio[1095]: verbose: CURRENT POSITION 1 jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::syncState stateService play jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::syncState currentStatus play jul 19 13:41:28 freespirit volumio[1095]: info: Received an update from plugin. extracting info from payload jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::pushState jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioPushState jul 19 13:41:28 freespirit volumio[1095]: info: ------------------------------ 14ms jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioGetQueue jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::getQueue jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getQueue jul 19 13:41:28 freespirit volumio[1095]: info: CoreCommandRouter::volumioGetQueue jul 19 13:41:28 freespirit volumio[1095]: info: CoreStateMachine::getQueue jul 19 13:41:28 freespirit volumio[1095]: info: CorePlayQueue::getQueue jul 19 13:41:57 freespirit systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... jul 19 13:41:57 freespirit dbus-daemon[755]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.118' (uid=0 pid=20144 comm="timedatectl show --property=NTPSynchronized --valu") jul 19 13:41:57 freespirit systemd[1]: Starting systemd-timedated.service - Time & Date Service... jul 19 13:41:57 freespirit dbus-daemon[755]: [system] Successfully activated service 'org.freedesktop.timedate1' jul 19 13:41:57 freespirit systemd[1]: Started systemd-timedated.service - Time & Date Service. jul 19 13:41:57 freespirit setdatetime-helper.sh[20143]: Time is already synchronized. jul 19 13:41:57 freespirit systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. jul 19 13:41:57 freespirit systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. jul 19 13:41:58 freespirit go-librespot[18318]: time="2025-07-19T13:41:58+02:00" level=trace msg="sent dealer ping" jul 19 13:41:58 freespirit go-librespot[18318]: time="2025-07-19T13:41:58+02:00" level=trace msg="received dealer pong" jul 19 13:42:00 freespirit volumio[1095]: Searching plugin music_service/upnp_browser jul 19 13:42:00 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search jul 19 13:42:00 freespirit volumio[1095]: info: All search sources collected, pushing search results jul 19 13:42:01 freespirit volumio[1095]: Searching plugin music_service/upnp_browser jul 19 13:42:01 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search jul 19 13:42:01 freespirit volumio[1095]: info: All search sources collected, pushing search results jul 19 13:42:03 freespirit volumio[1095]: Searching plugin music_service/upnp_browser jul 19 13:42:03 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search jul 19 13:42:03 freespirit volumio[1095]: info: All search sources collected, pushing search results jul 19 13:42:12 freespirit volumio[1095]: Searching plugin music_service/upnp_browser jul 19 13:42:12 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search jul 19 13:42:12 freespirit volumio[1095]: info: All search sources collected, pushing search results jul 19 13:42:27 freespirit systemd[1]: systemd-timedated.service: Deactivated successfully. jul 19 13:42:28 freespirit go-librespot[18318]: time="2025-07-19T13:42:28+02:00" level=trace msg="sent dealer ping" jul 19 13:42:28 freespirit go-librespot[18318]: time="2025-07-19T13:42:28+02:00" level=trace msg="received dealer pong" jul 19 13:42:39 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri jul 19 13:42:39 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:42:41 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri jul 19 13:42:41 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:42:44 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri jul 19 13:42:45 freespirit volumio[1095]: info: Preload queue cleared jul 19 13:42:51 freespirit volumio[1095]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri jul 19 13:42:53 freespirit volumio[1095]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| jul 19 13:42:53 freespirit volumio[1095]: TypeError: Cannot read properties of undefined (reading 'length') jul 19 13:42:53 freespirit volumio[1095]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 jul 19 13:42:53 freespirit volumio[1095]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 jul 19 13:42:53 freespirit volumio[1095]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) jul 19 13:42:53 freespirit volumio[1095]: at Parser.emit (node:events:514:28) jul 19 13:42:53 freespirit volumio[1095]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) jul 19 13:42:53 freespirit volumio[1095]: at emit (/volumio/node_modules/sax/lib/sax.js:625:35) jul 19 13:42:53 freespirit volumio[1095]: at emitNode (/volumio/node_modules/sax/lib/sax.js:630:5) jul 19 13:42:53 freespirit volumio[1095]: at closeTag (/volumio/node_modules/sax/lib/sax.js:890:7) jul 19 13:42:53 freespirit volumio[1095]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1437:13) jul 19 13:42:53 freespirit volumio[1095]: at exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) jul 19 13:42:53 freespirit volumio[1095]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) jul 19 13:42:53 freespirit volumio[1095]: at exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) jul 19 13:42:53 freespirit volumio[1095]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) jul 19 13:42:53 freespirit volumio[1095]: at IncomingMessage.emit (node:events:526:35) jul 19 13:42:53 freespirit volumio[1095]: at endReadableNT (node:internal/streams/readable:1376:12) jul 19 13:42:53 freespirit volumio[1095]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) jul 19 13:42:53 freespirit volumio[1095]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| jul 19 13:42:54 freespirit sudo[20289]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-07-19 13:41' jul 19 13:42:54 freespirit sudo[20289]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="4f980d5cf693b4272997a2fa2da8bb8036ddf1ab" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jul 5 02:28:04 UTC 2025" VOLUMIO_VERSION="4.015" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="fd2f0c5aa414951a829ccaf1ecae9bb1"