-- Logs begin at Sat 2025-08-09 11:35:30 CEST, end at Wed 2025-09-10 12:02:33 CEST. -- Sep 10 12:01:21 volumio systemd-timedated[757]: Changed local time to Wed Sep 10 12:01:21 2025 Sep 10 12:01:21 volumio sudo[754]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:21 volumio volumio-time-update[460]: volumio-time-update-util: System time updated successfully. Sep 10 12:01:21 volumio systemd[1]: Starting Daily apt download activities... Sep 10 12:01:21 volumio systemd[1]: Started Volumio Time Update Utility. Sep 10 12:01:21 volumio volumio-remote-updater[449]: [2025-09-10 12:01:21] [connect] Successful connection Sep 10 12:01:21 volumio smbd[755]: [2025/09/10 12:01:21.779670, 0] ../lib/util/become_daemon.c:138(daemon_ready) Sep 10 12:01:21 volumio smbd[755]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Sep 10 12:01:21 volumio systemd[1]: Started Samba SMB Daemon. Sep 10 12:01:21 volumio systemd[1]: Reached target Multi-User System. Sep 10 12:01:21 volumio systemd[1]: Reached target Graphical Interface. Sep 10 12:01:21 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Sep 10 12:01:21 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Sep 10 12:01:21 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Sep 10 12:01:24 volumio volumio[680]: info: ------------------------------------------- Sep 10 12:01:24 volumio volumio[680]: info: ----- Volumio3 ---- Sep 10 12:01:24 volumio volumio[680]: info: ------------------------------------------- Sep 10 12:01:24 volumio volumio[680]: info: ----- System startup ---- Sep 10 12:01:24 volumio volumio[680]: info: ------------------------------------------- Sep 10 12:01:27 volumio systemd[1]: apt-daily.service: Succeeded. Sep 10 12:01:27 volumio systemd[1]: Started Daily apt download activities. Sep 10 12:01:27 volumio volumio[680]: info: MYVOLUMIO Environment detected Sep 10 12:01:27 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Sep 10 12:01:27 volumio volumio[680]: info: Plugin folders cleanup Sep 10 12:01:27 volumio volumio[680]: info: Scanning into folder /volumio/app/plugins/ Sep 10 12:01:27 volumio volumio[680]: info: Scanning category audio_interface Sep 10 12:01:27 volumio volumio[680]: info: Scanning category miscellanea Sep 10 12:01:27 volumio volumio[680]: info: Scanning category music_service Sep 10 12:01:27 volumio volumio[680]: info: Scanning category plugins.json Sep 10 12:01:27 volumio volumio[680]: info: Scanning category system_controller Sep 10 12:01:27 volumio volumio[680]: info: Scanning category user_interface Sep 10 12:01:27 volumio volumio[680]: info: Scanning into folder /data/plugins/ Sep 10 12:01:27 volumio volumio[680]: info: Scanning category music_service Sep 10 12:01:27 volumio volumio[680]: info: Plugin folders cleanup completed Sep 10 12:01:27 volumio volumio[680]: info: ------------------------------------------- Sep 10 12:01:27 volumio volumio[680]: info: ----- Core plugins startup ---- Sep 10 12:01:27 volumio volumio[680]: info: ------------------------------------------- Sep 10 12:01:27 volumio volumio[680]: info: Loading plugins from folder /volumio/app/plugins/ Sep 10 12:01:27 volumio volumio[680]: info: Adding plugin upnp to MyMusic Plugins Sep 10 12:01:27 volumio volumio[680]: info: Adding plugin airplay_emulation to MyMusic Plugins Sep 10 12:01:27 volumio volumio[680]: info: Adding plugin upnp_browser to MyMusic Plugins Sep 10 12:01:27 volumio volumio[680]: info: Loading plugins from folder /data/plugins/ Sep 10 12:01:28 volumio volumio[680]: info: Loading plugin "system"... Sep 10 12:01:28 volumio volumio[680]: info: Loading plugin "appearance"... Sep 10 12:01:29 volumio dhcpcd[718]: eth0: carrier lost Sep 10 12:01:29 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down Sep 10 12:01:29 volumio avahi-daemon[467]: Withdrawing address record for 192.168.1.108 on eth0. Sep 10 12:01:29 volumio dhcpcd[718]: eth0: deleting route to 192.168.1.0/24 Sep 10 12:01:29 volumio avahi-daemon[467]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.108. Sep 10 12:01:29 volumio avahi-daemon[467]: Interface eth0.IPv4 no longer relevant for mDNS. Sep 10 12:01:29 volumio dhcpcd[718]: eth0: deleting default route via 192.168.1.1 Sep 10 12:01:29 volumio ifplugd(eth0)[645]: Link beat lost. Sep 10 12:01:31 volumio ntpd[626]: Deleting interface #3 eth0, 192.168.1.108#123, interface stats: received=0, sent=0, dropped=0, active_time=13 secs Sep 10 12:01:31 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Sep 10 12:01:31 volumio systemd[1]: Started Daily apt upgrade and clean activities. Sep 10 12:01:31 volumio systemd[1]: Startup finished in 16.271s (kernel) + 33.049s (userspace) = 49.320s. Sep 10 12:01:31 volumio volumio[680]: info: Loading plugin "network"... Sep 10 12:01:31 volumio volumio[680]: info: Refreshing Cached IP Addresses Sep 10 12:01:31 volumio sudo[913]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 10 12:01:31 volumio sudo[913]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:31 volumio sudo[915]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 10 12:01:31 volumio sudo[915]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:31 volumio sudo[913]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:31 volumio volumio[680]: info: Loading plugin "services"... Sep 10 12:01:32 volumio volumio[680]: info: Loading plugin "alsa_controller"... Sep 10 12:01:32 volumio sudo[922]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 10 12:01:32 volumio sudo[915]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:32 volumio sudo[922]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:32 volumio sudo[922]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:32 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 10 12:01:32 volumio volumio[680]: info: Loading plugin "wizard"... Sep 10 12:01:32 volumio volumio[680]: info: Loading plugin "networkfs"... Sep 10 12:01:32 volumio volumio[680]: info: Starting Udev Watcher for removable devices Sep 10 12:01:32 volumio volumio[680]: info: Ignoring mount for partition: boot Sep 10 12:01:32 volumio volumio[680]: info: Ignoring mount for partition: volumio Sep 10 12:01:32 volumio volumio[680]: info: Ignoring mount for partition: volumio_data Sep 10 12:01:32 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 10 12:01:32 volumio volumio[680]: info: Loading plugin "volumio_command_line_client"... Sep 10 12:01:32 volumio volumio[680]: info: Plugin upnp is not enabled Sep 10 12:01:32 volumio volumio[680]: info: Loading plugin "my_music"... Sep 10 12:01:32 volumio volumio[680]: info: Loading plugin "mpd"... Sep 10 12:01:32 volumio dhcpcd[718]: eth0: carrier acquired Sep 10 12:01:32 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off Sep 10 12:01:32 volumio dhcpcd[718]: eth0: IAID eb:10:62:a9 Sep 10 12:01:33 volumio kernel: hwmon hwmon1: Voltage normalised Sep 10 12:01:33 volumio volumio[680]: info: Plugin upnp_browser is not enabled Sep 10 12:01:33 volumio volumio[680]: info: Loading plugin "alarm-clock"... Sep 10 12:01:33 volumio dhcpcd[718]: eth0: soliciting an IPv6 router Sep 10 12:01:33 volumio dhcpcd[718]: eth0: soliciting a DHCP lease Sep 10 12:01:33 volumio ifplugd(eth0)[645]: Link beat detected. Sep 10 12:01:33 volumio volumio[680]: info: Plugin airplay_emulation is not enabled Sep 10 12:01:33 volumio volumio[680]: info: Loading plugin "last_100"... Sep 10 12:01:33 volumio volumio[680]: info: Loading plugin "webradio"... Sep 10 12:01:34 volumio volumio[680]: info: Loading plugin "i2s_dacs"... Sep 10 12:01:34 volumio volumio[680]: info: I2S DAC not set, start Auto-detection Sep 10 12:01:34 volumio volumio[680]: info: Loading plugin "volumiodiscovery"... Sep 10 12:01:34 volumio volumio[680]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 10 12:01:34 volumio volumio[680]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 10 12:01:34 volumio node[680]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 10 12:01:34 volumio volumio[680]: *** WARNING *** For more information see Sep 10 12:01:34 volumio volumio[680]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 10 12:01:34 volumio volumio[680]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 10 12:01:34 volumio volumio[680]: *** WARNING *** For more information see Sep 10 12:01:34 volumio node[680]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 10 12:01:34 volumio node[680]: *** WARNING *** For more information see Sep 10 12:01:34 volumio node[680]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 10 12:01:34 volumio node[680]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 10 12:01:34 volumio node[680]: *** WARNING *** For more information see Sep 10 12:01:34 volumio volumio[680]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 10 12:01:34 volumio volumio[680]: info: Discovery: Started advertising with name: Volumio Sep 10 12:01:34 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 10 12:01:34 volumio volumio[680]: info: Loading plugin "mixcloud"... Sep 10 12:01:35 volumio kernel: hwmon hwmon1: Undervoltage detected! Sep 10 12:01:36 volumio volumio[680]: info: Loading plugin "spop"... Sep 10 12:01:36 volumio volumio-remote-updater[449]: [2025-09-10 12:01:36] [connect] Successful connection Sep 10 12:01:37 volumio systemd[1]: systemd-fsckd.service: Succeeded. Sep 10 12:01:38 volumio dhcpcd[718]: eth0: probing for an IPv4LL address Sep 10 12:01:40 volumio volumio[680]: info: Loading plugin "outputs"... Sep 10 12:01:40 volumio volumio[680]: info: Loading plugin "albumart"... Sep 10 12:01:40 volumio volumio[680]: info: Plugin example_plugin is not enabled Sep 10 12:01:40 volumio volumio[680]: info: Loading plugin "inputs"... Sep 10 12:01:40 volumio volumio[680]: info: Loading plugin "updater_comm"... Sep 10 12:01:40 volumio volumio[680]: info: Plugin mpdemulation is not enabled Sep 10 12:01:40 volumio volumio[680]: info: Loading plugin "rest_api"... Sep 10 12:01:41 volumio volumio[680]: info: Loading plugin "websocket"... Sep 10 12:01:41 volumio volumio[680]: info: Starting Socket.io Server version 2.3.0 Sep 10 12:01:41 volumio volumio[680]: info: Loading plugin "motherearthradio"... Sep 10 12:01:41 volumio volumio[680]: Forking 3 albumart workers Sep 10 12:01:41 volumio volumio[680]: info: Applying required configuration parameters for plugin motherearthradio Sep 10 12:01:41 volumio volumio[680]: info: [1757498501960] [MotherEarth] API delay: 5 Sep 10 12:01:41 volumio volumio[680]: info: Loading plugin "podcast"... Sep 10 12:01:42 volumio volumio[680]: info: ControllerPodcast::constructor Sep 10 12:01:43 volumio volumio[680]: info: Loading i18n strings for locale de Sep 10 12:01:43 volumio volumio[680]: Updating browse sources language Sep 10 12:01:43 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 10 12:01:43 volumio volumio[680]: Starting albumart workers Sep 10 12:01:43 volumio volumio[680]: Starting albumart workers Sep 10 12:01:43 volumio volumio[680]: Starting albumart workers Sep 10 12:01:43 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 10 12:01:43 volumio dhcpcd[718]: eth0: using IPv4LL address 169.254.50.187 Sep 10 12:01:43 volumio dhcpcd[718]: eth0: adding route to 169.254.0.0/16 Sep 10 12:01:43 volumio dhcpcd[718]: eth0: adding default route Sep 10 12:01:43 volumio avahi-daemon[467]: Joining mDNS multicast group on interface eth0.IPv4 with address 169.254.50.187. Sep 10 12:01:43 volumio avahi-daemon[467]: New relevant interface eth0.IPv4 for mDNS. Sep 10 12:01:43 volumio avahi-daemon[467]: Registering new address record for 169.254.50.187 on eth0.IPv4. Sep 10 12:01:43 volumio volumio[680]: info: CoreCommandRouter::initPlayerControls Sep 10 12:01:44 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:44 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:44 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:44 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:44 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:44 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 10 12:01:44 volumio volumio[680]: Express server listening on port 3000 Sep 10 12:01:44 volumio volumio[680]: [Metrics] WebUI: 22s 367.78ms Sep 10 12:01:44 volumio volumio[680]: info: CoreStateMachine::resetVolumioState Sep 10 12:01:44 volumio volumio[680]: info: CoreStateMachine::getcurrentVolume Sep 10 12:01:44 volumio volumio[680]: info: CoreCommandRouter::volumioRetrievevolume Sep 10 12:01:44 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 12:01:44 volumio volumio[680]: info: Volumio Network Manager: Network status updated: 0 Sep 10 12:01:44 volumio volumio[680]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Sep 10 12:01:44 volumio volumio[680]: wlan0 Interface doesn't support scanning. Sep 10 12:01:44 volumio volumio[680]: info: Cannot use regular scanning, forcing with ap-force Sep 10 12:01:44 volumio sudo[1010]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Sep 10 12:01:44 volumio sudo[1010]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:44 volumio sudo[1010]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:44 volumio volumio[680]: command failed: No such device (-19) Sep 10 12:01:44 volumio volumio[680]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Sep 10 12:01:44 volumio volumio[680]: command failed: No such device (-19) Sep 10 12:01:45 volumio volumio[680]: info: CoreStateMachine::setRepeat null single undefined Sep 10 12:01:45 volumio volumio[680]: info: CoreStateMachine::pushState Sep 10 12:01:45 volumio volumio[680]: info: CorePlayQueue::getTrack 0 Sep 10 12:01:45 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 10 12:01:45 volumio ntpd[626]: Listen normally on 4 eth0 169.254.50.187:123 Sep 10 12:01:45 volumio ntpd[626]: new interface(s) found: waking up resolver Sep 10 12:01:45 volumio volumio[680]: info: CoreCommandRouter::volumioPushState Sep 10 12:01:45 volumio volumio[680]: info: CoreStateMachine::setRandom null Sep 10 12:01:45 volumio volumio[680]: info: CoreStateMachine::pushState Sep 10 12:01:45 volumio volumio[680]: info: CorePlayQueue::getTrack 0 Sep 10 12:01:45 volumio volumio[680]: info: CoreCommandRouter::volumioPushState Sep 10 12:01:45 volumio volumio[680]: info: Setting Device type: Raspberry PI Sep 10 12:01:45 volumio volumio[680]: info: VolumeController:: Volume=100 Mute =false Sep 10 12:01:45 volumio volumio[680]: info: CoreStateMachine::pushState Sep 10 12:01:45 volumio volumio[680]: info: CorePlayQueue::getTrack 0 Sep 10 12:01:45 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 10 12:01:45 volumio volumio[680]: info: CoreCommandRouter::volumioPushState Sep 10 12:01:45 volumio volumio[680]: info: CoreStateMachine::updateTrackBlock Sep 10 12:01:45 volumio volumio[680]: info: CorePlayQueue::getTrackBlock Sep 10 12:01:45 volumio volumio[680]: info: CoreCommandRouter::volumioRetrievevolume Sep 10 12:01:45 volumio volumio[680]: info: Completed loading Core Plugins Sep 10 12:01:45 volumio volumio[680]: info: Preparing to generate the ALSA configuration file Sep 10 12:01:46 volumio volumio[680]: info: Asound.conf file unchanged, so no further update is needed Sep 10 12:01:46 volumio volumio[680]: info: Output device has changed, restarting MPD Sep 10 12:01:46 volumio sudo[1047]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 10 12:01:46 volumio sudo[1047]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:46 volumio volumio[680]: info: ___________ START PLUGINS ___________ Sep 10 12:01:46 volumio sudo[1047]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:46 volumio volumio[680]: info: ControllerMpd::onStart: Initializing MPD Sep 10 12:01:46 volumio volumio[680]: info: Creating MPD Configuration file Sep 10 12:01:46 volumio sudo[1049]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 10 12:01:46 volumio sudo[1049]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:46 volumio systemd[1]: Stopping Music Player Daemon... Sep 10 12:01:46 volumio sudo[1053]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 10 12:01:46 volumio sudo[1053]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:46 volumio sudo[1053]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 10 12:01:46 volumio volumio[680]: info: [1757498506339] CoreMusicLibrary::Adding element Last_100 Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 10 12:01:46 volumio volumio[680]: info: [1757498506351] CoreMusicLibrary::Adding element Webradio Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 10 12:01:46 volumio volumio[680]: info: Initializing BBC Radios Sep 10 12:01:46 volumio sudo[1056]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 10 12:01:46 volumio sudo[1056]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 12:01:46 volumio systemd[1]: mpd.service: Succeeded. Sep 10 12:01:46 volumio systemd[1]: Stopped Music Player Daemon. Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 10 12:01:46 volumio volumio[680]: info: [1757498506617] CoreMusicLibrary::Adding element Mixcloud Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 10 12:01:46 volumio volumio[680]: Cannot find translation for source Mixcloud Sep 10 12:01:46 volumio systemd[1]: Starting Music Player Daemon... Sep 10 12:01:46 volumio volumio[680]: info: Creating Spotify config file Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:46 volumio sudo[1068]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 10 12:01:46 volumio sudo[1068]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 10 12:01:46 volumio volumio[680]: info: [1757498506982] CoreMusicLibrary::Adding element Mother Earth Radio Sep 10 12:01:46 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 10 12:01:46 volumio volumio[680]: Cannot find translation for source Mixcloud Sep 10 12:01:46 volumio volumio[680]: Cannot find translation for source Mother Earth Radio Sep 10 12:01:46 volumio sudo[1068]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 10 12:01:47 volumio volumio[680]: info: [1757498507014] CoreMusicLibrary::Adding element Podcast Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 10 12:01:47 volumio volumio[680]: Cannot find translation for source Mixcloud Sep 10 12:01:47 volumio volumio[680]: Cannot find translation for source Mother Earth Radio Sep 10 12:01:47 volumio volumio[680]: Cannot find translation for source Podcast Sep 10 12:01:47 volumio volumio[680]: info: Volumio Calling Home Sep 10 12:01:47 volumio volumio[680]: info: MPD Permissions set Sep 10 12:01:47 volumio volumio[680]: info: MPD Permissions set Sep 10 12:01:47 volumio volumio[680]: info: VolumeController:: Volume=100 Mute =false Sep 10 12:01:47 volumio volumio[680]: info: CoreStateMachine::pushState Sep 10 12:01:47 volumio volumio[680]: info: CorePlayQueue::getTrack 0 Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::volumioPushState Sep 10 12:01:47 volumio volumio[680]: info: Spotify config file written Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 10 12:01:47 volumio sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: No need to fix Spotify hosts Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 12:01:47 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:01:47 volumio systemd[1]: Started go-librespot Daemon. Sep 10 12:01:47 volumio sudo[1075]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:47 volumio go-librespot[1082]: go-librespot daemon starting... Sep 10 12:01:48 volumio go-librespot[1082]: time="2025-09-10T12:01:48+02:00" level=info msg="running go-librespot 0.3.2" Sep 10 12:01:48 volumio go-librespot[1082]: time="2025-09-10T12:01:48+02:00" level=debug msg="app state loaded" Sep 10 12:01:48 volumio go-librespot[1082]: time="2025-09-10T12:01:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 10 12:01:50 volumio mpd[1070]: Sep 10 12:01 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 10 12:01:50 volumio systemd[1]: Started Music Player Daemon. Sep 10 12:01:50 volumio sudo[1056]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:50 volumio sudo[1049]: pam_unix(sudo:session): session closed for user root Sep 10 12:01:50 volumio volumio[680]: info: Completed starting Core Plugins Sep 10 12:01:50 volumio volumio[680]: info: ------------------------------------------- Sep 10 12:01:50 volumio volumio[680]: info: ----- MyVolumio plugins startup ---- Sep 10 12:01:50 volumio volumio[680]: info: ------------------------------------------- Sep 10 12:01:50 volumio volumio[680]: info: [MyVolumio PluginManager] Fetching plans data.... Sep 10 12:01:50 volumio volumio[680]: info: MPD running with PID1070 Sep 10 12:01:50 volumio volumio[680]: ,establishing connection Sep 10 12:01:50 volumio volumio[680]: error: MPD error: The expression evaluated to a falsy value: Sep 10 12:01:50 volumio volumio[680]: assert.ok(self.idling) Sep 10 12:01:50 volumio volumio[680]: error: The expression evaluated to a falsy value: Sep 10 12:01:50 volumio volumio[680]: assert.ok(self.idling) Sep 10 12:01:50 volumio volumio[680]: error: MPD error: The expression evaluated to a falsy value: Sep 10 12:01:50 volumio volumio[680]: assert.ok(self.idling) Sep 10 12:01:50 volumio volumio[680]: error: The expression evaluated to a falsy value: Sep 10 12:01:50 volumio volumio[680]: assert.ok(self.idling) Sep 10 12:01:50 volumio volumio[680]: info: go-librespot daemon successfully initialized Sep 10 12:01:50 volumio volumio[680]: error: updateQueue error: null Sep 10 12:01:51 volumio systemd[1]: systemd-timedated.service: Succeeded. Sep 10 12:01:51 volumio volumio-remote-updater[449]: [2025-09-10 12:01:51] [connect] Successful connection Sep 10 12:01:51 volumio volumio-remote-updater[449]: [2025-09-10 12:01:51] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1757498511 101 Sep 10 12:01:51 volumio volumio[680]: 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 Sep 10 12:01:52 volumio volumio[680]: info: Volumio Network Manager: Network status updated: 1 Sep 10 12:01:53 volumio volumio[680]: info: Initializing connection to go-librespot Websocket Sep 10 12:01:55 volumio volumio[680]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Sep 10 12:01:55 volumio kernel: hwmon hwmon1: Voltage normalised Sep 10 12:02:01 volumio dhcpcd[718]: eth0: offered 192.168.1.100 from 192.168.1.1 Sep 10 12:02:02 volumio dhcpcd[718]: eth0: probing address 192.168.1.100/24 Sep 10 12:02:06 volumio volumio[680]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo ENOTFOUND oauth-performer.prod.vlmapi.io Sep 10 12:02:06 volumio volumio[680]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Sep 10 12:02:08 volumio dhcpcd[718]: eth0: leased 192.168.1.100 for 86400 seconds Sep 10 12:02:08 volumio avahi-daemon[467]: Registering new address record for 192.168.1.100 on eth0.IPv4. Sep 10 12:02:08 volumio dhcpcd[718]: eth0: adding route to 192.168.1.0/24 Sep 10 12:02:08 volumio dhcpcd[718]: eth0: changing default route via 192.168.1.1 Sep 10 12:02:08 volumio dhcpcd[718]: eth0: deleting route to 169.254.0.0/16 Sep 10 12:02:08 volumio avahi-daemon[467]: Withdrawing address record for 169.254.50.187 on eth0. Sep 10 12:02:08 volumio avahi-daemon[467]: Leaving mDNS multicast group on interface eth0.IPv4 with address 169.254.50.187. Sep 10 12:02:08 volumio avahi-daemon[467]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.100. Sep 10 12:02:08 volumio kernel: hwmon hwmon1: Undervoltage detected! Sep 10 12:02:08 volumio dhcpcd[718]: eth0: pid 718 deleted default route via 192.168.1.1 Sep 10 12:02:08 volumio go-librespot[1082]: time="2025-09-10T12:02:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Sep 10 12:02:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 10 12:02:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 10 12:02:09 volumio ntpd[626]: Listen normally on 5 eth0 192.168.1.100:123 Sep 10 12:02:09 volumio ntpd[626]: Deleting interface #4 eth0, 169.254.50.187#123, interface stats: received=0, sent=0, dropped=0, active_time=24 secs Sep 10 12:02:09 volumio ntpd[626]: new interface(s) found: waking up resolver Sep 10 12:02:10 volumio dhcpcd[718]: eth0: hardware address 2e:dd:4f:c1:b2:9e claims 192.168.1.100 Sep 10 12:02:10 volumio dhcpcd[718]: eth0: hardware address 2e:dd:4f:c1:b2:9e claims 192.168.1.100 Sep 10 12:02:10 volumio dhcpcd[718]: eth0: 10 second defence failed for 192.168.1.100 Sep 10 12:02:10 volumio dhcpcd[718]: eth0: deleting route to 192.168.1.0/24 Sep 10 12:02:10 volumio avahi-daemon[467]: Withdrawing address record for 192.168.1.100 on eth0. Sep 10 12:02:10 volumio avahi-daemon[467]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.100. Sep 10 12:02:10 volumio avahi-daemon[467]: Interface eth0.IPv4 no longer relevant for mDNS. Sep 10 12:02:10 volumio volumio[680]: info: Discovery: A device disappeared from network Sep 10 12:02:10 volumio volumio[680]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Sep 10 12:02:10 volumio volumio[680]: error: MyVolumio Plugin failed to start in a timely fashion Sep 10 12:02:10 volumio dhcpcd[718]: eth0: rebinding lease of 192.168.1.100 Sep 10 12:02:10 volumio volumio[680]: [Metrics] CommandRouter: 46s 11.07ms Sep 10 12:02:10 volumio volumio[680]: info: CoreCommandRouter::volumiosetStartupVolume Sep 10 12:02:10 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 10 12:02:10 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 12:02:10 volumio volumio[680]: info: CoreCommandRouter::Close All Modals sent Sep 10 12:02:10 volumio volumio[680]: info: CoreCommandRouter::Close All Modals sent Sep 10 12:02:10 volumio dhcpcd[718]: eth0: probing address 192.168.1.100/24 Sep 10 12:02:11 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Sep 10 12:02:11 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Sep 10 12:02:11 volumio ntpd[626]: Deleting interface #5 eth0, 192.168.1.100#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Sep 10 12:02:11 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Sep 10 12:02:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 10 12:02:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Sep 10 12:02:11 volumio systemd[1]: Stopped go-librespot Daemon. Sep 10 12:02:11 volumio systemd[1]: Started go-librespot Daemon. Sep 10 12:02:11 volumio go-librespot[1224]: go-librespot daemon starting... Sep 10 12:02:11 volumio go-librespot[1224]: time="2025-09-10T12:02:11+02:00" level=info msg="running go-librespot 0.3.2" Sep 10 12:02:11 volumio go-librespot[1224]: time="2025-09-10T12:02:11+02:00" level=debug msg="app state loaded" Sep 10 12:02:11 volumio go-librespot[1224]: time="2025-09-10T12:02:11+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 10 12:02:11 volumio go-librespot[1224]: time="2025-09-10T12:02:11+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Sep 10 12:02:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 10 12:02:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 10 12:02:11 volumio volumio[680]: info: Error connecting to go-librespot Websocket: Error: connect ECONNRESET 127.0.0.1:9879 Sep 10 12:02:12 volumio volumio[680]: info: CoreCommandRouter::volumioGetState Sep 10 12:02:12 volumio volumio[680]: info: CorePlayQueue::getTrack 0 Sep 10 12:02:12 volumio volumio[680]: info: Volumio Network Manager: Network status updated: 0 Sep 10 12:02:14 volumio kernel: hwmon hwmon1: Voltage normalised Sep 10 12:02:14 volumio volumio[680]: info: Initializing connection to go-librespot Websocket Sep 10 12:02:14 volumio volumio[680]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 10 12:02:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 10 12:02:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Sep 10 12:02:15 volumio systemd[1]: Stopped go-librespot Daemon. Sep 10 12:02:15 volumio systemd[1]: Started go-librespot Daemon. Sep 10 12:02:15 volumio go-librespot[1246]: go-librespot daemon starting... Sep 10 12:02:15 volumio go-librespot[1246]: time="2025-09-10T12:02:15+02:00" level=info msg="running go-librespot 0.3.2" Sep 10 12:02:15 volumio go-librespot[1246]: time="2025-09-10T12:02:15+02:00" level=debug msg="app state loaded" Sep 10 12:02:15 volumio go-librespot[1246]: time="2025-09-10T12:02:15+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 10 12:02:15 volumio go-librespot[1246]: time="2025-09-10T12:02:15+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Sep 10 12:02:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 10 12:02:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 10 12:02:15 volumio volumio[680]: info: Discovery: Browse raised the following error Error: getaddrinfo -3008 Sep 10 12:02:15 volumio dhcpcd[718]: eth0: leased 192.168.1.100 for 86400 seconds Sep 10 12:02:15 volumio dhcpcd[718]: eth0: adding route to 192.168.1.0/24 Sep 10 12:02:15 volumio dhcpcd[718]: eth0: adding default route via 192.168.1.1 Sep 10 12:02:15 volumio avahi-daemon[467]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.100. Sep 10 12:02:15 volumio avahi-daemon[467]: New relevant interface eth0.IPv4 for mDNS. Sep 10 12:02:15 volumio avahi-daemon[467]: Registering new address record for 192.168.1.100 on eth0.IPv4. Sep 10 12:02:16 volumio kernel: hwmon hwmon1: Undervoltage detected! Sep 10 12:02:16 volumio volumio[680]: info: Discovery: adding d3febc70-da14-42b5-b34e-30f5c724d999 Sep 10 12:02:16 volumio volumio[680]: info: Discovery: Found device Volumio Sep 10 12:02:16 volumio volumio[680]: info: CoreCommandRouter::volumioGetState Sep 10 12:02:16 volumio volumio[680]: info: CorePlayQueue::getTrack 0 Sep 10 12:02:17 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 10 12:02:17 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 12:02:17 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 10 12:02:17 volumio volumio[680]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=3.832&uuid=f52a2aaef50397b00dda09c5b7784019" http://updates.volumio.org/downloader-v1/track-device Sep 10 12:02:17 volumio volumio[680]: % Total % Received % Xferd Average Speed Time Time Time Current Sep 10 12:02:17 volumio volumio[680]: Dload Upload Total Spent Left Speed Sep 10 12:02:17 volumio volumio[680]: [1.6K blob data] Sep 10 12:02:17 volumio volumio[680]: retrying in 5 seconds, trial 0 Sep 10 12:02:17 volumio volumio[680]: info: Volumio Calling Home Sep 10 12:02:17 volumio volumio[680]: info: Volumio called home Sep 10 12:02:17 volumio volumio[680]: info: BOOT COMPLETED Sep 10 12:02:17 volumio ntpd[626]: Listen normally on 6 eth0 192.168.1.100:123 Sep 10 12:02:17 volumio ntpd[626]: new interface(s) found: waking up resolver Sep 10 12:02:18 volumio volumio[680]: info: Initializing connection to go-librespot Websocket Sep 10 12:02:18 volumio volumio[680]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 10 12:02:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 10 12:02:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Sep 10 12:02:18 volumio systemd[1]: Stopped go-librespot Daemon. Sep 10 12:02:18 volumio systemd[1]: Started go-librespot Daemon. Sep 10 12:02:18 volumio go-librespot[1280]: go-librespot daemon starting... Sep 10 12:02:18 volumio go-librespot[1280]: time="2025-09-10T12:02:18+02:00" level=info msg="running go-librespot 0.3.2" Sep 10 12:02:18 volumio go-librespot[1280]: time="2025-09-10T12:02:18+02:00" level=debug msg="app state loaded" Sep 10 12:02:18 volumio go-librespot[1280]: time="2025-09-10T12:02:18+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 10 12:02:18 volumio ntpd[626]: Soliciting pool server 152.53.44.250 Sep 10 12:02:18 volumio ntpd[626]: Soliciting pool server 131.130.251.107 Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=info msg="zeroconf server listening on port 35695" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=debug msg="obtained new client token: AAACPeS9PZ2M8Zq8/vVrAA4Uv80Gf+J5VY/Fe1zgILuAV5MNNxaeHC8ipEyL8jOlQBa8kSjnESSqiuUQLF2jvMcVy9RWVydE6QQ0pFrSXMuzpuVyenF8LGPfRHPpvdKbPm4EE3ByH3BFc1hOLZJBmWRwKm1GvjvgzoFF+9WkOb5zBOJm6EqUPoMJbjfDDTUHJt7oQ/8ag2r3Zhp1jGx0/OtWEAUjP4bpa5ipktMNvcFLx6Y7VvkakwytYEQ=" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 10 12:02:19 volumio ntpd[626]: Soliciting pool server 152.53.119.76 Sep 10 12:02:19 volumio ntpd[626]: Soliciting pool server 178.251.64.52 Sep 10 12:02:19 volumio ntpd[626]: Soliciting pool server 162.159.200.1 Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=debug msg="completed keyexchange" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=debug msg="completed challenge" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=info msg="authenticated AP" username="jj*****tr" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=info msg="authenticated Login5" username="jj*****tr" Sep 10 12:02:19 volumio go-librespot[1280]: time="2025-09-10T12:02:19+02:00" level=debug msg="initializing zeroconf session" username="jj*****tr" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=debug msg="dealer connection opened" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=trace msg="starting accesspoint recv loop" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=trace msg="starting dealer recv loop" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=trace msg="received accesspoint ping" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=debug msg="received connection id: YWNhYmM1MTYtZTQ4...NDUzRTQzNkI3RA==" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=trace msg="received accesspoint pong ack" Sep 10 12:02:20 volumio go-librespot[1280]: time="2025-09-10T12:02:20+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 10 12:02:20 volumio ntpd[626]: Soliciting pool server 94.199.174.89 Sep 10 12:02:20 volumio ntpd[626]: Soliciting pool server 83.215.130.11 Sep 10 12:02:20 volumio ntpd[626]: Soliciting pool server 46.102.157.67 Sep 10 12:02:20 volumio ntpd[626]: Soliciting pool server 152.53.15.127 Sep 10 12:02:21 volumio volumio[680]: info: Initializing connection to go-librespot Websocket Sep 10 12:02:21 volumio go-librespot[1280]: time="2025-09-10T12:02:21+02:00" level=debug msg="new websocket client" Sep 10 12:02:21 volumio volumio[680]: info: Connection to go-librespot Websocket established Sep 10 12:02:21 volumio ntpd[626]: Soliciting pool server 185.144.161.170 Sep 10 12:02:21 volumio ntpd[626]: Soliciting pool server 83.137.41.14 Sep 10 12:02:21 volumio ntpd[626]: Soliciting pool server 91.206.8.36 Sep 10 12:02:21 volumio ntpd[626]: Soliciting pool server 86.59.113.124 Sep 10 12:02:22 volumio volumio[680]: info: Volumio Network Manager: Network status updated: 1 Sep 10 12:02:22 volumio ntpd[626]: Soliciting pool server 78.41.116.149 Sep 10 12:02:22 volumio ntpd[626]: Soliciting pool server 2a0a:4cc0:c0:1264:c4b0:eaff:fe65:e4bf Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Sep 10 12:02:23 volumio volumio[680]: info: Adding plugin bluetooth to MyMusic Plugins Sep 10 12:02:23 volumio volumio[680]: info: Adding plugin multiroom to MyMusic Plugins Sep 10 12:02:23 volumio volumio[680]: info: Adding plugin metavolumio to MyMusic Plugins Sep 10 12:02:23 volumio volumio[680]: info: Adding plugin cd_controller to MyMusic Plugins Sep 10 12:02:23 volumio volumio[680]: info: Adding plugin qobuzconnect to MyMusic Plugins Sep 10 12:02:23 volumio volumio[680]: info: Adding plugin smart_inputs to MyMusic Plugins Sep 10 12:02:23 volumio ntpd[626]: Soliciting pool server 91.206.237.2 Sep 10 12:02:23 volumio volumio[680]: info: Adding plugin tidalconnect to MyMusic Plugins Sep 10 12:02:23 volumio volumio[680]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Sep 10 12:02:25 volumio volumio[680]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Sep 10 12:02:25 volumio volumio[680]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Sep 10 12:02:25 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 12:02:25 volumio volumio[680]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 10 12:02:25 volumio volumio[680]: info: Starting MyVolumio Remote Streaming Endpoints Sep 10 12:02:26 volumio volumio[680]: info: MyVolumio login type: Token Sep 10 12:02:26 volumio volumio[680]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Sep 10 12:02:26 volumio volumio[680]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Sep 10 12:02:28 volumio ntpd[626]: receive: Unexpected origin timestamp 0xec6bcb32.92db70c4 does not match aorg 0000000000.00000000 from server@83.137.41.14 xmt 0xec6bcb34.81092556 Sep 10 12:02:28 volumio ntpd[626]: receive: Unexpected origin timestamp 0xec6bcb32.92f0f5d5 does not match aorg 0000000000.00000000 from server@152.53.119.76 xmt 0xec6bcb34.8190fb58 Sep 10 12:02:28 volumio go-librespot[1280]: time="2025-09-10T12:02:28+02:00" level=debug msg="handling transfer player command from bfdb7bc958ef31b1359658f24830262b5fe3fb38" Sep 10 12:02:28 volumio go-librespot[1280]: time="2025-09-10T12:02:28+02:00" level=debug msg="resolved context of track" uri="spotify:album:7oRb9P09X3U4FqHn99Mjh5" Sep 10 12:02:28 volumio go-librespot[1280]: time="2025-09-10T12:02:28+02:00" level=trace msg="fetched new page 0 with 2 items (list: 2)" uri="spotify:album:7oRb9P09X3U4FqHn99Mjh5" Sep 10 12:02:28 volumio go-librespot[1280]: time="2025-09-10T12:02:28+02:00" level=debug msg="loading track (paused: false, position: 137055ms)" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:28 volumio go-librespot[1280]: time="2025-09-10T12:02:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 10 12:02:28 volumio go-librespot[1280]: time="2025-09-10T12:02:28+02:00" level=trace msg="emitting websocket event: will_play" Sep 10 12:02:28 volumio go-librespot[1280]: time="2025-09-10T12:02:28+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 242" Sep 10 12:02:29 volumio go-librespot[1280]: time="2025-09-10T12:02:29+02:00" level=debug msg="selected format OGG_VORBIS_320 (22a52deccf22e80573998dfdce10c6992b801667)" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:29 volumio kernel: hwmon hwmon1: Voltage normalised Sep 10 12:02:29 volumio go-librespot[1280]: time="2025-09-10T12:02:29+02:00" level=debug msg="requested aes key for file 22a52deccf22e80573998dfdce10c6992b801667, gid: 4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:29 volumio go-librespot[1280]: time="2025-09-10T12:02:29+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:29 volumio go-librespot[1280]: time="2025-09-10T12:02:29+02:00" level=debug msg="fetched first chunk of 49, total size is 25421876 bytes" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="fetched chunk 1/48, size: 524288" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="fetched chunk 3/48, size: 524288" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="fetched chunk 2/48, size: 524288" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="fetched chunk 15/48, size: 524288" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="fetched chunk 14/48, size: 524288" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=trace msg="seek to 137055ms (diff: 127ms, samples: 6044125, bytes: 7530300)" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="created new output device" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="fetched chunk 16/48, size: 524288" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="fetched chunk 17/48, size: 524288" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=info msg="loaded track \"Countach - Original\" (paused: false, position: 137055ms, duration: 459427ms, prefetched: false)" uri="spotify:track:4yjoFroiLO7KpM2CDUH2ie" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=trace msg="scheduling prefetch in 292s" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=trace msg="emitting websocket event: metadata" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=trace msg="emitting websocket event: active" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="sending successful reply for dealer request" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 10 12:02:30 volumio go-librespot[1280]: time="2025-09-10T12:02:30+02:00" level=trace msg="emitting websocket event: playing" Sep 10 12:02:31 volumio kernel: hwmon hwmon1: Undervoltage detected! Sep 10 12:02:31 volumio volumio[680]: info: Starting Streaming Service Transparent Proxy Sep 10 12:02:31 volumio volumio[680]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Sep 10 12:02:31 volumio volumio[680]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Sep 10 12:02:31 volumio volumio[680]: info: Streaming services startup Sep 10 12:02:31 volumio volumio[680]: info: Starting Streaming Daemon Sep 10 12:02:31 volumio sudo[1314]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 10 12:02:31 volumio sudo[1314]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 12:02:31 volumio volumio[680]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Sep 10 12:02:31 volumio sudo[1314]: pam_unix(sudo:session): session closed for user root Sep 10 12:02:32 volumio volumio[680]: info: Getting Spotify volume Sep 10 12:02:32 volumio volumio[680]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4yjoFroiLO7KpM2CDUH2ie","play_origin":""}} Sep 10 12:02:32 volumio volumio[680]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4yjoFroiLO7KpM2CDUH2ie","name":"Countach - Original","artist_names":["Butch"],"album_name":"Countach","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02588dfc6454ae649fc1ba886d","position":137055,"duration":459427,"release_date":"year:2018 month:3 day:12","track_number":1,"disc_number":1}} Sep 10 12:02:32 volumio volumio[680]: SPOTIFY: received: {"type":"active","data":null} Sep 10 12:02:32 volumio volumio[680]: info: Aligning Spotify Volume to Volumio Volume Sep 10 12:02:32 volumio volumio[680]: info: CoreCommandRouter::volumioGetState Sep 10 12:02:32 volumio volumio[680]: info: CorePlayQueue::getTrack 0 Sep 10 12:02:32 volumio volumio[680]: info: Setting Spotify Volume from Volumio: 100 Sep 10 12:02:32 volumio volumio[680]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4yjoFroiLO7KpM2CDUH2ie","resume":false,"play_origin":""}} Sep 10 12:02:32 volumio volumio[680]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 10 12:02:32 volumio volumio[680]: TypeError: Cannot read property 'service' of undefined Sep 10 12:02:32 volumio volumio[680]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Sep 10 12:02:32 volumio volumio[680]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Sep 10 12:02:32 volumio volumio[680]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Sep 10 12:02:32 volumio volumio[680]: at WebSocket.emit (events.js:315:20) Sep 10 12:02:32 volumio volumio[680]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Sep 10 12:02:32 volumio volumio[680]: at Receiver.emit (events.js:315:20) Sep 10 12:02:32 volumio volumio[680]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Sep 10 12:02:32 volumio volumio[680]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Sep 10 12:02:32 volumio volumio[680]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Sep 10 12:02:32 volumio volumio[680]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Sep 10 12:02:32 volumio volumio[680]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 10 12:02:33 volumio sudo[1330]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-10 12:01 Sep 10 12:02:33 volumio sudo[1330]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"