-- Logs begin at Fri 2024-11-15 03:50:24 EST, end at Tue 2025-04-22 12:41:08 EDT. -- Apr 22 12:40:42 minivolumio systemd-timedated[1022]: Changed local time to Tue Apr 22 12:40:42 2025 Apr 22 12:40:42 minivolumio sudo[1018]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:42 minivolumio volumio-time-update[471]: volumio-time-update-util: System time updated successfully. Apr 22 12:40:42 minivolumio systemd[1]: Started Volumio Time Update Utility. Apr 22 12:40:42 minivolumio systemd[1]: Starting Daily man-db regeneration... Apr 22 12:40:42 minivolumio systemd[1]: Starting Daily apt download activities... Apr 22 12:40:42 minivolumio ntpd[765]: Listen normally on 3 eth0 10.0.0.131:123 Apr 22 12:40:42 minivolumio ntpd[765]: new interface(s) found: waking up resolver Apr 22 12:40:42 minivolumio wireless.js[467]: trying... Apr 22 12:40:42 minivolumio sudo[1031]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 22 12:40:42 minivolumio sudo[1031]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:42 minivolumio sudo[1031]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:42 minivolumio systemd[1]: man-db.service: Succeeded. Apr 22 12:40:42 minivolumio systemd[1]: Started Daily man-db regeneration. Apr 22 12:40:43 minivolumio wireless.js[467]: trying... Apr 22 12:40:43 minivolumio sudo[1052]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 22 12:40:43 minivolumio sudo[1052]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:43 minivolumio sudo[1052]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:44 minivolumio wireless.js[467]: trying... Apr 22 12:40:44 minivolumio sudo[1058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 22 12:40:44 minivolumio sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:44 minivolumio sudo[1058]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:45 minivolumio wireless.js[467]: trying... Apr 22 12:40:45 minivolumio sudo[1073]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 22 12:40:45 minivolumio sudo[1073]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:45 minivolumio sudo[1073]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:45 minivolumio systemd[1]: apt-daily.service: Succeeded. Apr 22 12:40:45 minivolumio systemd[1]: Started Daily apt download activities. Apr 22 12:40:45 minivolumio systemd[1]: Starting Daily apt upgrade and clean activities... Apr 22 12:40:46 minivolumio wireless.js[467]: trying... Apr 22 12:40:46 minivolumio sudo[1114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 22 12:40:46 minivolumio sudo[1114]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:46 minivolumio sudo[1114]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:47 minivolumio wireless.js[467]: trying... Apr 22 12:40:47 minivolumio sudo[1143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 22 12:40:47 minivolumio sudo[1143]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:47 minivolumio sudo[1143]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:47 minivolumio systemd[1]: apt-daily-upgrade.service: Succeeded. Apr 22 12:40:47 minivolumio systemd[1]: Started Daily apt upgrade and clean activities. Apr 22 12:40:47 minivolumio dhcpcd[975]: wlan0: leased 10.0.0.86 for 172800 seconds Apr 22 12:40:47 minivolumio avahi-daemon[481]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.0.0.86. Apr 22 12:40:47 minivolumio avahi-daemon[481]: New relevant interface wlan0.IPv4 for mDNS. Apr 22 12:40:47 minivolumio dhcpcd[975]: wlan0: adding route to 10.0.0.0/24 Apr 22 12:40:47 minivolumio avahi-daemon[481]: Registering new address record for 10.0.0.86 on wlan0.IPv4. Apr 22 12:40:47 minivolumio dhcpcd[975]: wlan0: adding default route via 10.0.0.1 Apr 22 12:40:48 minivolumio wireless.js[467]: trying... Apr 22 12:40:48 minivolumio sudo[1169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 22 12:40:48 minivolumio sudo[1169]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:48 minivolumio sudo[1169]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:48 minivolumio wireless.js[467]: Connected to: ----KamelNetwork Apr 22 12:40:48 minivolumio wireless.js[467]: ---- Apr 22 12:40:48 minivolumio sudo[1172]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 22 12:40:48 minivolumio sudo[1172]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:48 minivolumio sudo[1172]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:48 minivolumio wireless.js[467]: ... joined AP, wlan0 IPv4 is 10.0.0.86, ipV6 is undefined Apr 22 12:40:48 minivolumio wireless.js[467]: It's done! AP Apr 22 12:40:48 minivolumio volumio-remote-updater[472]: [2025-04-22 12:40:48] [info] asio async_connect error: system:111 (Connection refused) Apr 22 12:40:48 minivolumio volumio-remote-updater[472]: [2025-04-22 12:40:48] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Apr 22 12:40:48 minivolumio volumio-remote-updater[472]: [2025-04-22 12:40:48] [error] handle_connect error: Underlying Transport Error Apr 22 12:40:48 minivolumio systemd[1]: Started Wireless Services. Apr 22 12:40:48 minivolumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Apr 22 12:40:48 minivolumio systemd[1]: Started Volumio Backend Module. Apr 22 12:40:48 minivolumio systemd[1]: Started Volumio Cpu Tweaker. Apr 22 12:40:48 minivolumio systemd[1]: Reached target Multi-User System. Apr 22 12:40:48 minivolumio systemd[1]: Reached target Graphical Interface. Apr 22 12:40:48 minivolumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Apr 22 12:40:48 minivolumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Apr 22 12:40:48 minivolumio systemd[1]: Started Update UTMP about System Runlevel Changes. Apr 22 12:40:48 minivolumio systemd[1]: Startup finished in 15.961s (kernel) + 30.808s (userspace) = 46.770s. Apr 22 12:40:48 minivolumio volumio-cpu-tweak[1178]: Setting RT Priority for mpd Apr 22 12:40:48 minivolumio volumio-cpu-tweak[1178]: Setting MPD Affinity Apr 22 12:40:48 minivolumio volumio-cpu-tweak[1178]: pid 804's current affinity mask: f Apr 22 12:40:48 minivolumio volumio-cpu-tweak[1178]: pid 804's new affinity mask: 3 Apr 22 12:40:48 minivolumio volumio-cpu-tweak[1178]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Apr 22 12:40:48 minivolumio volumio-cpu-tweak[1178]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Apr 22 12:40:48 minivolumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Apr 22 12:40:49 minivolumio ntpd[765]: Listen normally on 4 wlan0 10.0.0.86:123 Apr 22 12:40:49 minivolumio ntpd[765]: new interface(s) found: waking up resolver Apr 22 12:40:51 minivolumio volumio[1177]: info: ------------------------------------------- Apr 22 12:40:51 minivolumio volumio[1177]: info: ----- Volumio3 ---- Apr 22 12:40:51 minivolumio volumio[1177]: info: ------------------------------------------- Apr 22 12:40:51 minivolumio volumio[1177]: info: ----- System startup ---- Apr 22 12:40:51 minivolumio volumio[1177]: info: ------------------------------------------- Apr 22 12:40:52 minivolumio volumio[1177]: info: MYVOLUMIO Environment detected Apr 22 12:40:52 minivolumio volumio[1177]: info: Plugin folders cleanup Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning into folder /volumio/app/plugins/ Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning category audio_interface Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning category miscellanea Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning category music_service Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning category plugins.json Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning category system_controller Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning category user_interface Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning into folder /data/plugins/ Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning category music_service Apr 22 12:40:52 minivolumio volumio[1177]: info: Scanning category user_interface Apr 22 12:40:52 minivolumio volumio[1177]: info: Plugin folders cleanup completed Apr 22 12:40:52 minivolumio volumio[1177]: info: ------------------------------------------- Apr 22 12:40:52 minivolumio volumio[1177]: info: ----- Core plugins startup ---- Apr 22 12:40:52 minivolumio volumio[1177]: info: ------------------------------------------- Apr 22 12:40:52 minivolumio volumio[1177]: info: Loading plugins from folder /volumio/app/plugins/ Apr 22 12:40:52 minivolumio volumio[1177]: info: Adding plugin upnp to MyMusic Plugins Apr 22 12:40:52 minivolumio volumio[1177]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 22 12:40:52 minivolumio volumio[1177]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 22 12:40:52 minivolumio volumio[1177]: info: Loading plugins from folder /data/plugins/ Apr 22 12:40:52 minivolumio volumio[1177]: info: Loading plugin "system"... Apr 22 12:40:52 minivolumio volumio[1177]: info: Loading plugin "appearance"... Apr 22 12:40:52 minivolumio systemd[1]: systemd-fsckd.service: Succeeded. Apr 22 12:40:53 minivolumio volumio[1177]: info: Loading plugin "network"... Apr 22 12:40:53 minivolumio volumio[1177]: info: Refreshing Cached IP Addresses Apr 22 12:40:53 minivolumio sudo[1209]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 22 12:40:53 minivolumio sudo[1209]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:53 minivolumio sudo[1209]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:53 minivolumio sudo[1211]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 22 12:40:53 minivolumio sudo[1211]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:53 minivolumio sudo[1211]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:53 minivolumio volumio[1177]: info: Loading plugin "services"... Apr 22 12:40:53 minivolumio volumio[1177]: info: Loading plugin "alsa_controller"... Apr 22 12:40:53 minivolumio sudo[1220]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 22 12:40:53 minivolumio sudo[1220]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:53 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 22 12:40:53 minivolumio volumio[1177]: info: Loading plugin "wizard"... Apr 22 12:40:53 minivolumio volumio[1177]: info: Loading plugin "networkfs"... Apr 22 12:40:53 minivolumio volumio[1177]: info: Starting Udev Watcher for removable devices Apr 22 12:40:54 minivolumio volumio[1177]: info: Ignoring mount for partition: boot Apr 22 12:40:54 minivolumio volumio[1177]: info: Ignoring mount for partition: volumio Apr 22 12:40:54 minivolumio volumio[1177]: info: Ignoring mount for partition: volumio_data Apr 22 12:40:54 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 22 12:40:54 minivolumio volumio[1177]: info: Loading plugin "volumio_command_line_client"... Apr 22 12:40:54 minivolumio volumio[1177]: info: Loading plugin "upnp"... Apr 22 12:40:54 minivolumio volumio[1177]: info: [1745340054042] Starting Upmpd Daemon Apr 22 12:40:54 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 22 12:40:54 minivolumio volumio[1177]: info: Loading plugin "my_music"... Apr 22 12:40:54 minivolumio volumio[1177]: info: Loading plugin "mpd"... Apr 22 12:40:54 minivolumio volumio[1177]: info: Loading plugin "upnp_browser"... Apr 22 12:40:54 minivolumio volumio[1177]: info: Loading plugin "alarm-clock"... Apr 22 12:40:55 minivolumio volumio[1177]: info: Loading plugin "airplay_emulation"... Apr 22 12:40:55 minivolumio volumio[1177]: info: Starting Shairport Sync Apr 22 12:40:55 minivolumio volumio[1177]: info: Loading plugin "last_100"... Apr 22 12:40:55 minivolumio volumio[1177]: info: Loading plugin "webradio"... Apr 22 12:40:55 minivolumio volumio[1177]: info: Loading plugin "i2s_dacs"... Apr 22 12:40:55 minivolumio volumio[1177]: info: Loading plugin "volumiodiscovery"... Apr 22 12:40:55 minivolumio volumio[1177]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 22 12:40:55 minivolumio volumio[1177]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 22 12:40:55 minivolumio volumio[1177]: *** WARNING *** For more information see Apr 22 12:40:55 minivolumio volumio[1177]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 22 12:40:55 minivolumio node[1177]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 22 12:40:55 minivolumio volumio[1177]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 22 12:40:55 minivolumio volumio[1177]: *** WARNING *** For more information see Apr 22 12:40:55 minivolumio node[1177]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 22 12:40:55 minivolumio node[1177]: *** WARNING *** For more information see Apr 22 12:40:55 minivolumio node[1177]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 22 12:40:55 minivolumio node[1177]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 22 12:40:55 minivolumio node[1177]: *** WARNING *** For more information see Apr 22 12:40:55 minivolumio volumio[1177]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 22 12:40:55 minivolumio volumio[1177]: info: Discovery: Started advertising with name: MiniVolumio Apr 22 12:40:55 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 22 12:40:55 minivolumio volumio[1177]: info: Loading plugin "spop"... Apr 22 12:40:57 minivolumio volumio[1177]: info: Loading plugin "outputs"... Apr 22 12:40:57 minivolumio volumio[1177]: info: Loading plugin "albumart"... Apr 22 12:40:57 minivolumio volumio[1177]: info: Plugin example_plugin is not enabled Apr 22 12:40:57 minivolumio volumio[1177]: info: Loading plugin "inputs"... Apr 22 12:40:57 minivolumio volumio[1177]: info: Loading plugin "updater_comm"... Apr 22 12:40:57 minivolumio sudo[1220]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:57 minivolumio volumio[1177]: info: Plugin mpdemulation is not enabled Apr 22 12:40:57 minivolumio volumio[1177]: info: Loading plugin "rest_api"... Apr 22 12:40:57 minivolumio volumio[1177]: info: Loading plugin "websocket"... Apr 22 12:40:57 minivolumio volumio[1177]: info: Starting Socket.io Server version 2.3.0 Apr 22 12:40:57 minivolumio volumio[1177]: info: Loading plugin "touch_display"... Apr 22 12:40:57 minivolumio volumio[1177]: Forking 3 albumart workers Apr 22 12:40:57 minivolumio volumio[1177]: info: Applying required configuration parameters for plugin touch_display Apr 22 12:40:58 minivolumio volumio[1177]: info: Loading i18n strings for locale en Apr 22 12:40:58 minivolumio volumio[1177]: Updating browse sources language Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 22 12:40:58 minivolumio volumio-remote-updater[472]: [2025-04-22 12:40:58] [connect] Successful connection Apr 22 12:40:58 minivolumio volumio[1177]: Starting albumart workers Apr 22 12:40:58 minivolumio volumio[1177]: Starting albumart workers Apr 22 12:40:58 minivolumio volumio[1177]: Starting albumart workers Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::initPlayerControls Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 22 12:40:58 minivolumio volumio[1177]: Express server listening on port 3000 Apr 22 12:40:58 minivolumio volumio[1177]: [Metrics] WebUI: 8s 409.21ms Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreStateMachine::resetVolumioState Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreStateMachine::getcurrentVolume Apr 22 12:40:58 minivolumio volumio[1177]: info: CoreCommandRouter::volumioRetrievevolume Apr 22 12:40:58 minivolumio volumio[1177]: info: Volumio Network Manager: Network status updated: 3 Apr 22 12:40:58 minivolumio volumio-remote-updater[472]: [2025-04-22 12:40:58] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1745340058 101 Apr 22 12:40:58 minivolumio volumio[1177]: 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 Apr 22 12:40:59 minivolumio volumio[1177]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 22 12:40:59 minivolumio volumio[1177]: info: Reloading queue from file Apr 22 12:40:59 minivolumio volumio[1177]: info: VolumeController:: Volume=29 Mute =false Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreStateMachine::pushState Apr 22 12:40:59 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioPushState Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreStateMachine::updateTrackBlock Apr 22 12:40:59 minivolumio volumio[1177]: info: CorePlayQueue::getTrackBlock Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioRetrievevolume Apr 22 12:40:59 minivolumio volumio[1177]: info: Setting Device type: Raspberry PI Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreStateMachine::setRepeat null single undefined Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreStateMachine::pushState Apr 22 12:40:59 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioPushState Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreStateMachine::setRandom null Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreStateMachine::pushState Apr 22 12:40:59 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioPushState Apr 22 12:40:59 minivolumio volumio[1177]: info: Completed loading Core Plugins Apr 22 12:40:59 minivolumio volumio[1177]: info: Preparing to generate the ALSA configuration file Apr 22 12:40:59 minivolumio volumio[1177]: info: Asound.conf file unchanged, so no further update is needed Apr 22 12:40:59 minivolumio volumio[1177]: info: Output device has changed, restarting MPD Apr 22 12:40:59 minivolumio volumio[1177]: info: Output device has changed, restarting Shairport Sync Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 22 12:40:59 minivolumio sudo[1307]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 22 12:40:59 minivolumio sudo[1307]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:59 minivolumio sudo[1307]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:59 minivolumio sudo[1309]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 22 12:40:59 minivolumio sudo[1309]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:59 minivolumio systemd[1]: Stopping Music Player Daemon... Apr 22 12:40:59 minivolumio volumio[1177]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 22 12:40:59 minivolumio volumio[1177]: info: ___________ START PLUGINS ___________ Apr 22 12:40:59 minivolumio volumio[1177]: info: ControllerMpd::onStart: Initializing MPD Apr 22 12:40:59 minivolumio volumio[1177]: info: Creating MPD Configuration file Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 22 12:40:59 minivolumio volumio[1177]: info: [1745340059476] CoreMusicLibrary::Adding element Media Servers Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 22 12:40:59 minivolumio sudo[1316]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 22 12:40:59 minivolumio sudo[1316]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:59 minivolumio sudo[1316]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 22 12:40:59 minivolumio sudo[1318]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 22 12:40:59 minivolumio sudo[1318]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:59 minivolumio volumio[1177]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 22 12:40:59 minivolumio systemd[1]: mpd.service: Succeeded. Apr 22 12:40:59 minivolumio systemd[1]: Stopped Music Player Daemon. Apr 22 12:40:59 minivolumio volumio[1177]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 22 12:40:59 minivolumio volumio[1177]: info: [1745340059606] CoreMusicLibrary::Adding element Last_100 Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 22 12:40:59 minivolumio volumio[1177]: info: [1745340059609] CoreMusicLibrary::Adding element Webradio Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 22 12:40:59 minivolumio volumio[1177]: info: Initializing BBC Radios Apr 22 12:40:59 minivolumio systemd[1]: Starting Music Player Daemon... Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 22 12:40:59 minivolumio volumio[1177]: info: Creating Spotify config file Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:40:59 minivolumio sudo[1327]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 22 12:40:59 minivolumio sudo[1327]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:59 minivolumio sudo[1327]: pam_unix(sudo:session): session closed for user root Apr 22 12:40:59 minivolumio volumio[1177]: info: Loading i18n strings for locale en Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 22 12:40:59 minivolumio volumio[1177]: info: Volumio Calling Home Apr 22 12:40:59 minivolumio sudo[1344]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Apr 22 12:40:59 minivolumio sudo[1344]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:40:59 minivolumio systemd[1]: Reloading. Apr 22 12:40:59 minivolumio volumio[1177]: info: VolumeController:: Volume=29 Mute =false Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreStateMachine::pushState Apr 22 12:40:59 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioPushState Apr 22 12:40:59 minivolumio volumio[1177]: info: Discovery: adding 8a1a3894-7b7c-443c-bd25-e8e343c4eb91 Apr 22 12:40:59 minivolumio volumio[1177]: info: Discovery: Found device MiniVolumio Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioGetState Apr 22 12:40:59 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:40:59 minivolumio volumio[1177]: info: Discovery: this is already registered, 8a1a3894-7b7c-443c-bd25-e8e343c4eb91 Apr 22 12:40:59 minivolumio volumio[1177]: info: Discovery: Found device MiniVolumio Apr 22 12:40:59 minivolumio volumio[1177]: info: CoreCommandRouter::volumioGetState Apr 22 12:40:59 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:40:59 minivolumio volumio[1177]: info: MPD Permissions set Apr 22 12:40:59 minivolumio volumio[1177]: info: MPD Permissions set Apr 22 12:41:00 minivolumio volumio[1177]: info: Spotify config file written Apr 22 12:41:00 minivolumio sudo[1351]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 22 12:41:00 minivolumio sudo[1351]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:41:00 minivolumio volumio[1177]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 22 12:41:00 minivolumio volumio[1177]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Apr 22 12:41:00 minivolumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Apr 22 12:41:00 minivolumio volumio[1177]: info: Volumio called home Apr 22 12:41:00 minivolumio volumio[1177]: info: Starting Shairport Sync Apr 22 12:41:00 minivolumio volumio[1177]: info: Starting Shairport Sync Apr 22 12:41:00 minivolumio volumio[1177]: info: Starting Shairport Sync Apr 22 12:41:00 minivolumio sudo[1371]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 22 12:41:00 minivolumio sudo[1371]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:41:00 minivolumio sudo[1373]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 22 12:41:00 minivolumio sudo[1373]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::volumioGetState Apr 22 12:41:00 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:41:00 minivolumio sudo[1377]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 22 12:41:00 minivolumio sudo[1377]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:41:00 minivolumio volumio[1177]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 22 12:41:00 minivolumio volumio[1177]: SPOTIFY: BQCvf6sIXiEvueV4iE6delC96dpuLiD1uQpYb5ZxbBRxxJmCpiflon-c_31WqAnMMKlM35Ck6rY6PWBgE8o6Dz47OPNK7f8gm1Vcv2lH0tyfd8LzjF8Ia6wGPCgIO6LtsMhiOlLhqbqAUTZ_Mtmo4BPoPvSnOUz_wbNpMp5-fZpceKuNk6B5j0cs-Xv2kQ69r64oczYqZX_ehMgsrQNjBfuyKP-jR7sPIeASgnd2gTtHckXmvh1IPl7W6JUFeN26Yi0Ovjjr-RpsKNMuvuhRMPZwRdj3aQ Apr 22 12:41:00 minivolumio volumio[1177]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 22 12:41:00 minivolumio volumio[1177]: info: New Spotify access token = BQCvf6sIXiEvueV4iE6delC96dpuLiD1uQpYb5ZxbBRxxJmCpiflon-c_31WqAnMMKlM35Ck6rY6PWBgE8o6Dz47OPNK7f8gm1Vcv2lH0tyfd8LzjF8Ia6wGPCgIO6LtsMhiOlLhqbqAUTZ_Mtmo4BPoPvSnOUz_wbNpMp5-fZpceKuNk6B5j0cs-Xv2kQ69r64oczYqZX_ehMgsrQNjBfuyKP-jR7sPIeASgnd2gTtHckXmvh1IPl7W6JUFeN26Yi0Ovjjr-RpsKNMuvuhRMPZwRdj3aQ Apr 22 12:41:00 minivolumio volumio[1177]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 22 12:41:00 minivolumio systemd[1]: getty@tty1.service: Current command vanished from the unit file, execution of the command list won't be resumed. Apr 22 12:41:00 minivolumio volumio[1177]: SPOTIFY: User informations: {"country":"CA","display_name":"Forand","email":"pforand@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/pforand"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/pforand","id":"pforand","images":[],"product":"premium","type":"user","uri":"spotify:user:pforand"} Apr 22 12:41:00 minivolumio volumio[1177]: info: Spotify Successfully logged in Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 22 12:41:00 minivolumio volumio[1177]: info: [1745340060764] CoreMusicLibrary::Adding element Spotify Apr 22 12:41:00 minivolumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 22 12:41:00 minivolumio volumio[1177]: Cannot find translation for source Spotify Apr 22 12:41:00 minivolumio systemd[1]: systemd-hostnamed.service: Succeeded. Apr 22 12:41:00 minivolumio sudo[1344]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:00 minivolumio volumio[1177]: info: touch_display: systemctl daemon-reload succeeded. Apr 22 12:41:00 minivolumio sudo[1383]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Apr 22 12:41:00 minivolumio sudo[1383]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:41:01 minivolumio systemd[1]: Started Volumio Kiosk. Apr 22 12:41:01 minivolumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 22 12:41:01 minivolumio systemd[1]: Started go-librespot Daemon. Apr 22 12:41:01 minivolumio sudo[1351]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:01 minivolumio go-librespot[1387]: Librespot-go daemon starting... Apr 22 12:41:01 minivolumio systemd[1]: shairport-sync.service: Succeeded. Apr 22 12:41:01 minivolumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 22 12:41:01 minivolumio sudo[1383]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:01 minivolumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 22 12:41:01 minivolumio volumio[1177]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Apr 22 12:41:01 minivolumio volumio[1177]: info: touch_display: Volumio Kiosk started Apr 22 12:41:01 minivolumio volumio[1177]: info: CoreCommandRouter::volumioGetState Apr 22 12:41:01 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:41:01 minivolumio sudo[1371]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:01 minivolumio sudo[1373]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:01 minivolumio sudo[1377]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:01 minivolumio volumio[1177]: info: CoreCommandRouter::volumioGetState Apr 22 12:41:01 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:41:01 minivolumio volumio[1177]: info: Shairport-Sync Started Apr 22 12:41:01 minivolumio volumio[1177]: Error adding Membership: Error: addMembership EINVAL Apr 22 12:41:01 minivolumio volumio[1177]: info: Shairport-Sync Started Apr 22 12:41:01 minivolumio volumio[1177]: info: Shairport-Sync Started Apr 22 12:41:01 minivolumio volumio[1177]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X Apr 22 12:41:01 minivolumio volumio[1177]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 22 12:41:01 minivolumio volumio[1177]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 22 12:41:01 minivolumio startx[1385]: X.Org X Server 1.20.4 Apr 22 12:41:01 minivolumio startx[1385]: X Protocol Version 11, Revision 0 Apr 22 12:41:01 minivolumio startx[1385]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian Apr 22 12:41:01 minivolumio startx[1385]: Current Operating System: Linux minivolumio 6.6.56-v7+ #1803 SMP Thu Oct 10 14:08:55 BST 2024 armv7l Apr 22 12:41:01 minivolumio startx[1385]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=512 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=af3faec2-9654-4fec-8791-d5638a5837ad imgfile=/volumio_current.sqsh bootpart=UUID=2E0A-AE55 datapart=UUID=660717eb-e471-4727-aac1-2c263938c365 uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Apr 22 12:41:01 minivolumio startx[1385]: Build Date: 04 April 2023 07:50:56AM Apr 22 12:41:01 minivolumio startx[1385]: xorg-server 2:1.20.4-1+rpt4+deb10u9 (https://www.debian.org/support) Apr 22 12:41:01 minivolumio startx[1385]: Current version of pixman: 0.36.0 Apr 22 12:41:01 minivolumio startx[1385]: Before reporting problems, check http://wiki.x.org Apr 22 12:41:01 minivolumio startx[1385]: to make sure that you have the latest version. Apr 22 12:41:01 minivolumio startx[1385]: Markers: (--) probed, (**) from config file, (==) default setting, Apr 22 12:41:01 minivolumio startx[1385]: (++) from command line, (!!) notice, (II) informational, Apr 22 12:41:01 minivolumio startx[1385]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Apr 22 12:41:01 minivolumio startx[1385]: (==) Log file: "/var/log/Xorg.0.log", Time: Tue Apr 22 12:41:01 2025 Apr 22 12:41:01 minivolumio mpd[1339]: Apr 22 12:41 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 22 12:41:01 minivolumio systemd[1]: Started Music Player Daemon. Apr 22 12:41:01 minivolumio sudo[1318]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:01 minivolumio sudo[1309]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:01 minivolumio startx[1385]: (==) Using config directory: "/etc/X11/xorg.conf.d" Apr 22 12:41:01 minivolumio startx[1385]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Apr 22 12:41:01 minivolumio volumio[1177]: info: Completed starting Core Plugins Apr 22 12:41:01 minivolumio volumio[1177]: info: ------------------------------------------- Apr 22 12:41:01 minivolumio volumio[1177]: info: ----- MyVolumio plugins startup ---- Apr 22 12:41:01 minivolumio volumio[1177]: info: ------------------------------------------- Apr 22 12:41:01 minivolumio volumio[1177]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 22 12:41:01 minivolumio volumio[1177]: info: CoreCommandRouter::volumioGetState Apr 22 12:41:01 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:41:01 minivolumio volumio[1177]: info: MPD running with PID1339 Apr 22 12:41:01 minivolumio volumio[1177]: ,establishing connection Apr 22 12:41:01 minivolumio go-librespot[1387]: time="2025-04-22T12:41:01-04:00" level=info msg="generated new device id: a66088f55c237acf88b2de1562d2583c5472a47a" Apr 22 12:41:01 minivolumio go-librespot[1387]: time="2025-04-22T12:41:01-04:00" level=debug msg="stored credentials found for pforand" Apr 22 12:41:01 minivolumio volumio[1177]: error: MPD error: The expression evaluated to a falsy value: Apr 22 12:41:01 minivolumio volumio[1177]: assert.ok(self.idling) Apr 22 12:41:01 minivolumio volumio[1177]: error: The expression evaluated to a falsy value: Apr 22 12:41:01 minivolumio volumio[1177]: assert.ok(self.idling) Apr 22 12:41:01 minivolumio volumio[1177]: error: MPD error: The expression evaluated to a falsy value: Apr 22 12:41:01 minivolumio volumio[1177]: assert.ok(self.idling) Apr 22 12:41:01 minivolumio volumio[1177]: error: The expression evaluated to a falsy value: Apr 22 12:41:01 minivolumio volumio[1177]: assert.ok(self.idling) Apr 22 12:41:01 minivolumio volumio[1177]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 22 12:41:01 minivolumio volumio[1177]: error: updateQueue error: null Apr 22 12:41:02 minivolumio go-librespot[1387]: time="2025-04-22T12:41:02-04:00" level=debug msg="obtained new client token: AAC0lhqXSnu7OFLvyZbF/WUQVhaMwW15CxuzhsFjrwYqA2FiH5JbiAfoKJVzKimKvR06f1WsXIzPKrMJWoSRnmFwKLF9Zc7VhrhxxMZRbCEoaU01/PGZZ3J/t1f51Xkju3ZpqQLibgxYEaoLuAXv3bB4ZgjJGiLsgxc+jsPc6fW1lpW9fiswnD9c/l2sdsoI9dX44ayy1e8freyOTMcFfESAR4cdt7JuySiEVBNNA3esfSg+ZDucT1DTn/ezwg==" Apr 22 12:41:02 minivolumio go-librespot[1387]: time="2025-04-22T12:41:02-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 22 12:41:02 minivolumio go-librespot[1387]: time="2025-04-22T12:41:02-04:00" level=debug msg="completed keyexchange" Apr 22 12:41:02 minivolumio go-librespot[1387]: time="2025-04-22T12:41:02-04:00" level=debug msg="completed challenge" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="authenticated as pforand" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="authenticated as pforand" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 22 12:41:03 minivolumio volumio[1177]: info: touch_display: Setting screensaver timeout to 120 seconds. Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="dealer connection opened" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="received connection id: OGExYzZhMTYtMGFiOC00OWJjLTliOWQtYzVmNjg1ZWM5ODg5K2RlYWxlcit0Y3A6Ly8wYWNiZmFjNS5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArQjg5MDE1RkUwREJDMUJFOUVFQjg1RjE1RDNFMUNFNUE0NTNEQjBCNjFFNzQ5NUM4MDdFRDZEQjI5MUQ0QjMyOA==" Apr 22 12:41:03 minivolumio go-librespot[1387]: time="2025-04-22T12:41:03-04:00" level=debug msg="put connect state because NEW_DEVICE" Apr 22 12:41:04 minivolumio sudo[1496]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 22 12:41:04 minivolumio sudo[1496]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:41:04 minivolumio sudo[1496]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:04 minivolumio sudo[1501]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 22 12:41:04 minivolumio sudo[1501]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:41:04 minivolumio sudo[1501]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:04 minivolumio sudo[1509]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 22 12:41:04 minivolumio sudo[1509]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 12:41:04 minivolumio volumio[1177]: info: go-librespot daemon successfully initialized Apr 22 12:41:04 minivolumio systemd[1]: Started UPnP Renderer front-end to MPD. Apr 22 12:41:04 minivolumio sudo[1509]: pam_unix(sudo:session): session closed for user root Apr 22 12:41:04 minivolumio volumio[1177]: info: Upmpdcli Daemon Started Apr 22 12:41:04 minivolumio volumio[1512]: Generating RSA private key, 4096 bit long modulus (2 primes) Apr 22 12:41:05 minivolumio go-librespot[1387]: time="2025-04-22T12:41:05-04:00" level=debug msg="handling transfer player command from 060b6ae718d7d8da06f0e5c558dbb76a4893d005" Apr 22 12:41:05 minivolumio go-librespot[1387]: time="2025-04-22T12:41:05-04:00" level=trace msg="fetched new page 0 with 18 items (list: 18)" Apr 22 12:41:05 minivolumio go-librespot[1387]: time="2025-04-22T12:41:05-04:00" level=debug msg="shuffled context with seed 14947216844644641183 (len: 18, keep: 15)" Apr 22 12:41:05 minivolumio go-librespot[1387]: time="2025-04-22T12:41:05-04:00" level=debug msg="loading track spotify:track:5dv7SIQ4P6rhXVCutLYAgA (paused: false, position: 334206ms)" Apr 22 12:41:06 minivolumio go-librespot[1387]: time="2025-04-22T12:41:06-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 12:41:06 minivolumio go-librespot[1387]: time="2025-04-22T12:41:06-04:00" level=trace msg="emitting websocket event: will_play" Apr 22 12:41:06 minivolumio go-librespot[1387]: time="2025-04-22T12:41:06-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Apr 22 12:41:06 minivolumio go-librespot[1387]: time="2025-04-22T12:41:06-04:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5dv7SIQ4P6rhXVCutLYAgA" Apr 22 12:41:06 minivolumio go-librespot[1387]: time="2025-04-22T12:41:06-04:00" level=debug msg="requested aes key for file 4bd02645db13baa0e9fa32e3fad3ce8d449d7c51, gid: 5dv7SIQ4P6rhXVCutLYAgA" Apr 22 12:41:06 minivolumio go-librespot[1387]: time="2025-04-22T12:41:06-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1330" Apr 22 12:41:06 minivolumio go-librespot[1387]: time="2025-04-22T12:41:06-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1111" Apr 22 12:41:06 minivolumio volumio[1177]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=debug msg="fetched first chunk of 32, total size is 16703036 bytes" Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Apr 22 12:41:07 minivolumio volumio[1177]: info: Initializing connection to go-librespot Websocket Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=debug msg="new websocket client" Apr 22 12:41:07 minivolumio volumio[1177]: info: Connection to go-librespot Websocket established Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=debug msg="fetched chunk 2/31, size: 524288" Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=debug msg="fetched chunk 3/31, size: 524288" Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=debug msg="fetched chunk 1/31, size: 524288" Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=debug msg="fetched chunk 30/31, size: 524288" Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=debug msg="fetched chunk 29/31, size: 524288" Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=trace msg="seek to 334206ms (diff: 450ms, samples: 14738484, bytes: 15685575)" Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=info msg="loaded track \"Le sabbatique (monologue)\" (uri: spotify:track:5dv7SIQ4P6rhXVCutLYAgA, paused: false, position: 334206ms, duration: 355416ms)" Apr 22 12:41:07 minivolumio go-librespot[1387]: time="2025-04-22T12:41:07-04:00" level=debug msg="fetched chunk 31/31, size: 450108" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=trace msg="emitting websocket event: metadata" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=trace msg="emitting websocket event: active" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=debug msg="sending successful reply for delaer request" Apr 22 12:41:08 minivolumio volumio[1177]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5dv7SIQ4P6rhXVCutLYAgA","name":"Le sabbatique (monologue)","artist_names":["Richard Desjardins"],"album_name":"Au Club Soda","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a88aedcec90f550de06b888c","position":334206,"duration":355416,"release_date":"year:1993 month:9 day:27","track_number":7,"disc_number":1}} Apr 22 12:41:08 minivolumio volumio[1177]: SPOTIFY: received: {"type":"active","data":null} Apr 22 12:41:08 minivolumio volumio[1177]: info: Aligning Spotify Volume to Volumio Volume Apr 22 12:41:08 minivolumio volumio[1177]: info: CoreCommandRouter::volumioGetState Apr 22 12:41:08 minivolumio volumio[1177]: info: CorePlayQueue::getTrack 0 Apr 22 12:41:08 minivolumio volumio[1177]: info: Setting Spotify Volume from Volumio: 29 Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=trace msg="emitting websocket event: playing" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 22 12:41:08 minivolumio volumio[1177]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5dv7SIQ4P6rhXVCutLYAgA","play_origin":"playlist"}} Apr 22 12:41:08 minivolumio volumio[1177]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 22 12:41:08 minivolumio volumio[1177]: TypeError: Cannot read property 'service' of undefined Apr 22 12:41:08 minivolumio volumio[1177]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Apr 22 12:41:08 minivolumio volumio[1177]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Apr 22 12:41:08 minivolumio volumio[1177]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Apr 22 12:41:08 minivolumio volumio[1177]: at WebSocket.emit (events.js:315:20) Apr 22 12:41:08 minivolumio volumio[1177]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Apr 22 12:41:08 minivolumio volumio[1177]: at Receiver.emit (events.js:315:20) Apr 22 12:41:08 minivolumio volumio[1177]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Apr 22 12:41:08 minivolumio volumio[1177]: at internal/process/task_queues.js:149:7 Apr 22 12:41:08 minivolumio volumio[1177]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Apr 22 12:41:08 minivolumio volumio[1177]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Apr 22 12:41:08 minivolumio volumio[1177]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 22 12:41:08 minivolumio volumio[1177]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=debug msg="put connect state inactive" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=trace msg="emitting websocket event: inactive" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=debug msg="update volume to 65535/65535" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 22 12:41:08 minivolumio go-librespot[1387]: time="2025-04-22T12:41:08-04:00" level=trace msg="emitting websocket event: volume" Apr 22 12:41:08 minivolumio sudo[1585]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-22 12:40 Apr 22 12:41:08 minivolumio sudo[1585]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"