Oct 13 16:55:00 volumiotest volumio[1495]: info: Plugin mpdemulation is not enabled Oct 13 16:55:00 volumiotest volumio[1495]: info: Loading plugin "rest_api"... Oct 13 16:55:00 volumiotest volumio[1495]: info: Loading plugin "websocket"... Oct 13 16:55:00 volumiotest volumio[1495]: info: Starting Socket.io Server version 1.7.4 Oct 13 16:55:00 volumiotest volumio[1495]: info: Loading plugin "rotaryencoder2"... Oct 13 16:55:00 volumiotest sudo[1725]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:00 volumiotest volumio[1745]: Forking 3 albumart workers Oct 13 16:55:01 volumiotest systemd[1]: systemd-fsckd.service: Deactivated successfully. Oct 13 16:55:02 volumiotest dhcpcd[711]: timed out Oct 13 16:55:02 volumiotest sh[701]: timed out Oct 13 16:55:02 volumiotest sh[654]: ifup: failed to bring up eth0 Oct 13 16:55:02 volumiotest systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Oct 13 16:55:02 volumiotest systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Oct 13 16:55:02 volumiotest volumio[1495]: info: Loading i18n strings for locale en Oct 13 16:55:02 volumiotest volumio[1495]: Updating browse sources language Oct 13 16:55:02 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::initPlayerControls Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: Express server listening on port 3000 Oct 13 16:55:03 volumiotest volumio[1495]: [Metrics] WebUI: 12s 372.83ms Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreStateMachine::resetVolumioState Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreStateMachine::getcurrentVolume Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::volumioRetrievevolume Oct 13 16:55:03 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:03 volumiotest volumio[1495]: info: Volumio Network Manager: Network status updated: 2 Oct 13 16:55:04 volumiotest systemd[1]: systemd-hostnamed.service: Deactivated successfully. Oct 13 16:55:04 volumiotest volumio[1495]: verbose: New Socket.io Connection to 192.168.1.80 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/154.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Oct 13 16:55:04 volumiotest volumio[1495]: info: VolumeController:: Volume=86 Mute =false Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:04 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:04 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreCommandRouter::volumioRetrievevolume Oct 13 16:55:04 volumiotest systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Oct 13 16:55:04 volumiotest systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 16:55:04 volumiotest volumio[1495]: info: Reloading queue from file Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:04 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:04 volumiotest systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 16:55:04 volumiotest upmpdcli[1799]: Could not open config: /tmp/upmpdcli.conf Oct 13 16:55:04 volumiotest systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 13 16:55:04 volumiotest systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 13 16:55:04 volumiotest volumio[1495]: verbose: New Socket.io Connection to 192.168.1.80 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/154.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Oct 13 16:55:04 volumiotest volumio[1495]: info: Setting Device type: Raspberry PI Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreStateMachine::setRepeat null single undefined Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:04 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreStateMachine::setRandom true Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:04 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:04 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:05 volumiotest volumio[1495]: verbose: New Socket.io Connection to 192.168.1.80 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/154.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Oct 13 16:55:05 volumiotest volumio[1495]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 13 16:55:05 volumiotest volumio[1495]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115 Oct 13 16:55:05 volumiotest volumio[1495]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 13 16:55:05 volumiotest volumio[1495]: verbose: New Socket.io Connection to 192.168.1.80 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/154.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 Oct 13 16:55:05 volumiotest volumio[1495]: info: VolumeController:: Volume=86 Mute =false Oct 13 16:55:05 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:05 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:05 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:05 volumiotest volumio[1757]: Starting albumart workers Oct 13 16:55:05 volumiotest volumio[1495]: verbose: New Socket.io Connection to 192.168.1.80 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/154.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Oct 13 16:55:05 volumiotest volumio[1495]: verbose: New Socket.io Connection to 192.168.1.80 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/154.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Oct 13 16:55:05 volumiotest volumio[1755]: Starting albumart workers Oct 13 16:55:05 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 13 16:55:05 volumiotest volumio[1495]: info: Completed loading Core Plugins Oct 13 16:55:05 volumiotest volumio[1495]: info: Preparing to generate the ALSA configuration file Oct 13 16:55:05 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:05 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetVisibleSources Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:06 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:06 volumiotest volumio[1756]: Starting albumart workers Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:06 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 13 16:55:06 volumiotest volumio[1495]: info: Received Get System Info Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 16:55:06 volumiotest volumio[1495]: info: Discovery: Getting this device information Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:06 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:06 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:06 volumiotest volumio[1495]: info: Listing playlists Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetQueue Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreStateMachine::getQueue Oct 13 16:55:06 volumiotest volumio[1495]: info: CorePlayQueue::getQueue Oct 13 16:55:06 volumiotest volumio[1495]: info: Discovery: adding e54271c2-1451-4f16-a124-a9ecf722dcf0 Oct 13 16:55:06 volumiotest volumio[1495]: info: Discovery: Found device Volumio_Test Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:06 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:06 volumiotest volumio[1495]: info: Discovery: this is already registered, e54271c2-1451-4f16-a124-a9ecf722dcf0 Oct 13 16:55:06 volumiotest volumio[1495]: info: Discovery: Found device Volumio_Test Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:06 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:06 volumiotest sudo[1833]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 13 16:55:06 volumiotest sudo[1833]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:06 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:06 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:06 volumiotest sudo[1836]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 13 16:55:06 volumiotest sudo[1836]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:07 volumiotest sudo[1836]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:07 volumiotest sudo[1833]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:07 volumiotest volumio[1495]: info: Asound.conf file unchanged, so no further update is needed Oct 13 16:55:07 volumiotest volumio[1495]: info: Output device has changed, restarting MPD Oct 13 16:55:07 volumiotest volumio[1495]: info: Output device has changed, restarting Shairport Sync Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:07 volumiotest sudo[1849]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 13 16:55:07 volumiotest sudo[1849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:07 volumiotest sudo[1847]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 13 16:55:07 volumiotest sudo[1847]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:07 volumiotest sudo[1847]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:07 volumiotest volumio[1495]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 13 16:55:07 volumiotest volumio[1495]: info: ___________ START PLUGINS ___________ Oct 13 16:55:07 volumiotest volumio[1495]: info: ControllerMpd::onStart: Initializing MPD Oct 13 16:55:07 volumiotest volumio[1495]: info: Creating MPD Configuration file Oct 13 16:55:07 volumiotest systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 13 16:55:07 volumiotest systemd[1]: Starting mpd.service - Music Player Daemon... Oct 13 16:55:07 volumiotest sudo[1857]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Oct 13 16:55:07 volumiotest sudo[1857]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 13 16:55:07 volumiotest sudo[1859]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 13 16:55:07 volumiotest sudo[1859]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 13 16:55:07 volumiotest volumio[1495]: info: [1791903307585] CoreMusicLibrary::Adding element Media Servers Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 16:55:07 volumiotest sudo[1865]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 13 16:55:07 volumiotest sudo[1859]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:07 volumiotest sudo[1862]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 13 16:55:07 volumiotest sudo[1862]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:07 volumiotest systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Oct 13 16:55:07 volumiotest sudo[1857]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:07 volumiotest volumio[1495]: info: UPNP Browser: Client initialized successfully Oct 13 16:55:07 volumiotest sudo[1864]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 13 16:55:07 volumiotest sudo[1862]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:07 volumiotest sudo[1864]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:07 volumiotest systemd[1]: mpd.service: Deactivated successfully. Oct 13 16:55:07 volumiotest systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 13 16:55:07 volumiotest systemd[1]: mpd.socket: Deactivated successfully. Oct 13 16:55:07 volumiotest systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 13 16:55:07 volumiotest systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 13 16:55:07 volumiotest systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 13 16:55:07 volumiotest systemd[1]: Starting mpd.service - Music Player Daemon... Oct 13 16:55:07 volumiotest volumio[1495]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:07 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:08 volumiotest volumio[1495]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 13 16:55:08 volumiotest volumio[1495]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 13 16:55:08 volumiotest volumio[1495]: info: [1791903308048] CoreMusicLibrary::Adding element Last_100 Oct 13 16:55:08 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 16:55:08 volumiotest sudo[1880]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 13 16:55:08 volumiotest sudo[1880]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 13 16:55:08 volumiotest sudo[1885]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 13 16:55:08 volumiotest sudo[1880]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:08 volumiotest volumio[1495]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 13 16:55:08 volumiotest volumio[1495]: info: [1791903308067] CoreMusicLibrary::Adding element Webradio Oct 13 16:55:08 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 16:55:08 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 13 16:55:08 volumiotest volumio[1495]: info: Initializing BBC Radios Oct 13 16:55:08 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:08.134+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Oct 13 16:55:08 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 13 16:55:08 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:08 volumiotest volumio[1495]: info: AutoStart - onStart - waiting for system ready state Oct 13 16:55:08 volumiotest volumio[1495]: info: AutoStart - Polling config: interval=5000ms, maxAttempts=60 Oct 13 16:55:08 volumiotest volumio[1495]: info: AutoStart - Maximum wait time: 300 seconds Oct 13 16:55:08 volumiotest volumio[1495]: info: AutoStart - Startup volume disabled Oct 13 16:55:08 volumiotest volumio[1495]: info: AutoStart - Check #1/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:08 volumiotest volumio[1495]: info: GPIOButtonLED: Starting plugin Oct 13 16:55:09 volumiotest volumio[1495]: info: Volumio Calling Home Oct 13 16:55:09 volumiotest sudo[1915]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Oct 13 16:55:09 volumiotest sudo[1915]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:09 volumiotest sudo[1915]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:11 volumiotest volumio-remote-updater[818]: [2026-10-13 16:55:11] [connect] Successful connection Oct 13 16:55:11 volumiotest volumio[1495]: info: MPD Permissions set Oct 13 16:55:11 volumiotest volumio[1495]: info: MPD Permissions set Oct 13 16:55:11 volumiotest volumio[1495]: info: Volumio called home Oct 13 16:55:11 volumiotest sudo[1927]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay rotary-encoder pin_a=22 pin_b=27 relative_axis=true steps-per-period=2 Oct 13 16:55:11 volumiotest sudo[1927]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:11 volumiotest volumio[1495]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Oct 13 16:55:11 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:11 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:12 volumiotest kernel: rotary-encoder rotary@16: gray Oct 13 16:55:12 volumiotest kernel: input: rotary@16 as /devices/platform/rotary@16/input/input4 Oct 13 16:55:12 volumiotest sudo[1927]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:12 volumiotest volumio-remote-updater[818]: [2026-10-13 16:55:12] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1791903311 101 Oct 13 16:55:12 volumiotest volumio[1495]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 8 Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest mpd[1886]: 2026-10-13T16:55:12 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 13 16:55:12 volumiotest systemd[1]: Started mpd.service - Music Player Daemon. Oct 13 16:55:12 volumiotest sudo[1864]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:12 volumiotest sudo[1849]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:12 volumiotest volumio[1495]: info: GPIOButtonLED: dtoverlay already correct Oct 13 16:55:12 volumiotest volumio[1495]: info: GPIOButtonLED: LED+ on GPIO 14 Oct 13 16:55:12 volumiotest volumio[1495]: info: GPIOButtonLED: LED polarity = normal Oct 13 16:55:12 volumiotest volumio[1495]: info: GPIOButtonLED: LED blink slow Oct 13 16:55:12 volumiotest sudo[1961]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 13 16:55:12 volumiotest sudo[1961]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:12 volumiotest volumio[1495]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 8 Oct 13 16:55:12 volumiotest volumio[1495]: info: Received Get System Info Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 16:55:12 volumiotest volumio[1495]: info: Discovery: Getting this device information Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:12 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:12 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 16:55:12 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:12.932+02:00 level=INFO msg="system info for f90fc63a0507ee35e8f63fb50e6021ee" deviceName=Volumio_Test deviceVariant=volumio deviceModel= softwareVersion=4.119 Oct 13 16:55:12 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:12.983+02:00 level=INFO msg="bootstrapping state" hasInternet=true Oct 13 16:55:13 volumiotest volumio[1495]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 13 16:55:13 volumiotest volumio[1495]: info: Received Get System Info Oct 13 16:55:13 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 16:55:13 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 16:55:13 volumiotest volumio[1495]: info: Discovery: Getting this device information Oct 13 16:55:13 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:13 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:13 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 16:55:13 volumiotest volumio[1495]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Oct 13 16:55:13 volumiotest volumio-remote-updater[818]: Test mode disabled Oct 13 16:55:13 volumiotest volumio-remote-updater[818]: Alpha mode disabled Oct 13 16:55:13 volumiotest volumio-remote-updater[818]: Alpha legacy test mode disabled Oct 13 16:55:13 volumiotest volumio[1495]: info: AutoStart - Check #2/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:13 volumiotest volumio[1495]: info: Starting Shairport Sync Oct 13 16:55:13 volumiotest volumio[1495]: info: Starting Shairport Sync Oct 13 16:55:13 volumiotest volumio[1495]: info: Starting Shairport Sync Oct 13 16:55:13 volumiotest sudo[1970]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 13 16:55:13 volumiotest sudo[1970]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:13 volumiotest systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 13 16:55:13 volumiotest systemd[1]: shairport-sync.service: Deactivated successfully. Oct 13 16:55:13 volumiotest systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 13 16:55:13 volumiotest systemd[1]: shairport-sync.service: Consumed 1.259s CPU time. Oct 13 16:55:13 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:13 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:13 volumiotest sudo[1968]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 13 16:55:13 volumiotest sudo[1968]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:13 volumiotest systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 13 16:55:13 volumiotest sudo[1970]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:13 volumiotest systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 13 16:55:13 volumiotest systemd[1]: shairport-sync.service: Deactivated successfully. Oct 13 16:55:13 volumiotest systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 13 16:55:13 volumiotest systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 13 16:55:13 volumiotest sudo[1973]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 13 16:55:13 volumiotest sudo[1973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:13 volumiotest sudo[1968]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:13 volumiotest sudo[1992]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-key gpio=17 active_low=true gpio_pull=up keycode=20 Oct 13 16:55:13 volumiotest sudo[1992]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:13 volumiotest systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 13 16:55:14 volumiotest systemd[1]: shairport-sync.service: Deactivated successfully. Oct 13 16:55:14 volumiotest systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 13 16:55:14 volumiotest volumio[1495]: error: MPD error: The expression evaluated to a falsy value: Oct 13 16:55:14 volumiotest volumio[1495]: assert.ok(self.idling) Oct 13 16:55:14 volumiotest volumio[1495]: error: The expression evaluated to a falsy value: Oct 13 16:55:14 volumiotest volumio[1495]: assert.ok(self.idling) Oct 13 16:55:14 volumiotest kernel: input: button@11 as /devices/platform/button@11/input/input5 Oct 13 16:55:14 volumiotest volumio[1495]: info: MPD running with PID1886 Oct 13 16:55:14 volumiotest volumio[1495]: ,establishing connection Oct 13 16:55:14 volumiotest sudo[1992]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:14 volumiotest systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 13 16:55:14 volumiotest sudo[1973]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:14 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:14 volumiotest volumio[1495]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 13 16:55:14 volumiotest volumio[1495]: info: Shairport-Sync Started Oct 13 16:55:14 volumiotest volumio[1495]: Error adding Membership: Error: addMembership EINVAL Oct 13 16:55:14 volumiotest volumio[1495]: info: Shairport-Sync Started Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 13 16:55:14 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:14.361+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Oct 13 16:55:14 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:14.362+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Oct 13 16:55:14 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:14.362+02:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Oct 13 16:55:14 volumiotest volumio[1495]: info: Shairport-Sync Started Oct 13 16:55:14 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 13 16:55:14 volumiotest volumio[1495]: info: [ROTARYENCODER2] Socket connected to Volumio Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:14 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:14 volumiotest volumio[1495]: info: GPIOButtonLED: Boot complete - LED solid Oct 13 16:55:14 volumiotest volumio[1495]: info: Received Get System Info Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 16:55:14 volumiotest volumio[1495]: info: Discovery: Getting this device information Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:14 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 16:55:14 volumiotest sudo[2020]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Oct 13 16:55:14 volumiotest sudo[2020]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:14 volumiotest sudo[2020]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:14 volumiotest systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 13 16:55:14 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 13 16:55:14 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:14.994+02:00 level=INFO msg="enabling local network discovery" Oct 13 16:55:15 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:15.011+02:00 level=INFO msg="enabling BLE discovery" Oct 13 16:55:15 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:15 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:15 volumiotest volumio[1495]: info: Completed starting Core Plugins Oct 13 16:55:15 volumiotest volumio[1495]: info: ------------------------------------------- Oct 13 16:55:15 volumiotest volumio[1495]: info: ----- MyVolumio plugins startup ---- Oct 13 16:55:15 volumiotest volumio[1495]: info: ------------------------------------------- Oct 13 16:55:15 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 13 16:55:15 volumiotest sudo[2046]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Oct 13 16:55:15 volumiotest sudo[2046]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:15 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:15 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:15 volumiotest sudo[2046]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:15 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:15 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:15 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:15 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:16 volumiotest volumio5-onboarding[1868]: time=2026-10-13T16:55:16.035+02:00 level=INFO msg="service successfully established" component=discovery/localnet Oct 13 16:55:16 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:16 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:16 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:16 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:16 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:16 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:16 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:16 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:16 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:16 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:17 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:17 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:17 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:17 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:17 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:17 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:17 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:17 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:17 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:17 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:18 volumiotest systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 13 16:55:18 volumiotest systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 13 16:55:18 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:18 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:18 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:18 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:18 volumiotest volumio[1495]: info: AutoStart - Check #3/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:18 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:18 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:18 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:18 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:18 volumiotest volumio[1495]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 13 16:55:19 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:19 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:19 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:19 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:19 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:19 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:19 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:19 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:19 volumiotest systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Oct 13 16:55:19 volumiotest systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 16:55:19 volumiotest systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 16:55:19 volumiotest sudo[1961]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:19 volumiotest volumio[1495]: info: Upmpdcli Daemon Started Oct 13 16:55:19 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:19 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:20 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:20 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:20 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:20 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:20 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:20 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:20 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:20 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:21 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:21 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:21 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:21 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:21 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:21 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:21 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:21 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:22 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:22 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:22 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:22 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:22 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:22 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:22 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:22 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:23 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:23 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:23 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:23 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:23 volumiotest volumio[1495]: info: AutoStart - Check #4/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:23 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:23 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 13 16:55:24 volumiotest volumio[1495]: info: Adding plugin bluetooth to MyMusic Plugins Oct 13 16:55:24 volumiotest volumio[1495]: info: Adding plugin multiroom to MyMusic Plugins Oct 13 16:55:24 volumiotest volumio[1495]: info: Adding plugin metavolumio to MyMusic Plugins Oct 13 16:55:24 volumiotest volumio[1495]: info: Adding plugin cd_controller to MyMusic Plugins Oct 13 16:55:24 volumiotest volumio[1495]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 13 16:55:24 volumiotest volumio[1495]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 13 16:55:24 volumiotest volumio[1495]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 13 16:55:24 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 13 16:55:29 volumiotest volumio[1495]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 13 16:55:29 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 13 16:55:29 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:29 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:29 volumiotest volumio[1495]: info: Starting MyVolumio Remote Streaming Endpoints Oct 13 16:55:29 volumiotest volumio[1495]: info: MyVolumio login type: Token Oct 13 16:55:29 volumiotest volumio[1495]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 13 16:55:29 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 13 16:55:31 volumiotest upmpdcli[2215]: writing RSA key Oct 13 16:55:32 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 13 16:55:32 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 13 16:55:32 volumiotest volumio[1495]: info: Streaming services startup Oct 13 16:55:32 volumiotest volumio[1495]: info: Starting Streaming Daemon Oct 13 16:55:32 volumiotest volumio[1495]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 13 16:55:32 volumiotest sudo[2225]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 13 16:55:32 volumiotest sudo[2225]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:32 volumiotest volumio[1495]: info: AutoStart - Check #5/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:32 volumiotest sudo[2225]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:32 volumiotest volumio[1495]: error: Cannot start Volumio Streaming Daemon Oct 13 16:55:32 volumiotest volumio[1495]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 13 16:55:32 volumiotest volumio[1495]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 13 16:55:32 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:32 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:32 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:32 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:33 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:33 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:33 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:33 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:33 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPlay Oct 13 16:55:33 volumiotest volumio[1495]: info: CoreStateMachine::play index undefined Oct 13 16:55:33 volumiotest volumio[1495]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 13 16:55:33 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:33 volumiotest volumio[1495]: info: CoreStateMachine::startPlaybackTimer Oct 13 16:55:33 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:33 volumiotest volumio[1495]: info: [1791903333565] ControllerWebradio::clearAddPlayTrack Oct 13 16:55:33 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand stop Oct 13 16:55:33 volumiotest volumio[1495]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 13 16:55:33 volumiotest volumio[1495]: info: sendMpdCommand stop took 142 milliseconds Oct 13 16:55:33 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand clear Oct 13 16:55:33 volumiotest volumio[1495]: info: Oct 13 16:55:33 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:33 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:33 volumiotest volumio[1495]: info: sendMpdCommand clear took 61 milliseconds Oct 13 16:55:33 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand load "http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com" Oct 13 16:55:33 volumiotest volumio[1495]: info: Oct 13 16:55:33 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:33 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:33 volumiotest volumio[1495]: info: Oct 13 16:55:33 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:33 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:33 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:33 volumiotest volumio[1495]: info: ------------------------------ 66ms Oct 13 16:55:34 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:34 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:34 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand add "http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com" Oct 13 16:55:34 volumiotest volumio[1495]: info: ------------------------------ 489ms Oct 13 16:55:34 volumiotest volumio[1495]: info: ------------------------------ 452ms Oct 13 16:55:34 volumiotest volumio[1495]: info: Oct 13 16:55:34 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:34 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:34 volumiotest volumio[1495]: info: sendMpdCommand add "http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com" took 76 milliseconds Oct 13 16:55:34 volumiotest volumio[1495]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 13 16:55:34 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand play Oct 13 16:55:34 volumiotest volumio[1495]: info: Oct 13 16:55:34 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:34 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:34 volumiotest volumio[1495]: info: Oct 13 16:55:34 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:34 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:34 volumiotest volumio[1495]: info: ------------------------------ 63ms Oct 13 16:55:34 volumiotest volumio[1495]: info: sendMpdCommand play took 49 milliseconds Oct 13 16:55:34 volumiotest volumio[1495]: info: ------------------------------ 48ms Oct 13 16:55:34 volumiotest volumio[1495]: info: ------------------------------ 46ms Oct 13 16:55:34 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:34 volumiotest volumio[1495]: info: MyVolumio token set successfully Oct 13 16:55:34 volumiotest volumio[1495]: info: MYVOLUMIO: Adding device Oct 13 16:55:34 volumiotest volumio[1495]: info: MYVOLUMIO: Evaluating Server Oct 13 16:55:34 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:35 volumiotest volumio[1495]: info: MyVolumio status changed Oct 13 16:55:35 volumiotest volumio[1495]: info: Streaming services startup Oct 13 16:55:35 volumiotest volumio[1495]: info: Starting Streaming Daemon Oct 13 16:55:35 volumiotest volumio[1495]: info: Removing browser output: myVolumio user plan is not superstar Oct 13 16:55:35 volumiotest volumio[1495]: info: Removing audio output: Oct 13 16:55:35 volumiotest volumio[1495]: info: Stoppping Tunnel 1 Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:35 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 6 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 6 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:35 volumiotest sudo[2283]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 13 16:55:35 volumiotest sudo[2281]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 13 16:55:35 volumiotest sudo[2283]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:35 volumiotest sudo[2281]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 16:55:35 volumiotest systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 16:55:35 volumiotest systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:35 volumiotest systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 16:55:35 volumiotest systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 16:55:35 volumiotest systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 16:55:35 volumiotest systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 16:55:35 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 16:55:35 volumiotest systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:35 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest sudo[2283]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:35 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 146 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: ------------------------------ 148ms Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 144 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 141 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 140 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: ------------------------------ 75ms Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 66 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: ------------------------------ 66ms Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 44 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:35 volumiotest sudo[2281]: pam_unix(sudo:session): session closed for user root Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:35 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:35 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":160,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"mp3?aw_0_1st.playerid=tunein.com","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:35 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:35 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:35 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":160,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"mp3?aw_0_1st.playerid=tunein.com","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:35 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:35 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:35 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:35 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:35 volumiotest volumio[1495]: info: ------------------------------ 285ms Oct 13 16:55:35 volumiotest volumio[1495]: info: ------------------------------ 279ms Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:35 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:35 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:35 volumiotest volumio[1495]: info: Oct 13 16:55:35 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:35 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:35 volumiotest volumio[1495]: info: ------------------------------ 229ms Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 188 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 186 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 186 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 172 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 163 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: ------------------------------ 22ms Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 14 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: info: ------------------------------ 13ms Oct 13 16:55:35 volumiotest volumio[1495]: info: sendMpdCommand status took 5 milliseconds Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:35 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:36 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":160,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:36 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:36 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":171,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:36 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:36 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":240,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:36 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:36 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":263,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:36 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:36 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: ------------------------------ 718ms Oct 13 16:55:36 volumiotest volumio[1495]: info: ------------------------------ 717ms Oct 13 16:55:36 volumiotest volumio[1495]: info: ------------------------------ 637ms Oct 13 16:55:36 volumiotest volumio[1495]: info: ------------------------------ 633ms Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:36 volumiotest volumio[1495]: info: Setting Geolocation for MyVolumio to eu7 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:36 volumiotest volumio[1495]: error: Cannot start Volumio Streaming Daemon Oct 13 16:55:36 volumiotest volumio[1495]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 13 16:55:36 volumiotest volumio[1495]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 13 16:55:36 volumiotest volumio[1495]: info: Remote SSH Stopped Oct 13 16:55:36 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 664 milliseconds Oct 13 16:55:36 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 679 milliseconds Oct 13 16:55:36 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 679 milliseconds Oct 13 16:55:36 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:36 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:36 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:36 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":332,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:36 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:36 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":492,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:36 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:36 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":503,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:36 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:36 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: ------------------------------ 1079ms Oct 13 16:55:36 volumiotest volumio[1495]: info: ------------------------------ 948ms Oct 13 16:55:36 volumiotest volumio[1495]: info: ------------------------------ 939ms Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: [1791903336946] ControllerWebradio::seek Oct 13 16:55:36 volumiotest volumio[1495]: info: ControllerMpd::seek Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::stop Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::stPlaybackTimer Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:36 volumiotest volumio[1495]: info: CoreStateMachine::serviceStop Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceStop Oct 13 16:55:37 volumiotest volumio[1495]: info: [1791903337016] ControllerWebradio::stop Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand stop Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:37 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:37 volumiotest volumio[1495]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: error: null Oct 13 16:55:37 volumiotest volumio[1495]: info: Oct 13 16:55:37 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:37 volumiotest volumio[1495]: info: Oct 13 16:55:37 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:37 volumiotest volumio[1495]: info: Updating MyVolumio device info Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:37 volumiotest volumio[1495]: info: Oct 13 16:55:37 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:37 volumiotest volumio[1495]: info: Oct 13 16:55:37 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand stop took 450 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand status took 93 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand status took 71 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:37 volumiotest volumio[1495]: info: Oct 13 16:55:37 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:37 volumiotest volumio[1495]: info: Oct 13 16:55:37 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand status took 12 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand status took 28 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 26 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 25 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand status took 25 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand status took 21 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:37 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService stop Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: No code Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:37 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService stop Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: No code Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: ------------------------------ 305ms Oct 13 16:55:37 volumiotest volumio[1495]: info: ------------------------------ 300ms Oct 13 16:55:37 volumiotest volumio[1495]: info: AutoStart - Check #6/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::play index undefined Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::startPlaybackTimer Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: [1791903337699] ControllerWebradio::clearAddPlayTrack Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand stop Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 204 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 207 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 199 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 198 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: info: sendMpdCommand stop took 6 milliseconds Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:37 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand clear Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Oct 13 16:55:37 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:37 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:37 volumiotest volumio[1495]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Oct 13 16:55:37 volumiotest volumio[1495]: info: ------------------------------ 443ms Oct 13 16:55:37 volumiotest volumio[1495]: info: ------------------------------ 420ms Oct 13 16:55:37 volumiotest volumio[1495]: info: ------------------------------ 455ms Oct 13 16:55:37 volumiotest volumio[1495]: info: ------------------------------ 453ms Oct 13 16:55:37 volumiotest volumio[1495]: info: Oct 13 16:55:37 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:38 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:38 volumiotest volumio[1495]: info: sendMpdCommand clear took 300 milliseconds Oct 13 16:55:38 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand load "http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com" Oct 13 16:55:38 volumiotest volumio[1495]: info: Oct 13 16:55:38 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:38 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:38 volumiotest volumio[1495]: info: Oct 13 16:55:38 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:38 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:38 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:38 volumiotest volumio[1495]: info: ------------------------------ 59ms Oct 13 16:55:38 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:38 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:38 volumiotest volumio[1495]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 13 16:55:38 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 13 16:55:38 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:38 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 13 16:55:38 volumiotest volumio-remote-updater[818]: Test mode disabled Oct 13 16:55:38 volumiotest volumio-remote-updater[818]: Alpha mode disabled Oct 13 16:55:38 volumiotest volumio-remote-updater[818]: Alpha legacy test mode disabled Oct 13 16:55:38 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 13 16:55:38 volumiotest volumio[1495]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 13 16:55:38 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 13 16:55:38 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:38 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:38 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand add "http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com" Oct 13 16:55:38 volumiotest volumio[1495]: info: ------------------------------ 908ms Oct 13 16:55:38 volumiotest volumio[1495]: info: ------------------------------ 907ms Oct 13 16:55:38 volumiotest volumio[1495]: info: Oct 13 16:55:38 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:39 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand add "http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com" took 50 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand play Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:39 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:39 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 37ms Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand play took 11 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 11ms Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 10ms Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:39 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand status took 4 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:39 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:39 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:39 volumiotest volumio[1495]: info: Oct 13 16:55:39 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand status took 17 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand status took 15 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 16ms Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand status took 15 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 14 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 9ms Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand status took 7 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 6ms Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand status took 5 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":57,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"mp3?aw_0_1st.playerid=tunein.com","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:39 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 52ms Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 37 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 43 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 43 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 28 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 26 milliseconds Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:39 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":57,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"mp3?aw_0_1st.playerid=tunein.com","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:39 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:39 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":57,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"mp3?aw_0_1st.playerid=tunein.com","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:39 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:39 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"mp3?aw_0_1st.playerid=tunein.com","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:39 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:39 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"mp3?aw_0_1st.playerid=tunein.com","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:39 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:39 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"mp3?aw_0_1st.playerid=tunein.com","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:39 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:39 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 291ms Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 290ms Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 290ms Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 281ms Oct 13 16:55:39 volumiotest volumio[1495]: info: ------------------------------ 282ms Oct 13 16:55:39 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:40 volumiotest volumio[1495]: info: Oct 13 16:55:40 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:40 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:40 volumiotest volumio[1495]: info: Oct 13 16:55:40 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:40 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:40 volumiotest volumio[1495]: info: Oct 13 16:55:40 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:40 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:40 volumiotest volumio[1495]: info: Oct 13 16:55:40 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:40 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:40 volumiotest volumio[1495]: info: Oct 13 16:55:40 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:40 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:40 volumiotest volumio[1495]: info: Oct 13 16:55:40 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:40 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:40 volumiotest volumio[1495]: info: ------------------------------ 23ms Oct 13 16:55:40 volumiotest volumio[1495]: info: sendMpdCommand status took 38 milliseconds Oct 13 16:55:40 volumiotest volumio[1495]: info: ------------------------------ 37ms Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:40 volumiotest volumio[1495]: info: sendMpdCommand status took 21 milliseconds Oct 13 16:55:40 volumiotest volumio[1495]: info: ------------------------------ 38ms Oct 13 16:55:40 volumiotest volumio[1495]: info: sendMpdCommand status took 37 milliseconds Oct 13 16:55:40 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 19 milliseconds Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:40 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:40 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":675,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:40 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:40 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:40 volumiotest volumio[1495]: info: ------------------------------ 96ms Oct 13 16:55:40 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 59 milliseconds Oct 13 16:55:40 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 60 milliseconds Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:40 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:40 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:40 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":698,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:40 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:40 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:40 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:40 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":721,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:40 volumiotest volumio[1495]: verbose: CURRENT POSITION 0 Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:40 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:40 volumiotest volumio[1495]: info: ------------------------------ 233ms Oct 13 16:55:40 volumiotest volumio[1495]: info: ------------------------------ 257ms Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:40 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:41 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:41 volumiotest volumio[1495]: info: MYVOLUMIO: Adding device Oct 13 16:55:41 volumiotest volumio[1495]: info: MYVOLUMIO: Evaluating Server Oct 13 16:55:41 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:42 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:42 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:42 volumiotest volumio[1495]: info: Setting Geolocation for MyVolumio to eu6 Oct 13 16:55:42 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:42 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:42 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:42 volumiotest volumio[1495]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 13 16:55:42 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:42 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:42 volumiotest volumio[1495]: info: AutoStart - Check #7/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:43 volumiotest volumio[1495]: info: Updating MyVolumio device info Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:43 volumiotest volumio[1495]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:43 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:44 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 13 16:55:44 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:44 volumiotest volumio[1495]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Oct 13 16:55:44 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:44 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:44 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:44 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:45 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:45 volumiotest volumio[1495]: info: [1791903345822] ControllerWebradio::seek Oct 13 16:55:45 volumiotest volumio[1495]: info: ControllerMpd::seek Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:45 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::stop Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::stPlaybackTimer Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:45 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:45 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::serviceStop Oct 13 16:55:45 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 0 Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::serviceStop Oct 13 16:55:45 volumiotest volumio[1495]: info: [1791903345890] ControllerWebradio::stop Oct 13 16:55:45 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand stop Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:45 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:45 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:45 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:46 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:46 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:46 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:46 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:46 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:46 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:46 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:46 volumiotest volumio[1495]: error: null Oct 13 16:55:46 volumiotest volumio[1495]: info: Oct 13 16:55:46 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:46 volumiotest volumio[1495]: info: Oct 13 16:55:46 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand stop took 376 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:46 volumiotest volumio[1495]: info: Oct 13 16:55:46 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:46 volumiotest volumio[1495]: info: Oct 13 16:55:46 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand status took 20 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand status took 20 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand status took 18 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand status took 2 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:46 volumiotest volumio[1495]: info: Oct 13 16:55:46 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:46 volumiotest volumio[1495]: info: Oct 13 16:55:46 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 20 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 20 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 20 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 21 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand status took 19 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand status took 15 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:46 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService stop Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: No code Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:46 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService stop Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: No code Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:46 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService stop Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: No code Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Rolling Stones - Beast of burden","artist":"ROCK ANTENNE 70er Rock","album":null,"uri":"http://stream.rockantenne.de/70er-rock/stream/mp3?aw_0_1st.playerid=tunein.com","trackType":"com"} Oct 13 16:55:46 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService stop Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: No code Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: ------------------------------ 504ms Oct 13 16:55:46 volumiotest volumio[1495]: info: ------------------------------ 504ms Oct 13 16:55:46 volumiotest volumio[1495]: info: ------------------------------ 503ms Oct 13 16:55:46 volumiotest volumio[1495]: info: ------------------------------ 487ms Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::play index undefined Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 2 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::startPlaybackTimer Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 2 Oct 13 16:55:46 volumiotest volumio[1495]: info: [1791903346828] ControllerWebradio::clearAddPlayTrack Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand stop Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 521 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 521 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: info: sendMpdCommand stop took 19 milliseconds Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:46 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand clear Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 2 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 2 Oct 13 16:55:46 volumiotest volumio[1495]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Oct 13 16:55:46 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 2 Oct 13 16:55:46 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:46 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 2 Oct 13 16:55:46 volumiotest volumio[1495]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Oct 13 16:55:46 volumiotest volumio[1495]: info: ------------------------------ 613ms Oct 13 16:55:46 volumiotest volumio[1495]: info: ------------------------------ 610ms Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::updateTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrackBlock Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:47 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:47 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:47 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:47 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:47 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:47 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:47 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreStateMachine::serviceClearAddPlay Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 13 16:55:47 volumiotest volumio[1495]: error: WARNING: No clearAddPlayTracks method for service webradio Oct 13 16:55:47 volumiotest volumio[1495]: info: Oct 13 16:55:47 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:47 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:47 volumiotest volumio[1495]: info: sendMpdCommand clear took 376 milliseconds Oct 13 16:55:47 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand load "https://api.radiorock.sk/stream/hi" Oct 13 16:55:47 volumiotest volumio[1495]: info: Oct 13 16:55:47 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:47 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:47 volumiotest volumio[1495]: info: Oct 13 16:55:47 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:47 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:47 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:47 volumiotest volumio[1495]: info: ------------------------------ 61ms Oct 13 16:55:47 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:47 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:47 volumiotest volumio[1495]: info: AutoStart - Check #8/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:49 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:49 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:49 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 13 16:55:49 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 13 16:55:49 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 13 16:55:49 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetBrowseSources Oct 13 16:55:49 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 13 16:55:50 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:50 volumiotest volumio[1495]: error: updateQueue error: null Oct 13 16:55:50 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand add "https://api.radiorock.sk/stream/hi" Oct 13 16:55:50 volumiotest volumio[1495]: info: ------------------------------ 3121ms Oct 13 16:55:50 volumiotest volumio[1495]: info: ------------------------------ 3121ms Oct 13 16:55:50 volumiotest volumio[1495]: info: Oct 13 16:55:50 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:50 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:50 volumiotest volumio[1495]: info: sendMpdCommand add "https://api.radiorock.sk/stream/hi" took 18 milliseconds Oct 13 16:55:50 volumiotest volumio[1495]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 13 16:55:50 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand play Oct 13 16:55:50 volumiotest volumio[1495]: info: Oct 13 16:55:50 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:50 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:50 volumiotest volumio[1495]: info: Oct 13 16:55:50 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:50 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:50 volumiotest volumio[1495]: info: ------------------------------ 36ms Oct 13 16:55:50 volumiotest volumio[1495]: info: sendMpdCommand play took 19 milliseconds Oct 13 16:55:50 volumiotest volumio[1495]: info: ------------------------------ 20ms Oct 13 16:55:50 volumiotest volumio[1495]: info: ------------------------------ 19ms Oct 13 16:55:50 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:50 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:50 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:50 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:51 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:51 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:51 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:51 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:52 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand status took 2 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:52 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces system playlist update Oct 13 16:55:52 volumiotest volumio[1495]: info: Ignoring MPD Status Update Oct 13 16:55:52 volumiotest volumio[1495]: info: Oct 13 16:55:52 volumiotest volumio[1495]: ---------------------------- MPD announces state update: player Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::getState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand status Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand status took 5 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand status took 55 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 56ms Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand status took 55 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 54 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 54ms Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand status took 53 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 52ms Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand status took 52 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseState Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:52 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":22,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Say You Will - Foreigner","artist":null,"album":null,"uri":"https://api.radiorock.sk/stream/hi","trackType":""} Oct 13 16:55:52 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus stop Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 61ms Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 3 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 3 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 3 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 2 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: info: sendMpdCommand playlistinfo took 2 milliseconds Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:52 volumiotest volumio[1495]: verbose: ControllerMpd::parseTrackInfo Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:52 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":22,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Say You Will - Foreigner","artist":null,"album":null,"uri":"https://api.radiorock.sk/stream/hi","trackType":""} Oct 13 16:55:52 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:52 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:52 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":34,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Say You Will - Foreigner","artist":null,"album":null,"uri":"https://api.radiorock.sk/stream/hi","trackType":""} Oct 13 16:55:52 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:52 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:52 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":34,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Say You Will - Foreigner","artist":null,"album":null,"uri":"https://api.radiorock.sk/stream/hi","trackType":""} Oct 13 16:55:52 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:52 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:52 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":34,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Say You Will - Foreigner","artist":null,"album":null,"uri":"https://api.radiorock.sk/stream/hi","trackType":""} Oct 13 16:55:52 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:52 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: ControllerMpd::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::servicePushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:52 volumiotest volumio[1495]: verbose: STATE SERVICE {"status":"play","position":0,"seek":34,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Say You Will - Foreigner","artist":null,"album":null,"uri":"https://api.radiorock.sk/stream/hi","trackType":""} Oct 13 16:55:52 volumiotest volumio[1495]: verbose: CURRENT POSITION 3 Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState stateService play Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::syncState currentStatus play Oct 13 16:55:52 volumiotest volumio[1495]: info: Received an update from plugin. extracting info from payload Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreStateMachine::pushState Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPushState Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 565ms Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 565ms Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 564ms Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 562ms Oct 13 16:55:52 volumiotest volumio[1495]: info: ------------------------------ 566ms Oct 13 16:55:52 volumiotest volumio[1495]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 13 16:55:52 volumiotest volumio[1495]: info: Completed starting MyVolumio Plugin Oct 13 16:55:52 volumiotest volumio[1495]: [Metrics] CommandRouter: 60s 33.71ms Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::volumiosetStartupVolume Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::Close All Modals sent Oct 13 16:55:52 volumiotest volumio[1495]: info: CoreCommandRouter::Close All Modals sent Oct 13 16:55:52 volumiotest volumio[1495]: info: AutoStart - Check #9/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:53 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:53 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:53 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:53 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:53 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:53 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 13 16:55:53 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 13 16:55:54 volumiotest volumio[1495]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 13 16:55:54 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:54 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:54 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:55 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:55 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:55 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:55 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:55 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:55 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:56 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:56 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:56 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:56 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:57 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:57 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:57 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:57 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:57 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:57 volumiotest volumio[1495]: info: CoreCommandRouter::volumioGetState Oct 13 16:55:58 volumiotest volumio[1495]: info: AutoStart - Check #10/60 - VOLUMIO_SYSTEM_STATUS = starting Oct 13 16:55:58 volumiotest volumio[1495]: info: CoreCommandRouter::volumioPrevious Oct 13 16:55:58 volumiotest volumio[1495]: info: CoreStateMachine::previous Oct 13 16:55:58 volumiotest volumio[1495]: info: CorePlayQueue::getTrack 3 Oct 13 16:55:58 volumiotest volumio[1495]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 13 16:55:58 volumiotest volumio[1495]: TypeError: Cannot read properties of undefined (reading 'service') Oct 13 16:55:58 volumiotest volumio[1495]: at CoreStateMachine.previous (/volumio/app/statemachine.js:1329:97) Oct 13 16:55:58 volumiotest volumio[1495]: at CoreCommandRouter.volumioPrevious (/volumio/app/index.js:97:28) Oct 13 16:55:58 volumiotest volumio[1495]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:270:33) Oct 13 16:55:58 volumiotest volumio[1495]: at Socket.emit (node:events:514:28) Oct 13 16:55:58 volumiotest volumio[1495]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Oct 13 16:55:58 volumiotest volumio[1495]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Oct 13 16:55:58 volumiotest volumio[1495]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 13 16:56:01 volumiotest sudo[2612]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-13 16:55' Oct 13 16:56:01 volumiotest sudo[2612]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"