-- Logs begin at Sun 2024-10-20 20:57:17 CEST, end at Mon 2024-10-21 05:09:29 CEST. -- Oct 21 05:08:01 volumio CRON[27758]: pam_unix(cron:session): session opened for user root by (uid=0) Oct 21 05:08:01 volumio CRON[27759]: (root) CMD (/usr/bin/python3 /home/volumio/measure_temp.py) Oct 21 05:08:01 volumio cron[702]: 2024-10-21 05:08:01 1t2im1-0007Dp-NW Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=118 egid=124 Oct 21 05:08:01 volumio cron[702]: 2024-10-21 05:08:01 1t2im1-0007Dp-NW <= root@volumio U=root P=local S=634 Oct 21 05:08:01 volumio cron[702]: 2024-10-21 05:08:01 1t2im1-0007Dp-NW Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=118 egid=124 Oct 21 05:08:01 volumio cron[702]: exim: could not open panic log - aborting: see message(s) above Oct 21 05:08:01 volumio exim[27765]: 2024-10-21 05:08:01 1t2im1-0007Dp-NW <= root@volumio U=root P=local S=634 Oct 21 05:08:01 volumio exim[27765]: 2024-10-21 05:08:01 1t2im1-0007Dp-NW Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=118 egid=124 Oct 21 05:08:01 volumio exim[27765]: exim: could not open panic log - aborting: see message(s) above Oct 21 05:08:01 volumio CRON[27758]: (root) MAIL (mailed 64 bytes of output but got status 0x0001 from MTA ) Oct 21 05:08:01 volumio CRON[27758]: pam_unix(cron:session): session closed for user root Oct 21 05:08:13 volumio volumio-remote-updater[688]: [2024-10-21 05:08:13] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] Oct 21 05:08:18 volumio volumio-remote-updater[688]: [2024-10-21 05:08:18] [connect] Successful connection Oct 21 05:08:24 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 21 05:08:24 volumio systemd[1]: media-NieuwVolume.mount: Succeeded. Oct 21 05:08:24 volumio ntfs-3g[1500]: Unmounting /dev/sda2 (NieuwVolume) Oct 21 05:08:24 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 21 05:08:24 volumio systemd[1]: Started dynamicswap service. Oct 21 05:08:24 volumio systemd[1]: dynamicswap.service: Succeeded. Oct 21 05:08:24 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 21 05:08:24 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Oct 21 05:08:24 volumio systemd[1]: Started dynamicswap service. Oct 21 05:08:24 volumio systemd[1]: Stopped Volumio Backend Module. Oct 21 05:08:24 volumio systemd[1]: Started Volumio Backend Module. Oct 21 05:08:24 volumio systemd[1]: dynamicswap.service: Succeeded. Oct 21 05:08:26 volumio volumio[27815]: info: ------------------------------------------- Oct 21 05:08:26 volumio volumio[27815]: info: ----- Volumio3 ---- Oct 21 05:08:26 volumio volumio[27815]: info: ------------------------------------------- Oct 21 05:08:26 volumio volumio[27815]: info: ----- System startup ---- Oct 21 05:08:26 volumio volumio[27815]: info: ------------------------------------------- Oct 21 05:08:27 volumio volumio[27815]: info: MYVOLUMIO Environment detected Oct 21 05:08:27 volumio volumio[27815]: info: Plugin folders cleanup Oct 21 05:08:27 volumio volumio[27815]: info: Scanning into folder /volumio/app/plugins/ Oct 21 05:08:27 volumio volumio[27815]: info: Scanning category audio_interface Oct 21 05:08:27 volumio volumio[27815]: info: Scanning category miscellanea Oct 21 05:08:27 volumio volumio[27815]: info: Scanning category music_service Oct 21 05:08:27 volumio volumio[27815]: info: Scanning category plugins.json Oct 21 05:08:27 volumio volumio[27815]: info: Scanning category system_controller Oct 21 05:08:27 volumio volumio[27815]: info: Scanning category user_interface Oct 21 05:08:27 volumio volumio[27815]: info: Scanning into folder /data/plugins/ Oct 21 05:08:27 volumio volumio[27815]: info: Scanning category system_controller Oct 21 05:08:27 volumio volumio[27815]: info: Scanning category user_interface Oct 21 05:08:27 volumio volumio[27815]: info: Plugin folders cleanup completed Oct 21 05:08:27 volumio volumio[27815]: info: ------------------------------------------- Oct 21 05:08:27 volumio volumio[27815]: info: ----- Core plugins startup ---- Oct 21 05:08:27 volumio volumio[27815]: info: ------------------------------------------- Oct 21 05:08:27 volumio volumio[27815]: info: Loading plugins from folder /volumio/app/plugins/ Oct 21 05:08:27 volumio volumio[27815]: info: Adding plugin upnp to MyMusic Plugins Oct 21 05:08:27 volumio volumio[27815]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 21 05:08:27 volumio volumio[27815]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 21 05:08:27 volumio volumio[27815]: info: Loading plugins from folder /data/plugins/ Oct 21 05:08:27 volumio volumio[27815]: info: Loading plugin "system"... Oct 21 05:08:27 volumio volumio[27815]: info: Loading plugin "appearance"... Oct 21 05:08:28 volumio volumio[27815]: info: Loading plugin "network"... Oct 21 05:08:28 volumio volumio[27815]: info: Refreshing Cached IP Addresses Oct 21 05:08:28 volumio sudo[27843]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 21 05:08:28 volumio sudo[27843]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 21 05:08:28 volumio sudo[27843]: pam_unix(sudo:session): session closed for user root Oct 21 05:08:28 volumio sudo[27845]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 21 05:08:28 volumio sudo[27845]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 21 05:08:28 volumio volumio[27815]: info: Loading plugin "services"... Oct 21 05:08:28 volumio sudo[27845]: pam_unix(sudo:session): session closed for user root Oct 21 05:08:28 volumio volumio[27815]: info: Loading plugin "alsa_controller"... Oct 21 05:08:28 volumio sudo[27849]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 21 05:08:28 volumio sudo[27849]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 21 05:08:28 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 21 05:08:28 volumio volumio[27815]: info: Loading plugin "wizard"... Oct 21 05:08:28 volumio volumio[27815]: info: Loading plugin "networkfs"... Oct 21 05:08:28 volumio volumio[27815]: info: Starting Udev Watcher for removable devices Oct 21 05:08:28 volumio volumio[27815]: info: Ignoring mount for partition: boot Oct 21 05:08:28 volumio volumio[27815]: info: Ignoring mount for partition: volumio Oct 21 05:08:28 volumio volumio[27815]: info: Ignoring mount for partition: volumio_data Oct 21 05:08:28 volumio volumio[27815]: error: Cannot associate FS Label, not mounting Oct 21 05:08:28 volumio volumio[27815]: info: Mounting Device NieuwVolume Oct 21 05:08:29 volumio sudo[27858]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda2 /mnt/USB/NieuwVolume -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Oct 21 05:08:29 volumio sudo[27858]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 21 05:08:29 volumio ntfs-3g[27861]: Version 2017.3.23AR.3 integrated FUSE 28 Oct 21 05:08:29 volumio ntfs-3g[27861]: Mounted /dev/sda2 (Read-Write, label "NieuwVolume", NTFS 3.1) Oct 21 05:08:29 volumio ntfs-3g[27861]: Cmdline options: rw,noatime,dmask=0000,fmask=0000,iocharset=utf8 Oct 21 05:08:29 volumio ntfs-3g[27861]: Mount options: iocharset=utf8,allow_other,nonempty,noatime,rw,default_permissions,fsname=/dev/sda2,blkdev,blksize=4096 Oct 21 05:08:29 volumio ntfs-3g[27861]: Global ownership and permissions enforced, configuration type 7 Oct 21 05:08:29 volumio ntfs-3g[27861]: Unmounting /dev/sda2 (NieuwVolume) Oct 21 05:08:29 volumio sudo[27858]: pam_unix(sudo:session): session closed for user root Oct 21 05:08:29 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 21 05:08:29 volumio volumio[27815]: info: Loading plugin "volumio_command_line_client"... Oct 21 05:08:29 volumio volumio[27815]: info: Plugin upnp is not enabled Oct 21 05:08:29 volumio volumio[27815]: info: Loading plugin "my_music"... Oct 21 05:08:29 volumio volumio[27815]: info: Loading plugin "mpd"... Oct 21 05:08:30 volumio volumio[27815]: info: Plugin upnp_browser is not enabled Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "alarm-clock"... Oct 21 05:08:30 volumio volumio[27815]: info: Plugin airplay_emulation is not enabled Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "last_100"... Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "webradio"... Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "i2s_dacs"... Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "volumiodiscovery"... Oct 21 05:08:30 volumio volumio[27815]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 21 05:08:30 volumio volumio[27815]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 21 05:08:30 volumio node[27815]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 21 05:08:30 volumio volumio[27815]: *** WARNING *** For more information see Oct 21 05:08:30 volumio volumio[27815]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 21 05:08:30 volumio volumio[27815]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 21 05:08:30 volumio volumio[27815]: *** WARNING *** For more information see Oct 21 05:08:30 volumio node[27815]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 21 05:08:30 volumio node[27815]: *** WARNING *** For more information see Oct 21 05:08:30 volumio node[27815]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 21 05:08:30 volumio node[27815]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 21 05:08:30 volumio node[27815]: *** WARNING *** For more information see Oct 21 05:08:30 volumio volumio[27815]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 21 05:08:30 volumio volumio[27815]: info: Discovery: Started advertising with name: Volumio Oct 21 05:08:30 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "autostart"... Oct 21 05:08:30 volumio volumio-remote-updater[688]: [2024-10-21 05:08:30] [connect] Successful connection Oct 21 05:08:30 volumio volumio[27815]: info: Applying required configuration parameters for plugin autostart Oct 21 05:08:30 volumio volumio[27815]: info: AutoStart - onVolumioStart - read config.json Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "outputs"... Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "albumart"... Oct 21 05:08:30 volumio volumio[27815]: info: Plugin example_plugin is not enabled Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "inputs"... Oct 21 05:08:30 volumio volumio[27815]: info: Loading plugin "updater_comm"... Oct 21 05:08:31 volumio volumio[27815]: info: Plugin mpdemulation is not enabled Oct 21 05:08:31 volumio volumio[27815]: info: Loading plugin "rest_api"... Oct 21 05:08:31 volumio volumio[27815]: info: Loading plugin "websocket"... Oct 21 05:08:31 volumio volumio[27815]: info: Starting Socket.io Server version 2.3.0 Oct 21 05:08:31 volumio volumio[27815]: info: Loading plugin "lastfm"... Oct 21 05:08:31 volumio volumio[27815]: Forking 3 albumart workers Oct 21 05:08:31 volumio volumio[27815]: Starting albumart workers Oct 21 05:08:31 volumio volumio[27815]: Starting albumart workers Oct 21 05:08:31 volumio volumio[27815]: info: Loading i18n strings for locale nl Oct 21 05:08:31 volumio volumio[27815]: Updating browse sources language Oct 21 05:08:31 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 21 05:08:31 volumio volumio[27815]: Starting albumart workers Oct 21 05:08:32 volumio sudo[27849]: pam_unix(sudo:session): session closed for user root Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::initPlayerControls Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: Express server listening on port 3000 Oct 21 05:08:32 volumio volumio[27815]: [Metrics] WebUI: 6s 374.62ms Oct 21 05:08:32 volumio volumio[27815]: info: CoreStateMachine::resetVolumioState Oct 21 05:08:32 volumio volumio[27815]: info: CoreStateMachine::getcurrentVolume Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioRetrievevolume Oct 21 05:08:32 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:08:32 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:08:32 volumio volumio-remote-updater[688]: [2024-10-21 05:08:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1729480110 101 Oct 21 05:08:32 volumio volumio[27815]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:32 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:32 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:32 volumio volumio[27815]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreStateMachine::setRepeat true single undefined Oct 21 05:08:32 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:08:32 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:08:32 volumio volumio[27815]: info: CoreStateMachine::setRandom true Oct 21 05:08:32 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:08:32 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:08:32 volumio volumio[27815]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 21 05:08:32 volumio volumio[27815]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03111 Oct 21 05:08:32 volumio volumio[27815]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 21 05:08:32 volumio volumio[27815]: info: Setting Device type: Raspberry PI Oct 21 05:08:32 volumio volumio[27815]: info: Completed loading Core Plugins Oct 21 05:08:32 volumio volumio[27815]: info: Preparing to generate the ALSA configuration file Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:32 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:32 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:32 volumio volumio[27815]: info: Asound.conf file unchanged, so no further update is needed Oct 21 05:08:32 volumio volumio[27815]: info: Output device has changed, restarting MPD Oct 21 05:08:32 volumio sudo[27927]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 21 05:08:32 volumio sudo[27927]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 21 05:08:32 volumio volumio[27815]: info: ___________ START PLUGINS ___________ Oct 21 05:08:32 volumio sudo[27927]: pam_unix(sudo:session): session closed for user root Oct 21 05:08:32 volumio volumio[27815]: info: ControllerMpd::onStart: Initializing MPD Oct 21 05:08:32 volumio volumio[27815]: info: Creating MPD Configuration file Oct 21 05:08:32 volumio sudo[27930]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 21 05:08:32 volumio sudo[27930]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 21 05:08:32 volumio sudo[27933]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 21 05:08:32 volumio sudo[27933]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 21 05:08:32 volumio volumio[27815]: info: [1729480112736] CoreMusicLibrary::Adding element Last_100 Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 21 05:08:32 volumio sudo[27933]: pam_unix(sudo:session): session closed for user root Oct 21 05:08:32 volumio volumio[27815]: info: [1729480112743] CoreMusicLibrary::Adding element Webradio Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 21 05:08:32 volumio systemd[1]: Stopping Music Player Daemon... Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 21 05:08:32 volumio sudo[27935]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 21 05:08:32 volumio sudo[27935]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 21 05:08:32 volumio volumio[27815]: info: Initializing BBC Radios Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: AutoStart - onStart Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 21 05:08:32 volumio volumio[27815]: info: [1729480112844] CoreMusicLibrary::Adding element LastFM Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 21 05:08:32 volumio volumio[27815]: Cannot find translation for source LastFM Oct 21 05:08:32 volumio volumio[27815]: info: [LastFM] scrobbler initiated! Oct 21 05:08:32 volumio volumio[27815]: info: [LastFM] extended logging: false Oct 21 05:08:32 volumio volumio[27815]: info: [LastFM] try scrobble stream/radio plays: true Oct 21 05:08:32 volumio volumio[27815]: info: [LastFM] Left init routine Oct 21 05:08:32 volumio volumio[27815]: info: [LastFM] Socket already connected: true Oct 21 05:08:32 volumio volumio[27815]: info: Volumio Calling Home Oct 21 05:08:32 volumio volumio[27815]: info: MPD Permissions set Oct 21 05:08:32 volumio volumio[27815]: info: MPD Permissions set Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:32 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:33 volumio volumio[27815]: info: Reloading queue from file Oct 21 05:08:34 volumio systemd[1]: mpd.service: Succeeded. Oct 21 05:08:34 volumio systemd[1]: Stopped Music Player Daemon. Oct 21 05:08:34 volumio systemd[1]: Starting Music Player Daemon... Oct 21 05:08:35 volumio systemd[1]: Started Music Player Daemon. Oct 21 05:08:35 volumio sudo[27930]: pam_unix(sudo:session): session closed for user root Oct 21 05:08:35 volumio sudo[27935]: pam_unix(sudo:session): session closed for user root Oct 21 05:08:35 volumio volumio[27815]: info: Completed starting Core Plugins Oct 21 05:08:35 volumio volumio[27815]: info: ------------------------------------------- Oct 21 05:08:35 volumio volumio[27815]: info: ----- MyVolumio plugins startup ---- Oct 21 05:08:35 volumio volumio[27815]: info: ------------------------------------------- Oct 21 05:08:35 volumio volumio[27815]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 21 05:08:36 volumio volumio[27815]: error: MPD error: The expression evaluated to a falsy value: Oct 21 05:08:36 volumio volumio[27815]: assert.ok(self.idling) Oct 21 05:08:36 volumio volumio[27815]: error: The expression evaluated to a falsy value: Oct 21 05:08:36 volumio volumio[27815]: assert.ok(self.idling) Oct 21 05:08:36 volumio volumio[27815]: info: MPD running with PID27959 Oct 21 05:08:36 volumio volumio[27815]: ,establishing connection Oct 21 05:08:36 volumio volumio[27815]: error: updateQueue error: null Oct 21 05:08:36 volumio volumio[27815]: error: updateQueue error: null Oct 21 05:08:37 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:37 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:37 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:37 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:37 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:37 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:37 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:37 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:41 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand update Oct 21 05:08:41 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:41 volumio volumio[27815]: info: Oct 21 05:08:41 volumio volumio[27815]: ---------------------------- MPD announces state update: update Oct 21 05:08:41 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:08:41 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:41 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:41 volumio volumio[27815]: info: Oct 21 05:08:41 volumio volumio[27815]: ---------------------------- MPD announces state update: update Oct 21 05:08:41 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:08:41 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:42 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:42 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:42 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:42 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:42 volumio volumio[27815]: info: MPD Database updated - AlbumList cache refreshed Oct 21 05:08:42 volumio volumio[27815]: info: Oct 21 05:08:42 volumio volumio[27815]: ---------------------------- MPD announces state update: database Oct 21 05:08:42 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:42 volumio volumio[27815]: info: Oct 21 05:08:42 volumio volumio[27815]: ---------------------------- MPD announces state update: update Oct 21 05:08:42 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:08:42 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:42 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:08:42 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:42 volumio volumio[27815]: info: MPD Database updated - AlbumList cache refreshed Oct 21 05:08:42 volumio volumio[27815]: info: Oct 21 05:08:42 volumio volumio[27815]: ---------------------------- MPD announces state update: database Oct 21 05:08:42 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:42 volumio volumio[27815]: info: Oct 21 05:08:42 volumio volumio[27815]: ---------------------------- MPD announces state update: update Oct 21 05:08:42 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:08:42 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:42 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:08:42 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:08:48 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:48 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:48 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:48 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:52 volumio volumio[27815]: info: AutoStart - Plugin is starting Oct 21 05:08:52 volumio volumio[27815]: info: CoreCommandRouter::volumioGetQueue Oct 21 05:08:52 volumio volumio[27815]: info: CoreStateMachine::getQueue Oct 21 05:08:52 volumio volumio[27815]: info: CorePlayQueue::getQueue Oct 21 05:08:52 volumio volumio[27815]: info: AutoStart - start playing Oct 21 05:08:52 volumio volumio[27815]: info: AutoStart - start playing with no specific position Oct 21 05:08:52 volumio volumio[27815]: info: CoreCommandRouter::volumioPlay Oct 21 05:08:52 volumio volumio[27815]: info: CoreStateMachine::play index 0 Oct 21 05:08:52 volumio volumio[27815]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 21 05:08:52 volumio volumio[27815]: info: CoreStateMachine::stop Oct 21 05:08:52 volumio volumio[27815]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 21 05:08:52 volumio volumio[27815]: info: CoreStateMachine::play index undefined Oct 21 05:08:52 volumio volumio[27815]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 21 05:08:52 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:52 volumio volumio[27815]: info: CoreStateMachine::startPlaybackTimer Oct 21 05:08:52 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:52 volumio volumio[27815]: verbose: ControllerMpd::clearAddPlayTracks USB/NieuwVolume/Radio server/ALBUMS/- Classic/1994 - Giacomo Puccini - Famous Arias/Giacomo Puccini - Che Gelida Manina.mp3 Oct 21 05:08:52 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand stop Oct 21 05:08:54 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:54 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:54 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:08:54 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:08:56 volumio volumio[27815]: error: MyVolumio Plugin failed to start in a timely fashion Oct 21 05:08:56 volumio volumio[27815]: info: BOOT COMPLETED Oct 21 05:08:56 volumio volumio[27815]: [Metrics] CommandRouter: 29s 680.09ms Oct 21 05:08:56 volumio volumio[27815]: info: CoreCommandRouter::volumiosetStartupVolume Oct 21 05:08:56 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 21 05:08:56 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 21 05:08:56 volumio volumio[27815]: info: CoreCommandRouter::Close All Modals sent Oct 21 05:08:56 volumio volumio[27815]: info: CoreCommandRouter::Close All Modals sent Oct 21 05:08:56 volumio kernel: bcm2835-i2s fe203000.i2s: I2S SYNC error! Oct 21 05:08:57 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 21 05:08:57 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 21 05:08:57 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:09:01 volumio volumio[27815]: info: Oct 21 05:09:01 volumio volumio[27815]: ---------------------------- MPD announces state update: update Oct 21 05:09:01 volumio volumio[27815]: info: MPD Database updated - AlbumList cache refreshed Oct 21 05:09:01 volumio volumio[27815]: info: Oct 21 05:09:01 volumio volumio[27815]: ---------------------------- MPD announces state update: database Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:09:01 volumio volumio[27815]: info: Oct 21 05:09:01 volumio volumio[27815]: ---------------------------- MPD announces state update: update Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand update took 19452 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 19372 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::getState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand status Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 19372 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 19371 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 19369 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 18489 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 18489 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 18488 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 18487 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 18486 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 18485 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand stop took 8302 milliseconds Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: info: Command Router : Notfying DB Updatefalse Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::Close All Modals sent Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: info: Command Router : Notfying DB Updatefalse Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::Close All Modals sent Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: info: Command Router : Notfying DB Updatefalse Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::Close All Modals sent Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: info: Command Router : Notfying DB Updatefalse Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::Close All Modals sent Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand clear Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 19624ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 19621ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 18741ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 18742ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 18742ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 18743ms Oct 21 05:09:01 volumio volumio[27815]: info: Oct 21 05:09:01 volumio volumio[27815]: ---------------------------- MPD announces system playlist update Oct 21 05:09:01 volumio volumio[27815]: info: Ignoring MPD Status Update Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 295 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 291 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 285 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 284 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand status took 283 milliseconds Oct 21 05:09:01 volumio volumio[27815]: info: sendMpdCommand clear took 96 milliseconds Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: info: Command Router : Notfying DB Updatefalse Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::Close All Modals sent Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: info: Command Router : Notfying DB Updatefalse Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::Close All Modals sent Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::parseState Oct 21 05:09:01 volumio volumio[27815]: verbose: ControllerMpd::sendMpdCommand add "USB/NieuwVolume/Radio server/ALBUMS/- Classic/1994 - Giacomo Puccini - Famous Arias/Giacomo Puccini - Che Gelida Manina.mp3" Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ControllerMpd::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::servicePushState Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 21 05:09:01 volumio volumio[27815]: verbose: CURRENT POSITION 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState stateService stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::syncState currentStatus stop Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: No code Oct 21 05:09:01 volumio volumio[27815]: info: CoreStateMachine::pushState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioPushState Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 415ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 413ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 413ms Oct 21 05:09:01 volumio volumio[27815]: info: Oct 21 05:09:01 volumio volumio[27815]: ---------------------------- MPD announces system playlist update Oct 21 05:09:01 volumio volumio[27815]: info: Ignoring MPD Status Update Oct 21 05:09:01 volumio volumio[27815]: info: Oct 21 05:09:01 volumio volumio[27815]: ---------------------------- MPD announces system playlist update Oct 21 05:09:01 volumio volumio[27815]: info: Ignoring MPD Status Update Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:01 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:01 volumio volumio[27815]: error: updateQueue error: null Oct 21 05:09:01 volumio volumio[27815]: error: updateQueue error: null Oct 21 05:09:01 volumio volumio[27815]: error: updateQueue error: null Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 176ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 22ms Oct 21 05:09:01 volumio volumio[27815]: info: ------------------------------ 21ms Oct 21 05:09:01 volumio CRON[27982]: pam_unix(cron:session): session opened for user root by (uid=0) Oct 21 05:09:01 volumio CRON[27983]: (root) CMD (/usr/bin/python3 /home/volumio/measure_temp.py) Oct 21 05:09:02 volumio cron[702]: 2024-10-21 05:09:02 1t2in0-0007HR-1M Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=118 egid=124 Oct 21 05:09:02 volumio cron[702]: 2024-10-21 05:09:02 1t2in0-0007HR-1M <= root@volumio U=root P=local S=633 Oct 21 05:09:02 volumio cron[702]: 2024-10-21 05:09:02 1t2in0-0007HR-1M Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=118 egid=124 Oct 21 05:09:02 volumio cron[702]: exim: could not open panic log - aborting: see message(s) above Oct 21 05:09:02 volumio exim[27989]: 2024-10-21 05:09:02 1t2in0-0007HR-1M <= root@volumio U=root P=local S=633 Oct 21 05:09:02 volumio exim[27989]: 2024-10-21 05:09:02 1t2in0-0007HR-1M Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=118 egid=124 Oct 21 05:09:02 volumio exim[27989]: exim: could not open panic log - aborting: see message(s) above Oct 21 05:09:02 volumio CRON[27982]: (root) MAIL (mailed 63 bytes of output but got status 0x0001 from MTA ) Oct 21 05:09:02 volumio CRON[27982]: pam_unix(cron:session): session closed for user root Oct 21 05:09:02 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 21 05:09:02 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 21 05:09:02 volumio volumio[27815]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 21 05:09:06 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:06 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:06 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:06 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:11 volumio volumio[27815]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=3.695&uuid=0c43e586fe46088d78b2a1ce057e0ad8" http://updates.volumio.org/downloader-v1/track-device Oct 21 05:09:11 volumio volumio[27815]: % Total % Received % Xferd Average Speed Time Time Time Current Oct 21 05:09:11 volumio volumio[27815]: Dload Upload Total Spent Left Speed Oct 21 05:09:11 volumio volumio[27815]: [2.2K blob data] Oct 21 05:09:11 volumio volumio[27815]: retrying in 5 seconds, trial 0 Oct 21 05:09:11 volumio volumio[27815]: info: Volumio Calling Home Oct 21 05:09:11 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:11 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:11 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:11 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:16 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:16 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:16 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:16 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:17 volumio volumiologrotate[680]: Total log size is greater than 18MB, cleaning logs Oct 21 05:09:17 volumio volumiologrotate[680]: Clearing /var/log/mpd.log Oct 21 05:09:17 volumio volumiologrotate[680]: Clearing /var/log/samba/log.smbd Oct 21 05:09:17 volumio volumiologrotate[680]: Clearing /var/log/samba/log.winbindd Oct 21 05:09:17 volumio volumiologrotate[680]: Clearing /var/log/samba/log.nmbd Oct 21 05:09:17 volumio volumiologrotate[680]: Clearing /var/log/wtmp Oct 21 05:09:17 volumio volumiologrotate[680]: Clearing /var/log/boot.log Oct 21 05:09:21 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:21 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:21 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:21 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:26 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:26 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:26 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:26 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:28 volumio volumio[27815]: info: Discovery: adding bb46374f-887a-42fb-91a9-cd1a48c39133 Oct 21 05:09:28 volumio volumio[27815]: info: Discovery: Found device Volumio Oct 21 05:09:28 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:28 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:28 volumio volumio[27815]: info: Discovery: this is already registered, bb46374f-887a-42fb-91a9-cd1a48c39133 Oct 21 05:09:28 volumio volumio[27815]: info: Discovery: Found device Volumio Oct 21 05:09:28 volumio volumio[27815]: info: CoreCommandRouter::volumioGetState Oct 21 05:09:28 volumio volumio[27815]: info: CorePlayQueue::getTrack 0 Oct 21 05:09:28 volumio volumio[27815]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 21 05:09:28 volumio volumio[27815]: Error: connect ENETUNREACH 130.211.19.189:80 Oct 21 05:09:28 volumio volumio[27815]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Oct 21 05:09:28 volumio volumio[27815]: errno: -101, Oct 21 05:09:28 volumio volumio[27815]: code: 'ENETUNREACH', Oct 21 05:09:28 volumio volumio[27815]: syscall: 'connect', Oct 21 05:09:28 volumio volumio[27815]: address: '130.211.19.189', Oct 21 05:09:28 volumio volumio[27815]: port: 80 Oct 21 05:09:28 volumio volumio[27815]: } Oct 21 05:09:28 volumio volumio[27815]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 21 05:09:29 volumio sudo[28082]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-21 05:08 Oct 21 05:09:29 volumio sudo[28082]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="ef589a0572b08c3d1e9a984ec6a655ef3698e415" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="abe72e92bc7de90ab6193cbc17e21ad2750980a2" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 28 May 2024 12:17:12 PM CEST" VOLUMIO_VERSION="3.695" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8f37ff40efaaf3752fac55d6a95d61cb"