-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sat 2024-11-30 11:26:22 CET. -- Nov 30 11:25:00 volumio volumio[850]: info: Enabling MyMusic plugin cd_controller Nov 30 11:25:00 volumio volumio[850]: info: [MyVolumio PluginManager] Enabling and starting plugin music_service cd_controller Nov 30 11:25:00 volumio volumio[850]: info: [MyVolumio PluginManager] Plugin music_service cd_controller not in user plan, not enabling Nov 30 11:25:00 volumio volumio[850]: info: Error: Plugin music_service cd_controller not in user plan, not enabling Nov 30 11:25:00 volumio volumio[850]: error: Could not Enable MyMusic Plugin: Error Nov 30 11:25:00 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:25:01 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 30 11:25:05 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 30 11:25:09 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 30 11:25:10 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:25:10 volumio volumio[850]: info: Listing playlists Nov 30 11:25:10 volumio volumio[850]: info: Listing playlists Nov 30 11:25:11 volumio kernel: hwmon hwmon1: Undervoltage detected! Nov 30 11:25:13 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 30 11:25:15 volumio kernel: hwmon hwmon1: Voltage normalised Nov 30 11:25:20 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:25:25 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Nov 30 11:25:25 volumio volumio[850]: info: CURURI: music-library Nov 30 11:25:25 volumio volumio[850]: error: Failed LSINFO: null Nov 30 11:25:25 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:26 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 30 11:25:26 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 30 11:25:26 volumio volumio[850]: info: Discovery: Getting this device information Nov 30 11:25:26 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:25:26 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 30 11:25:28 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Nov 30 11:25:28 volumio volumio[850]: info: CURURI: albums:// Nov 30 11:25:28 volumio volumio[850]: info: listAlbums - loading Albums from cache Nov 30 11:25:28 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:29 volumio kernel: hwmon hwmon1: Undervoltage detected! Nov 30 11:25:30 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:25:30 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:30 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:25:30 volumio volumio[850]: info: Listing playlists Nov 30 11:25:30 volumio volumio[850]: info: Listing playlists Nov 30 11:25:31 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:25:31 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:32 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:25:32 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:36 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:25:36 volumio kernel: hwmon hwmon1: Voltage normalised Nov 30 11:25:36 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:39 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:39 volumio volumio[850]: info: CoreCommandRouter::volumioReplaceandPlayItems Nov 30 11:25:39 volumio volumio[850]: info: CoreStateMachine::ClearQueue Nov 30 11:25:39 volumio volumio[850]: info: CoreStateMachine::stop Nov 30 11:25:39 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 30 11:25:39 volumio volumio[850]: info: CoreStateMachine::updateTrackBlock Nov 30 11:25:39 volumio volumio[850]: info: CorePlayQueue::getTrackBlock Nov 30 11:25:39 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:25:39 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:39 volumio volumio[850]: info: CorePlayQueue::getTrack 38 Nov 30 11:25:39 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:25:39 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:39 volumio volumio[850]: info: CoreStateMachine::serviceStop Nov 30 11:25:39 volumio volumio[850]: info: CorePlayQueue::getTrack 38 Nov 30 11:25:39 volumio volumio[850]: info: CoreCommandRouter::serviceStop Nov 30 11:25:39 volumio volumio[850]: info: [1732962339823] ControllerUPNPBrowser::stop Nov 30 11:25:39 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand stop Nov 30 11:25:39 volumio volumio[850]: info: CorePlayQueue::clearPlayQueue Nov 30 11:25:39 volumio volumio[850]: info: CorePlayQueue::saveQueue Nov 30 11:25:39 volumio volumio[850]: info: CoreCommandRouter::volumioPushQueue Nov 30 11:25:39 volumio volumio[850]: info: CoreStateMachine::addQueueItems Nov 30 11:25:39 volumio volumio[850]: info: CorePlayQueue::addQueueItems Nov 30 11:25:39 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7210 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7210 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6262 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6262 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7201 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7201 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7197 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7197 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6769 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6769 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6466 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6466 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6478 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6478 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7193 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7193 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6482 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6482 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6621 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6621 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6477 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6477 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6618 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6618 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6638 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6638 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6620 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6620 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6820 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6820 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6766 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6766 Nov 30 11:25:39 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83953 Nov 30 11:25:39 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83953 Nov 30 11:25:39 volumio volumio[850]: info: CoreCommandRouter::volumioPushQueue Nov 30 11:25:39 volumio volumio[850]: info: CorePlayQueue::saveQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::updateTrackBlock Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrackBlock Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPlay Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::play index 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::addQueueItems Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::addQueueItems Nov 30 11:25:40 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83954 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83954 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83955 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83955 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83956 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83956 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83957 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83957 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83958 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83958 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83959 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83959 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83960 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83960 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83961 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83961 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83962 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83962 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83963 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83963 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83964 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83964 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83965 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83965 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83966 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83966 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83967 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83967 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83968 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83968 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83969 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83969 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83970 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83970 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83971 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83971 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83972 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83972 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83973 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83973 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83974 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83974 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83975 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83975 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83976 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83976 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83977 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83977 Nov 30 11:25:40 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83978 Nov 30 11:25:40 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83978 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::stop Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::saveQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::play index undefined Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::updateTrackBlock Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrackBlock Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::startPlaybackTimer Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: info: [1732962340203] ControllerUPNPBrowser::clearAddPlayTrack Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand stop Nov 30 11:25:40 volumio kernel: hwmon hwmon1: Undervoltage detected! Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand stop took 667 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand stop took 287 milliseconds Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand clear Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 40 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand clear took 40 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 38 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 37 milliseconds Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.1.10:50002/m/MP3/82136.mp3" Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 30 11:25:40 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState stateService stop Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus stop Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: No code Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 30 11:25:40 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState stateService stop Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus stop Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: No code Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 77ms Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 76ms Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: error: updateQueue error: null Nov 30 11:25:40 volumio volumio[850]: error: updateQueue error: null Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 52ms Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand playlistinfo took 49 milliseconds Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.1.10:50002/m/MP3/82136.mp3" Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 10ms Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 9ms Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:40 volumio volumio[850]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 97ms Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand add "http://192.168.1.10:50002/m/MP3/82136.mp3" took 15 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService mpd Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand play Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 8ms Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand play took 6 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 4ms Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 3ms Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 24 milliseconds Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 27 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 25 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand playlistinfo took 5 milliseconds Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:40 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus stop Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 51ms Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:25:40 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:25:40 volumio volumio[850]: info: Nov 30 11:25:40 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 16ms Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 15 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand playlistinfo took 12 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand playlistinfo took 12 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 8ms Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 7 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 7ms Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand status took 5 milliseconds Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":354,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:40 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:25:40 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":377,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:40 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:25:40 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 121ms Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 123ms Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand playlistinfo took 100 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand playlistinfo took 99 milliseconds Nov 30 11:25:40 volumio volumio[850]: info: sendMpdCommand playlistinfo took 101 milliseconds Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:40 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:40 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:25:40 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:40 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:25:40 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:40 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:40 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:25:40 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 177ms Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 169ms Nov 30 11:25:40 volumio volumio[850]: info: ------------------------------ 167ms Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:40 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:40 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:40 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::volumioPause Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::pause Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::servicePause Nov 30 11:25:42 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::servicePause Nov 30 11:25:42 volumio volumio[850]: info: [1732962342793] ControllerUPNPBrowser::pause Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand pause Nov 30 11:25:42 volumio volumio[850]: info: Nov 30 11:25:42 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:42 volumio volumio[850]: info: sendMpdCommand pause took 2 milliseconds Nov 30 11:25:42 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:42 volumio volumio[850]: info: Nov 30 11:25:42 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:42 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:42 volumio volumio[850]: info: Nov 30 11:25:42 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:25:42 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:25:42 volumio volumio[850]: info: sendMpdCommand status took 3 milliseconds Nov 30 11:25:42 volumio volumio[850]: info: sendMpdCommand status took 2 milliseconds Nov 30 11:25:42 volumio volumio[850]: info: sendMpdCommand status took 1 milliseconds Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:25:42 volumio volumio[850]: info: sendMpdCommand playlistinfo took 1 milliseconds Nov 30 11:25:42 volumio volumio[850]: info: sendMpdCommand playlistinfo took 1 milliseconds Nov 30 11:25:42 volumio volumio[850]: info: sendMpdCommand playlistinfo took 1 milliseconds Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:42 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:25:42 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:42 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:42 volumio volumio[850]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2982,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:42 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::syncState stateService pause Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus pause Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:25:42 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:42 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:42 volumio volumio[850]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2982,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:42 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::syncState stateService pause Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus pause Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:25:42 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:25:42 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:25:42 volumio volumio[850]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2982,"duration":219,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Sugar","artist":"Robin Schulz Feat. Francesco Yates","album":"Sugar-WEB","uri":"http://192.168.1.10:50002/m/MP3/82136.mp3","trackType":"mp3"} Nov 30 11:25:42 volumio volumio[850]: verbose: CURRENT POSITION 16 Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::syncState stateService pause Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus pause Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:25:42 volumio volumio[850]: info: ------------------------------ 19ms Nov 30 11:25:42 volumio volumio[850]: info: ------------------------------ 18ms Nov 30 11:25:42 volumio volumio[850]: info: ------------------------------ 18ms Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:42 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:42 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:42 volumio volumio[850]: info: CoreCommandRouter::volumioGetQueue Nov 30 11:25:42 volumio volumio[850]: info: CoreStateMachine::getQueue Nov 30 11:25:42 volumio volumio[850]: info: CorePlayQueue::getQueue Nov 30 11:25:42 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:42 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:42 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:25:48 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:25:48 volumio kernel: hwmon hwmon1: Voltage normalised Nov 30 11:25:48 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:50 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:25:50 volumio volumio[850]: info: Listing playlists Nov 30 11:25:50 volumio volumio[850]: info: Listing playlists Nov 30 11:25:50 volumio kernel: hwmon hwmon1: Undervoltage detected! Nov 30 11:25:54 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:25:54 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:54 volumio kernel: hwmon hwmon1: Voltage normalised Nov 30 11:25:56 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:25:56 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 30 11:25:56 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 30 11:25:56 volumio volumio[850]: info: Discovery: Getting this device information Nov 30 11:25:56 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:25:56 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 30 11:25:56 volumio volumio[850]: info: Preload queue cleared Nov 30 11:25:57 volumio kernel: hwmon hwmon1: Undervoltage detected! Nov 30 11:26:00 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:26:00 volumio volumio[850]: info: Preload queue cleared Nov 30 11:26:00 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:26:02 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:26:02 volumio volumio[850]: info: Preload queue cleared Nov 30 11:26:05 volumio kernel: hwmon hwmon1: Voltage normalised Nov 30 11:26:06 volumio volumio[850]: info: Preload queue cleared Nov 30 11:26:06 volumio volumio[850]: info: CoreCommandRouter::volumioReplaceandPlayItems Nov 30 11:26:06 volumio volumio[850]: info: CoreStateMachine::ClearQueue Nov 30 11:26:06 volumio volumio[850]: info: CoreStateMachine::stop Nov 30 11:26:06 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 30 11:26:06 volumio volumio[850]: info: CoreStateMachine::updateTrackBlock Nov 30 11:26:06 volumio volumio[850]: info: CorePlayQueue::getTrackBlock Nov 30 11:26:06 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:26:06 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:06 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:26:06 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:26:06 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:06 volumio volumio[850]: info: CoreStateMachine::serviceStop Nov 30 11:26:06 volumio volumio[850]: info: CorePlayQueue::getTrack 16 Nov 30 11:26:06 volumio volumio[850]: info: CoreCommandRouter::serviceStop Nov 30 11:26:06 volumio volumio[850]: info: [1732962366986] ControllerUPNPBrowser::stop Nov 30 11:26:06 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand stop Nov 30 11:26:06 volumio volumio[850]: info: CorePlayQueue::clearPlayQueue Nov 30 11:26:06 volumio volumio[850]: info: CorePlayQueue::saveQueue Nov 30 11:26:06 volumio volumio[850]: info: CoreCommandRouter::volumioPushQueue Nov 30 11:26:06 volumio volumio[850]: info: CoreStateMachine::addQueueItems Nov 30 11:26:06 volumio volumio[850]: info: CorePlayQueue::addQueueItems Nov 30 11:26:06 volumio volumio[850]: info: Preload queue cleared Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7210 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7210 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6262 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6262 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7201 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7201 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7197 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7197 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6769 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6769 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6466 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6466 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6478 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6478 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7193 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$7193 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6482 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6482 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6621 Nov 30 11:26:06 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6621 Nov 30 11:26:06 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6477 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6477 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6618 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6618 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6638 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6638 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6620 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6620 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6820 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6820 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6766 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/folder/http://192.168.1.10:50001/ContentDirectory/control@22$6766 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83953 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83953 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83954 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83954 Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushQueue Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::saveQueue Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::updateTrackBlock Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrackBlock Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPlay Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::play index 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::addQueueItems Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::addQueueItems Nov 30 11:26:07 volumio volumio[850]: info: Preload queue cleared Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83955 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83955 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83956 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83956 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83957 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83957 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83958 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83958 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83959 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83959 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83960 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83960 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83961 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83961 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83962 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83962 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83963 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83963 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83964 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83964 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83965 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83965 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83966 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83966 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83967 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83967 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83968 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83968 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83969 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83969 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83970 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83970 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83971 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83971 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83972 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83972 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83973 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83973 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83974 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83974 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83975 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83975 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83976 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83976 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83977 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83977 Nov 30 11:26:07 volumio volumio[850]: info: Adding Item to queue: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83978 Nov 30 11:26:07 volumio volumio[850]: info: Using cached record of: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83978 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::stop Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushQueue Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::saveQueue Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::play index undefined Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::updateTrackBlock Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrackBlock Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::startPlaybackTimer Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: info: [1732962367123] ControllerUPNPBrowser::clearAddPlayTrack Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand stop Nov 30 11:26:07 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand stop took 238 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand stop took 103 milliseconds Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand clear Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 17 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand clear took 18 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 16 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 15 milliseconds Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.1.10:50002/m/MP3/76697.mp3" Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 30 11:26:07 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState stateService stop Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus stop Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: No code Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 30 11:26:07 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState stateService stop Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus stop Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: No code Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 37ms Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 37ms Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: error: updateQueue error: null Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 26ms Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand playlistinfo took 24 milliseconds Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:07 volumio volumio[850]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 45ms Nov 30 11:26:07 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:07 volumio volumio[850]: error: updateQueue error: null Nov 30 11:26:07 volumio volumio[850]: error: updateQueue error: null Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.1.10:50002/m/MP3/76697.mp3" Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 29ms Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 29ms Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand add "http://192.168.1.10:50002/m/MP3/76697.mp3" took 12 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::setConsumeUpdateService mpd Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand play Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 6ms Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand play took 5 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 4ms Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 3ms Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 29 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 31 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 31 milliseconds Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces system playlist update Nov 30 11:26:07 volumio volumio[850]: info: Ignoring MPD Status Update Nov 30 11:26:07 volumio volumio[850]: info: Nov 30 11:26:07 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 31ms Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 27 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand playlistinfo took 23 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand playlistinfo took 13 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand playlistinfo took 14 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 12ms Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 10 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 9ms Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand status took 6 milliseconds Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:07 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus stop Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:07 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:26:07 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:07 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:26:07 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 80ms Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 85ms Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 85ms Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand playlistinfo took 27 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand playlistinfo took 23 milliseconds Nov 30 11:26:07 volumio volumio[850]: info: sendMpdCommand playlistinfo took 24 milliseconds Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:07 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:07 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:26:07 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:07 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:26:07 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:07 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:07 volumio volumio[850]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:07 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState stateService play Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus play Nov 30 11:26:07 volumio volumio[850]: info: Received an update from plugin. extracting info from payload Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:07 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 87ms Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 68ms Nov 30 11:26:07 volumio volumio[850]: info: ------------------------------ 65ms Nov 30 11:26:07 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:07 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:07 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:07 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:07 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:07 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:08 volumio volumio[850]: info: CoreCommandRouter::volumioPause Nov 30 11:26:08 volumio volumio[850]: info: CoreStateMachine::pause Nov 30 11:26:08 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:26:08 volumio volumio[850]: info: CoreStateMachine::servicePause Nov 30 11:26:08 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:08 volumio volumio[850]: info: CoreCommandRouter::servicePause Nov 30 11:26:08 volumio volumio[850]: info: [1732962368984] ControllerUPNPBrowser::pause Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand pause Nov 30 11:26:08 volumio volumio[850]: info: Nov 30 11:26:08 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:08 volumio volumio[850]: info: sendMpdCommand pause took 2 milliseconds Nov 30 11:26:08 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:08 volumio volumio[850]: info: Nov 30 11:26:08 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:08 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:08 volumio volumio[850]: info: Nov 30 11:26:08 volumio volumio[850]: ---------------------------- MPD announces state update: player Nov 30 11:26:08 volumio volumio[850]: info: ControllerMpd::getState Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand status Nov 30 11:26:08 volumio volumio[850]: info: sendMpdCommand status took 6 milliseconds Nov 30 11:26:08 volumio volumio[850]: info: sendMpdCommand status took 4 milliseconds Nov 30 11:26:08 volumio volumio[850]: info: sendMpdCommand status took 2 milliseconds Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::parseState Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 30 11:26:08 volumio volumio[850]: info: sendMpdCommand playlistinfo took 3 milliseconds Nov 30 11:26:08 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:09 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:09 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:09 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:09 volumio volumio[850]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2480,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:09 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::syncState stateService pause Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus pause Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:09 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 11:26:09 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:26:09 volumio volumio[850]: info: ------------------------------ 20ms Nov 30 11:26:09 volumio volumio[850]: info: sendMpdCommand playlistinfo took 12 milliseconds Nov 30 11:26:09 volumio volumio[850]: info: sendMpdCommand playlistinfo took 12 milliseconds Nov 30 11:26:09 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:09 volumio volumio[850]: verbose: ControllerMpd::parseTrackInfo Nov 30 11:26:09 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:09 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:09 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:09 volumio volumio[850]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2480,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:09 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::syncState stateService pause Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus pause Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:09 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:26:09 volumio volumio[850]: info: ControllerMpd::pushState Nov 30 11:26:09 volumio volumio[850]: info: CoreCommandRouter::servicePushState Nov 30 11:26:09 volumio volumio[850]: info: CorePlayQueue::getTrack 17 Nov 30 11:26:09 volumio volumio[850]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2480,"duration":3362,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"76697.mp3","artist":null,"album":"(Global-Sets.com)","uri":"http://192.168.1.10:50002/m/MP3/76697.mp3","trackType":"mp3"} Nov 30 11:26:09 volumio volumio[850]: verbose: CURRENT POSITION 17 Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::syncState stateService pause Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::syncState currentStatus pause Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::pushState Nov 30 11:26:09 volumio volumio[850]: info: CoreCommandRouter::volumioPushState Nov 30 11:26:09 volumio volumio[850]: info: CoreStateMachine::stPlaybackTimer Nov 30 11:26:09 volumio volumio[850]: info: ------------------------------ 33ms Nov 30 11:26:09 volumio volumio[850]: info: ------------------------------ 31ms Nov 30 11:26:09 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:09 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:09 volumio volumio[850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 30 11:26:09 volumio kernel: hwmon hwmon1: Undervoltage detected! Nov 30 11:26:10 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:26:10 volumio volumio[850]: info: Listing playlists Nov 30 11:26:10 volumio volumio[850]: info: Listing playlists Nov 30 11:26:13 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:26:13 volumio kernel: hwmon hwmon1: Voltage normalised Nov 30 11:26:13 volumio volumio[850]: info: Preload queue cleared Nov 30 11:26:13 volumio volumio[850]: info: Preloading song: upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83017 Nov 30 11:26:13 volumio volumio[850]: info: Exploding uri upnp/http://192.168.1.10:50001/ContentDirectory/control@22$@83017 in service upnp_browser Nov 30 11:26:15 volumio kernel: hwmon hwmon1: Undervoltage detected! Nov 30 11:26:19 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:26:19 volumio volumio[850]: info: Preload queue cleared Nov 30 11:26:19 volumio kernel: hwmon hwmon1: Voltage normalised Nov 30 11:26:20 volumio volumio[850]: info: CoreCommandRouter::volumioGetState Nov 30 11:26:20 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:26:20 volumio volumio[850]: info: Preload queue cleared Nov 30 11:26:21 volumio volumio[850]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 30 11:26:21 volumio volumio[850]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 30 11:26:21 volumio volumio[850]: TypeError: Cannot read property 'length' of undefined Nov 30 11:26:21 volumio volumio[850]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Nov 30 11:26:21 volumio volumio[850]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Nov 30 11:26:21 volumio volumio[850]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Nov 30 11:26:21 volumio volumio[850]: at Parser.emit (events.js:315:20) Nov 30 11:26:21 volumio volumio[850]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Nov 30 11:26:21 volumio volumio[850]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Nov 30 11:26:21 volumio volumio[850]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Nov 30 11:26:21 volumio volumio[850]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Nov 30 11:26:21 volumio volumio[850]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Nov 30 11:26:21 volumio volumio[850]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Nov 30 11:26:21 volumio volumio[850]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Nov 30 11:26:21 volumio volumio[850]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Nov 30 11:26:21 volumio volumio[850]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Nov 30 11:26:21 volumio volumio[850]: at IncomingMessage.emit (events.js:327:22) Nov 30 11:26:21 volumio volumio[850]: at endReadableNT (internal/streams/readable.js:1327:12) Nov 30 11:26:21 volumio volumio[850]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Nov 30 11:26:21 volumio volumio[850]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 30 11:26:22 volumio sudo[4459]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-30 11:25 Nov 30 11:26:22 volumio sudo[4459]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"