-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Fri 2025-12-12 16:07:45 CET. -- Dec 12 16:07:07 volumio systemd-timedated[1033]: Changed local time to Fri Dec 12 16:07:07 2025 Dec 12 16:07:07 volumio sudo[1031]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:07 volumio volumio-time-update[600]: volumio-time-update-util: System time updated successfully. Dec 12 16:07:07 volumio systemd[1]: Starting Daily apt download activities... Dec 12 16:07:07 volumio systemd[1]: Started Volumio Time Update Utility. Dec 12 16:07:07 volumio wireless.js[605]: trying... Dec 12 16:07:07 volumio sudo[1056]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 12 16:07:07 volumio sudo[1056]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:07 volumio sudo[1056]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:08 volumio systemd[1]: apt-daily.service: Succeeded. Dec 12 16:07:08 volumio systemd[1]: Started Daily apt download activities. Dec 12 16:07:08 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Dec 12 16:07:08 volumio wireless.js[605]: trying... Dec 12 16:07:08 volumio dhcpcd[1022]: wlan0: leased 192.168.2.100 for 86400 seconds Dec 12 16:07:08 volumio avahi-daemon[614]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.100. Dec 12 16:07:08 volumio sudo[1122]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Dec 12 16:07:08 volumio sudo[1122]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:08 volumio dhcpcd[1022]: wlan0: adding route to 192.168.2.0/24 Dec 12 16:07:08 volumio avahi-daemon[614]: New relevant interface wlan0.IPv4 for mDNS. Dec 12 16:07:08 volumio dhcpcd[1022]: wlan0: adding default route via 192.168.2.254 Dec 12 16:07:08 volumio avahi-daemon[614]: Registering new address record for 192.168.2.100 on wlan0.IPv4. Dec 12 16:07:08 volumio sudo[1122]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:08 volumio wireless.js[605]: Connected to: ----Van Rossem WIFI Dec 12 16:07:08 volumio wireless.js[605]: ---- Dec 12 16:07:08 volumio sudo[1129]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 16:07:08 volumio sudo[1129]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:08 volumio sudo[1129]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:08 volumio wireless.js[605]: ... joined AP, wlan0 IPv4 is 192.168.2.100, ipV6 is undefined Dec 12 16:07:08 volumio wireless.js[605]: It's done! AP Dec 12 16:07:08 volumio systemd[1]: Started Wireless Services. Dec 12 16:07:08 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Dec 12 16:07:08 volumio systemd[1]: Started Volumio Backend Module. Dec 12 16:07:08 volumio systemd[1]: Started Volumio Cpu Tweaker. Dec 12 16:07:08 volumio systemd[1]: Reached target Multi-User System. Dec 12 16:07:08 volumio systemd[1]: Reached target Graphical Interface. Dec 12 16:07:08 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Dec 12 16:07:08 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Dec 12 16:07:08 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Dec 12 16:07:08 volumio volumio-cpu-tweak[1162]: Setting RT Priority for mpd Dec 12 16:07:08 volumio volumio-remote-updater[596]: [2025-12-12 16:07:08] [info] asio async_connect error: system:111 (Connection refused) Dec 12 16:07:08 volumio volumio-remote-updater[596]: [2025-12-12 16:07:08] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Dec 12 16:07:08 volumio volumio-remote-updater[596]: [2025-12-12 16:07:08] [error] handle_connect error: Underlying Transport Error Dec 12 16:07:08 volumio volumio-cpu-tweak[1162]: pid 35's current scheduling policy: SCHED_OTHER Dec 12 16:07:08 volumio volumio-cpu-tweak[1162]: pid 35's current scheduling priority: 0 Dec 12 16:07:08 volumio volumio-cpu-tweak[1162]: Setting MPD Affinity Dec 12 16:07:08 volumio volumio-cpu-tweak[1162]: pid 3's current affinity mask: f Dec 12 16:07:08 volumio volumio-cpu-tweak[1162]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Dec 12 16:07:08 volumio volumio-cpu-tweak[1162]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Dec 12 16:07:08 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Dec 12 16:07:08 volumio systemd[1]: Started Daily apt upgrade and clean activities. Dec 12 16:07:08 volumio systemd[1]: Startup finished in 14.083s (kernel) + 18.249s (userspace) = 32.333s. Dec 12 16:07:09 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Dec 12 16:07:10 volumio ntpd[777]: Listen normally on 4 wlan0 192.168.2.100:123 Dec 12 16:07:10 volumio ntpd[777]: new interface(s) found: waking up resolver Dec 12 16:07:11 volumio volumio[1161]: info: ------------------------------------------- Dec 12 16:07:11 volumio volumio[1161]: info: ----- Volumio3 ---- Dec 12 16:07:11 volumio volumio[1161]: info: ------------------------------------------- Dec 12 16:07:11 volumio volumio[1161]: info: ----- System startup ---- Dec 12 16:07:11 volumio volumio[1161]: info: ------------------------------------------- Dec 12 16:07:12 volumio volumio[1161]: info: MYVOLUMIO Environment detected Dec 12 16:07:13 volumio volumio[1161]: info: Plugin folders cleanup Dec 12 16:07:13 volumio volumio[1161]: info: Scanning into folder /volumio/app/plugins/ Dec 12 16:07:13 volumio volumio[1161]: info: Scanning category audio_interface Dec 12 16:07:13 volumio volumio[1161]: info: Scanning category miscellanea Dec 12 16:07:13 volumio volumio[1161]: info: Scanning category music_service Dec 12 16:07:13 volumio volumio[1161]: info: Scanning category plugins.json Dec 12 16:07:13 volumio volumio[1161]: info: Scanning category system_controller Dec 12 16:07:13 volumio volumio[1161]: info: Scanning category user_interface Dec 12 16:07:13 volumio volumio[1161]: info: Scanning into folder /data/plugins/ Dec 12 16:07:13 volumio volumio[1161]: info: Scanning category music_service Dec 12 16:07:13 volumio volumio[1161]: info: Plugin folders cleanup completed Dec 12 16:07:13 volumio volumio[1161]: info: ------------------------------------------- Dec 12 16:07:13 volumio volumio[1161]: info: ----- Core plugins startup ---- Dec 12 16:07:13 volumio volumio[1161]: info: ------------------------------------------- Dec 12 16:07:13 volumio volumio[1161]: info: Loading plugins from folder /volumio/app/plugins/ Dec 12 16:07:13 volumio volumio[1161]: info: Adding plugin upnp to MyMusic Plugins Dec 12 16:07:13 volumio volumio[1161]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 12 16:07:13 volumio volumio[1161]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 12 16:07:13 volumio volumio[1161]: info: Loading plugins from folder /data/plugins/ Dec 12 16:07:13 volumio volumio[1161]: info: Loading plugin "system"... Dec 12 16:07:13 volumio volumio[1161]: info: Loading plugin "appearance"... Dec 12 16:07:14 volumio volumio[1161]: info: Loading plugin "network"... Dec 12 16:07:14 volumio volumio[1161]: info: Refreshing Cached IP Addresses Dec 12 16:07:14 volumio sudo[1198]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 12 16:07:14 volumio sudo[1198]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:14 volumio sudo[1200]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 16:07:14 volumio sudo[1198]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:14 volumio sudo[1200]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:14 volumio sudo[1200]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:14 volumio volumio[1161]: info: Loading plugin "services"... Dec 12 16:07:14 volumio volumio[1161]: info: Loading plugin "alsa_controller"... Dec 12 16:07:14 volumio sudo[1209]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 12 16:07:14 volumio sudo[1209]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:14 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 16:07:14 volumio volumio[1161]: info: Loading plugin "wizard"... Dec 12 16:07:14 volumio volumio[1161]: info: Loading plugin "networkfs"... Dec 12 16:07:14 volumio volumio[1161]: info: Starting Udev Watcher for removable devices Dec 12 16:07:15 volumio sudo[1224]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=Ikwoonopnummer69!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.2/music02 /mnt/NAS/music02 Dec 12 16:07:15 volumio sudo[1224]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:15 volumio volumio[1161]: info: Ignoring mount for partition: boot Dec 12 16:07:15 volumio volumio[1161]: info: Ignoring mount for partition: volumio Dec 12 16:07:15 volumio volumio[1161]: info: Ignoring mount for partition: volumio_data Dec 12 16:07:15 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 16:07:15 volumio volumio[1161]: info: Loading plugin "volumio_command_line_client"... Dec 12 16:07:15 volumio volumio[1161]: info: Loading plugin "upnp"... Dec 12 16:07:15 volumio volumio[1161]: info: [1765552035060] Starting Upmpd Daemon Dec 12 16:07:15 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 16:07:15 volumio volumio[1161]: info: Loading plugin "my_music"... Dec 12 16:07:15 volumio volumio[1161]: info: Loading plugin "mpd"... Dec 12 16:07:15 volumio kernel: Key type cifs.spnego registered Dec 12 16:07:15 volumio kernel: Key type cifs.idmap registered Dec 12 16:07:15 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Dec 12 16:07:15 volumio kernel: CIFS: Attempting to mount //192.168.2.2/music02 Dec 12 16:07:15 volumio volumio[1161]: info: Loading plugin "upnp_browser"... Dec 12 16:07:15 volumio sudo[1209]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:16 volumio volumio[1161]: info: Loading plugin "alarm-clock"... Dec 12 16:07:16 volumio volumio[1161]: info: Loading plugin "airplay_emulation"... Dec 12 16:07:16 volumio volumio[1161]: info: Starting Shairport Sync Dec 12 16:07:16 volumio volumio[1161]: info: Loading plugin "last_100"... Dec 12 16:07:16 volumio volumio[1161]: info: Loading plugin "webradio"... Dec 12 16:07:16 volumio volumio[1161]: info: Loading plugin "i2s_dacs"... Dec 12 16:07:16 volumio volumio[1161]: info: Loading plugin "volumiodiscovery"... Dec 12 16:07:16 volumio volumio[1161]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 12 16:07:16 volumio volumio[1161]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 16:07:16 volumio volumio[1161]: *** WARNING *** For more information see Dec 12 16:07:16 volumio node[1161]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 12 16:07:16 volumio volumio[1161]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 12 16:07:16 volumio volumio[1161]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 16:07:16 volumio volumio[1161]: *** WARNING *** For more information see Dec 12 16:07:16 volumio node[1161]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 16:07:16 volumio node[1161]: *** WARNING *** For more information see Dec 12 16:07:16 volumio node[1161]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 12 16:07:16 volumio node[1161]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 16:07:16 volumio node[1161]: *** WARNING *** For more information see Dec 12 16:07:16 volumio volumio[1161]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 12 16:07:16 volumio volumio[1161]: info: Discovery: Started advertising with name: Volumio Dec 12 16:07:16 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 16:07:16 volumio volumio[1161]: info: Loading plugin "spop"... Dec 12 16:07:18 volumio volumio[1161]: info: Loading plugin "outputs"... Dec 12 16:07:18 volumio volumio[1161]: info: Loading plugin "albumart"... Dec 12 16:07:18 volumio volumio[1161]: info: Plugin example_plugin is not enabled Dec 12 16:07:18 volumio volumio[1161]: info: Loading plugin "inputs"... Dec 12 16:07:18 volumio volumio[1161]: info: Loading plugin "updater_comm"... Dec 12 16:07:18 volumio volumio[1161]: info: Plugin mpdemulation is not enabled Dec 12 16:07:18 volumio volumio[1161]: info: Loading plugin "rest_api"... Dec 12 16:07:18 volumio volumio[1161]: info: Loading plugin "websocket"... Dec 12 16:07:18 volumio volumio[1161]: info: Starting Socket.io Server version 2.3.0 Dec 12 16:07:18 volumio volumio[1161]: info: Loading i18n strings for locale nl Dec 12 16:07:18 volumio volumio[1161]: Updating browse sources language Dec 12 16:07:18 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 16:07:18 volumio volumio[1161]: Forking 3 albumart workers Dec 12 16:07:18 volumio volumio-remote-updater[596]: [2025-12-12 16:07:18] [connect] Successful connection Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::initPlayerControls Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: Express server listening on port 3000 Dec 12 16:07:19 volumio volumio[1161]: [Metrics] WebUI: 8s 500.92ms Dec 12 16:07:19 volumio volumio[1161]: info: CoreStateMachine::resetVolumioState Dec 12 16:07:19 volumio volumio[1161]: info: CoreStateMachine::getcurrentVolume Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::volumioRetrievevolume Dec 12 16:07:19 volumio volumio[1161]: info: CoreStateMachine::pushState Dec 12 16:07:19 volumio volumio[1161]: info: CorePlayQueue::getTrack 0 Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::volumioPushState Dec 12 16:07:19 volumio volumio[1161]: info: Volumio Network Manager: Network status updated: 3 Dec 12 16:07:19 volumio volumio-remote-updater[596]: [2025-12-12 16:07:19] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1765552038 101 Dec 12 16:07:19 volumio volumio[1161]: 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 Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:19 volumio volumio[1161]: info: Reloading queue from file Dec 12 16:07:19 volumio volumio[1161]: info: CoreStateMachine::setRepeat null single undefined Dec 12 16:07:19 volumio volumio[1161]: info: CoreStateMachine::pushState Dec 12 16:07:19 volumio volumio[1161]: info: CorePlayQueue::getTrack 0 Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::volumioPushState Dec 12 16:07:19 volumio volumio[1161]: info: CoreStateMachine::setRandom null Dec 12 16:07:19 volumio volumio[1161]: info: CoreStateMachine::pushState Dec 12 16:07:19 volumio volumio[1161]: info: CorePlayQueue::getTrack 0 Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::volumioPushState Dec 12 16:07:19 volumio volumio[1161]: info: Setting Device type: Raspberry PI Dec 12 16:07:19 volumio volumio[1161]: info: Discovery: adding 1cbe26e9-34e3-4c8e-afc5-1ad7d95e4c71 Dec 12 16:07:19 volumio volumio[1161]: info: Discovery: Found device Volumio Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::volumioGetState Dec 12 16:07:19 volumio volumio[1161]: info: CorePlayQueue::getTrack 0 Dec 12 16:07:19 volumio volumio[1161]: info: Discovery: this is already registered, 1cbe26e9-34e3-4c8e-afc5-1ad7d95e4c71 Dec 12 16:07:19 volumio volumio[1161]: info: Discovery: Found device Volumio Dec 12 16:07:19 volumio volumio[1161]: info: CoreCommandRouter::volumioGetState Dec 12 16:07:19 volumio volumio[1161]: info: CorePlayQueue::getTrack 0 Dec 12 16:07:19 volumio volumio[1161]: Starting albumart workers Dec 12 16:07:19 volumio volumio[1161]: Starting albumart workers Dec 12 16:07:19 volumio volumio[1161]: Starting albumart workers Dec 12 16:07:21 volumio sudo[1224]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:21 volumio volumio[1161]: info: Cannot mount NAS music02 at system boot, trial number 1 ,retrying in 5 seconds Dec 12 16:07:21 volumio volumio[1161]: info: Completed loading Core Plugins Dec 12 16:07:21 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Dec 12 16:07:21 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Dec 12 16:07:21 volumio volumio[1161]: info: Preparing to generate the ALSA configuration file Dec 12 16:07:21 volumio volumio[1161]: info: Asound.conf file unchanged, so no further update is needed Dec 12 16:07:21 volumio volumio[1161]: info: Output device has changed, restarting MPD Dec 12 16:07:21 volumio volumio[1161]: info: Output device has changed, restarting Shairport Sync Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:21 volumio sudo[1303]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 16:07:21 volumio sudo[1303]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:21 volumio sudo[1303]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:21 volumio sudo[1305]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 16:07:21 volumio sudo[1305]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:21 volumio volumio[1161]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 16:07:21 volumio volumio[1161]: info: ___________ START PLUGINS ___________ Dec 12 16:07:21 volumio volumio[1161]: info: ControllerMpd::onStart: Initializing MPD Dec 12 16:07:21 volumio volumio[1161]: info: Creating MPD Configuration file Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 16:07:21 volumio volumio[1161]: info: [1765552041654] CoreMusicLibrary::Adding element Media Servers Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 16:07:21 volumio sudo[1313]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 16:07:21 volumio sudo[1313]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:21 volumio sudo[1313]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:21 volumio sudo[1315]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 16:07:21 volumio sudo[1315]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:21 volumio systemd[1]: Listening on mpd.socket. Dec 12 16:07:21 volumio systemd[1]: Starting Music Player Daemon... Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:21 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Dec 12 16:07:21 volumio systemd[1]: mpd.service: Succeeded. Dec 12 16:07:21 volumio systemd[1]: Stopped Music Player Daemon. Dec 12 16:07:21 volumio systemd[1]: Starting Music Player Daemon... Dec 12 16:07:21 volumio volumio[1161]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:21 volumio volumio[1161]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 16:07:21 volumio volumio[1161]: info: [1765552041793] CoreMusicLibrary::Adding element Last_100 Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 16:07:21 volumio volumio[1161]: info: [1765552041797] CoreMusicLibrary::Adding element Webradio Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 16:07:21 volumio volumio[1161]: info: Initializing BBC Radios Dec 12 16:07:21 volumio sudo[1320]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 12 16:07:21 volumio sudo[1320]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:21 volumio sudo[1320]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Dec 12 16:07:21 volumio sudo[1320]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:21 volumio volumio[1161]: info: Creating Spotify config file Dec 12 16:07:21 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: Volumio Calling Home Dec 12 16:07:22 volumio volumio[1161]: info: MPD Permissions set Dec 12 16:07:22 volumio volumio[1161]: info: MPD Permissions set Dec 12 16:07:22 volumio volumio[1161]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 12 16:07:22 volumio volumio[1161]: info: Volumio called home Dec 12 16:07:22 volumio volumio[1161]: info: Spotify config file written Dec 12 16:07:22 volumio sudo[1342]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 12 16:07:22 volumio sudo[1342]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:22 volumio volumio[1161]: info: No need to fix Spotify hosts Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio systemd[1]: Started go-librespot Daemon. Dec 12 16:07:22 volumio go-librespot[1344]: go-librespot daemon starting... Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:07:22 volumio sudo[1342]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:22 volumio volumio[1161]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 12 16:07:22 volumio volumio[1161]: SPOTIFY: BQBr7Saktl-LmGUeiTdwe8UXnTgT0ELTsj5OTM_QxlZBis7eMstJIxEFNr7rxb_v8cY8-1qVngVmxPKCFRSYNy4x0S_v0rtfERuK2C1rUAsctweGYLbMPdyqMQv-LNE2Bp6F9-xkZKwhkdFn4108vAUapvbc0BjuBGv4mlG6fKeNWMR1JgGXHX9vn6VnZSCRSxwT4QW1xhDVP611SmbOJHFUEkdT--1LQRijRyhjZBnj5TavqfUANnTEPTdl1wNvP3fDwJPIr52xhDUxcZIRegcjbobXc9R-qW39Xg Dec 12 16:07:22 volumio volumio[1161]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 12 16:07:22 volumio volumio[1161]: info: New Spotify access token = BQBr7Saktl-LmGUeiTdwe8UXnTgT0ELTsj5OTM_QxlZBis7eMstJIxEFNr7rxb_v8cY8-1qVngVmxPKCFRSYNy4x0S_v0rtfERuK2C1rUAsctweGYLbMPdyqMQv-LNE2Bp6F9-xkZKwhkdFn4108vAUapvbc0BjuBGv4mlG6fKeNWMR1JgGXHX9vn6VnZSCRSxwT4QW1xhDVP611SmbOJHFUEkdT--1LQRijRyhjZBnj5TavqfUANnTEPTdl1wNvP3fDwJPIr52xhDUxcZIRegcjbobXc9R-qW39Xg Dec 12 16:07:22 volumio volumio[1161]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::volumioGetState Dec 12 16:07:22 volumio volumio[1161]: info: CorePlayQueue::getTrack 0 Dec 12 16:07:22 volumio volumio[1161]: info: Starting Shairport Sync Dec 12 16:07:22 volumio volumio[1161]: info: Starting Shairport Sync Dec 12 16:07:22 volumio volumio[1161]: info: Starting Shairport Sync Dec 12 16:07:22 volumio sudo[1357]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 16:07:22 volumio sudo[1357]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:22 volumio sudo[1355]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 16:07:22 volumio sudo[1355]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:22 volumio sudo[1360]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 16:07:22 volumio sudo[1360]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:22 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Dec 12 16:07:22 volumio systemd[1]: shairport-sync.service: Succeeded. Dec 12 16:07:22 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Dec 12 16:07:22 volumio volumio[1161]: SPOTIFY: User informations: {"country":"NL","display_name":"Gerwin van Rossem","email":"gwvanrossem@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/gwvanrossem"},"followers":{"href":null,"total":2},"href":"https://api.spotify.com/v1/users/gwvanrossem","id":"gwvanrossem","images":[{"height":300,"url":"https://scontent-ams2-1.xx.fbcdn.net/v/t39.30808-1/462606013_4116694778617583_719738030014745723_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=104&ccb=1-7&_nc_sid=79bf43&_nc_ohc=Aso1wDTuXpIQ7kNvwHpyoVW&_nc_oc=AdkCHcY0wah2YwcWcXGmQqd2AtgfFFeE4q7Qf3MSmKsRwBE8NcWsHBFJT7XNtj8WTnXh2BKwXhscB3gcrfzRazDY&_nc_zt=24&_nc_ht=scontent-ams2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=aP7-jtgrt1jONzsMau7-Ew&_nc_tpa=Q5bMBQF-Hp7waZn77wm-53rNHkEeRTbbOxF_gXhYfaw9clcy23dIMBH0mik-stShT335qPy8_7vu&oh=00_AfnGF63dQVV1uS-3n3tj9vyEX2nfcE0dZmLeJ0-pXymiqQ&oe=6941ACB6","width":300},{"height":64,"url":"https://scontent-ams2-1.xx.fbcdn.net/v/t39.30808-1/462606013_4116694778617583_719738030014745723_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=104&ccb=1-7&_nc_sid=28885b&_nc_ohc=Aso1wDTuXpIQ7kNvwHpyoVW&_nc_oc=AdkCHcY0wah2YwcWcXGmQqd2AtgfFFeE4q7Qf3MSmKsRwBE8NcWsHBFJT7XNtj8WTnXh2BKwXhscB3gcrfzRazDY&_nc_zt=24&_nc_ht=scontent-ams2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=aP7-jtgrt1jONzsMau7-Ew&_nc_tpa=Q5bMBQGKSZr0PHxgjftZpmrY3vR2ubX4eUs_W-yRimAQWQ5Ec6KngUnU1pjF7wibWc9axXC2qxEb&oh=00_AfmzqjODpgkU6lcxblT7FCzy2y0WrLmsDJj1Pfo8zFc4KA&oe=6941ACB6","width":64}],"product":"premium","type":"user","uri":"spotify:user:gwvanrossem"} Dec 12 16:07:22 volumio volumio[1161]: info: Spotify Successfully logged in Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 16:07:22 volumio volumio[1161]: info: [1765552042762] CoreMusicLibrary::Adding element Spotify Dec 12 16:07:22 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 16:07:22 volumio volumio[1161]: Cannot find translation for source Spotify Dec 12 16:07:22 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Dec 12 16:07:22 volumio sudo[1357]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:22 volumio sudo[1360]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:22 volumio sudo[1355]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:22 volumio volumio[1161]: info: Shairport-Sync Started Dec 12 16:07:22 volumio volumio[1161]: Error adding Membership: Error: addMembership EINVAL Dec 12 16:07:22 volumio volumio[1161]: info: Shairport-Sync Started Dec 12 16:07:22 volumio volumio[1161]: info: Shairport-Sync Started Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01:00" level=debug msg="app state loaded" Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 16:07:23 volumio systemd[1]: systemd-fsckd.service: Succeeded. Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01: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]" Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01: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]" Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01: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]" Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01:00" level=info msg="zeroconf server listening on port 36643" Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01:00" level=debug msg="obtained new client token: AADspnmFlMKwDqMBQy9GEvUYYF+XTUddarun63wPNj9uuaYBzSmEtYUaoD5DhI7bvYbbhi8HvBhhoOYASLvM0g0qLdLhH0f6GxbIIdW21Awg0CFR85z0BXtXIfAb2UN9ZdyKlbYeAHtBHu0rhkmJf79UVjC/Bov9JNf3vfsvJO8DpXDAxhvkP93BPO8q6p+ACugspTLzlXo6jY59++aKK5fbDIo8r2F8hddVkdbvuZl1xDpjLlffCef8hQ==" Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 16:07:23 volumio go-librespot[1344]: time="2025-12-12T16:07:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 12 16:07:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 16:07:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 16:07:25 volumio sudo[1388]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 12 16:07:25 volumio sudo[1388]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:25 volumio sudo[1388]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:25 volumio sudo[1390]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 16:07:25 volumio sudo[1390]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:25 volumio sudo[1390]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:25 volumio sudo[1394]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 12 16:07:25 volumio sudo[1394]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:25 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Dec 12 16:07:25 volumio sudo[1394]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:25 volumio volumio[1161]: info: Upmpdcli Daemon Started Dec 12 16:07:25 volumio volumio[1161]: info: go-librespot daemon successfully initialized Dec 12 16:07:25 volumio mpd[1333]: Dec 12 16:07 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 12 16:07:26 volumio sudo[1398]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=Ikwoonopnummer69!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.2/music02 /mnt/NAS/music02 Dec 12 16:07:26 volumio sudo[1398]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:26 volumio kernel: CIFS: Attempting to mount //192.168.2.2/music02 Dec 12 16:07:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 12 16:07:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 12 16:07:27 volumio systemd[1]: Stopped go-librespot Daemon. Dec 12 16:07:27 volumio systemd[1]: Started go-librespot Daemon. Dec 12 16:07:27 volumio go-librespot[1402]: go-librespot daemon starting... Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01:00" level=debug msg="app state loaded" Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 16:07:27 volumio systemd[1]: Started Music Player Daemon. Dec 12 16:07:27 volumio sudo[1315]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:27 volumio sudo[1305]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:27 volumio volumio[1161]: info: Completed starting Core Plugins Dec 12 16:07:27 volumio volumio[1161]: info: ------------------------------------------- Dec 12 16:07:27 volumio volumio[1161]: info: ----- MyVolumio plugins startup ---- Dec 12 16:07:27 volumio volumio[1161]: info: ------------------------------------------- Dec 12 16:07:27 volumio volumio[1161]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01: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]" Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01: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]" Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01: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]" Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01:00" level=info msg="zeroconf server listening on port 34785" Dec 12 16:07:27 volumio volumio[1396]: Generating RSA private key, 4096 bit long modulus (2 primes) Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01:00" level=debug msg="obtained new client token: AABmHdT8XnPsAzyHFDWwGdHkacYPkOOKV/bVgzKdh4yGM6OxUtjmJakPAtbfmdugD1dr0bOz6fDqE0xqcKSaFukDex4S8g/dnsAGU6o+x1PZ0RPZtcygF2g/I/A1bZdBBkiD0BPYGBMNxKjfc38Wf3mDApMYjPiAo1uqA0hUr/7qhBmksQPgNZkbkZjqHlhRATJ6dz/NQhzDorRKvF06Tm1C86td6TSdi88/NmvhiWhxH4Kuv+bjxxDUWA==" Dec 12 16:07:27 volumio volumio[1161]: error: MPD error: The expression evaluated to a falsy value: Dec 12 16:07:27 volumio volumio[1161]: assert.ok(self.idling) Dec 12 16:07:27 volumio volumio[1161]: error: The expression evaluated to a falsy value: Dec 12 16:07:27 volumio volumio[1161]: assert.ok(self.idling) Dec 12 16:07:27 volumio volumio[1161]: info: MPD running with PID1333 Dec 12 16:07:27 volumio volumio[1161]: ,establishing connection Dec 12 16:07:27 volumio volumio[1161]: error: MPD error: The expression evaluated to a falsy value: Dec 12 16:07:27 volumio volumio[1161]: assert.ok(self.idling) Dec 12 16:07:27 volumio volumio[1161]: error: The expression evaluated to a falsy value: Dec 12 16:07:27 volumio volumio[1161]: assert.ok(self.idling) Dec 12 16:07:27 volumio volumio[1161]: error: updateQueue error: null Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 16:07:27 volumio go-librespot[1402]: time="2025-12-12T16:07:27+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 12 16:07:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 16:07:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 16:07:28 volumio volumio[1161]: info: Initializing connection to go-librespot Websocket Dec 12 16:07:28 volumio volumio[1161]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:07:30 volumio sudo[1431]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 16:07:30 volumio sudo[1431]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:30 volumio sudo[1434]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 16:07:30 volumio sudo[1434]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:30 volumio systemd[1]: Started MPD Monitor Service. Dec 12 16:07:30 volumio sudo[1431]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:30 volumio volumio[1161]: info: Successfully started MPD Monitor Dec 12 16:07:30 volumio systemd[1]: Stopping MPD Monitor Service... Dec 12 16:07:30 volumio systemd[1]: mpd_monitor.service: Main process exited, code=killed, status=15/TERM Dec 12 16:07:30 volumio systemd[1]: mpd_monitor.service: Succeeded. Dec 12 16:07:30 volumio systemd[1]: Stopped MPD Monitor Service. Dec 12 16:07:30 volumio systemd[1]: Started MPD Monitor Service. Dec 12 16:07:30 volumio sudo[1434]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:30 volumio volumio[1161]: info: Successfully started MPD Monitor Dec 12 16:07:30 volumio mpd_monitor.sh[1437]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 16:07:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 12 16:07:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 12 16:07:30 volumio systemd[1]: Stopped go-librespot Daemon. Dec 12 16:07:30 volumio systemd[1]: Started go-librespot Daemon. Dec 12 16:07:30 volumio go-librespot[1441]: go-librespot daemon starting... Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=debug msg="app state loaded" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01: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-gew1.spotify.com:80]" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=info msg="zeroconf server listening on port 44573" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=debug msg="obtained new client token: AAAPBbRHMMkMxp+9NW71YbJPngjDlnfk3loYzGPn94Q+EPmX1jlwPM7i/AHDXdwA/lOZs1ZaYxOuNYACeQR8lVfEmjvr6v4CLDbggQ1ei7hBXSBqAPJdMZDoaD4Oouq0USXe73rxCt8fzjkCtCFStwyDYFuu6NPbyyGd74S3LWG+UtqkCr1hxUxyH4f17lzuMMIP4I2ng4nRu2sUOJ853ZULOtNetgYvUidnXQrpekMjgCNbcKbdA1a/eQ==" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 16:07:30 volumio go-librespot[1441]: time="2025-12-12T16:07:30+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 12 16:07:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 16:07:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 16:07:31 volumio volumio[1161]: info: Initializing connection to go-librespot Websocket Dec 12 16:07:31 volumio volumio[1161]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:07:32 volumio sudo[1398]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:32 volumio volumio[1161]: info: Cannot mount NAS music02 at system boot, trial number 2 ,retrying in 5 seconds Dec 12 16:07:32 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Dec 12 16:07:32 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Dec 12 16:07:33 volumio volumio[1161]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 12 16:07:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 12 16:07:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 12 16:07:34 volumio systemd[1]: Stopped go-librespot Daemon. Dec 12 16:07:34 volumio systemd[1]: Started go-librespot Daemon. Dec 12 16:07:34 volumio go-librespot[1449]: go-librespot daemon starting... Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=debug msg="app state loaded" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01: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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=info msg="zeroconf server listening on port 38115" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=debug msg="obtained new client token: AAD9Vm9wCykBD+aj/s68MwP1/rkDCdIyqmx2vyb93eu+swEnfzVuB/ufeLh7Xs4Zm1f08yy1WiRYAsm7pGMVSAwibfOK6Va8hR4Y8ce34Bu1gJZw8dKJdu/WZYz8GukbQ50o7gDqso88AafUMU3A4Pl6yr6TAN5eSlylClW/iTEhIGIj0rypuP/9r1G+T/M64MmzHcP+JK7dfLKZhF4Wr4AopSuMC+5tj2OI5VkTYJ5h1YHfVeh7iPPwMg==" Dec 12 16:07:34 volumio volumio[1161]: info: Initializing connection to go-librespot Websocket Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Dec 12 16:07:34 volumio go-librespot[1449]: time="2025-12-12T16:07:34+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 12 16:07:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 16:07:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 16:07:34 volumio volumio[1161]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:07:37 volumio systemd[1]: systemd-timedated.service: Succeeded. Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 12 16:07:37 volumio volumio[1161]: info: Adding plugin bluetooth to MyMusic Plugins Dec 12 16:07:37 volumio volumio[1161]: info: Adding plugin multiroom to MyMusic Plugins Dec 12 16:07:37 volumio volumio[1161]: info: Adding plugin metavolumio to MyMusic Plugins Dec 12 16:07:37 volumio volumio[1161]: info: Adding plugin cd_controller to MyMusic Plugins Dec 12 16:07:37 volumio volumio[1161]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 12 16:07:37 volumio volumio[1161]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 12 16:07:37 volumio volumio[1161]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 12 16:07:37 volumio volumio[1161]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 12 16:07:37 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 12 16:07:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 12 16:07:37 volumio systemd[1]: Stopped go-librespot Daemon. Dec 12 16:07:37 volumio systemd[1]: Started go-librespot Daemon. Dec 12 16:07:37 volumio go-librespot[1474]: go-librespot daemon starting... Dec 12 16:07:37 volumio go-librespot[1474]: time="2025-12-12T16:07:37+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 16:07:37 volumio go-librespot[1474]: time="2025-12-12T16:07:37+01:00" level=debug msg="app state loaded" Dec 12 16:07:37 volumio go-librespot[1474]: time="2025-12-12T16:07:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01: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-gew1.spotify.com:80]" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=info msg="zeroconf server listening on port 46455" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="obtained new client token: AACPtWvlPrloS+OnB1ZnhbN1Fjg3Eyh6pN5O56F4esozlZ/eFNxwy++Rsixy394HXR8OgrkwFng1ZkuQyr8LbjGSKDUA+n2tqzw/WSOpl8Ldr48pJzWzEm7n/40HjelS1qBO6eVZEwkkYuVkkZPfLumYAuhLUaae99TtaJ0Zc7urJq5L56qh3EDOcaNEG3xwEIKjEInlw++TpgKZYC0K1U3bjHAEs4rE3KN4HyWwF3v1f9AjGytuCxs=" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="completed keyexchange" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="completed challenge" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=info msg="authenticated AP" username="gw*******em" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=info msg="authenticated Login5" username="gw*******em" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="initializing zeroconf session" username="gw*******em" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="dealer connection opened" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=trace msg="starting accesspoint recv loop" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=trace msg="starting dealer recv loop" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=trace msg="received accesspoint ping" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="received connection id: ZjNiMGI3OWEtYjRh...Mjk4MkJGRDZERg==" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=trace msg="received accesspoint pong ack" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="update volume requested to 65535/65535" Dec 12 16:07:38 volumio volumio[1161]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 12 16:07:38 volumio volumio[1161]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 12 16:07:38 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:38 volumio volumio[1161]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 16:07:38 volumio volumio[1161]: info: Starting MyVolumio Remote Streaming Endpoints Dec 12 16:07:38 volumio volumio[1161]: info: MyVolumio login type: Token Dec 12 16:07:38 volumio volumio[1161]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 12 16:07:38 volumio volumio[1161]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 12 16:07:38 volumio go-librespot[1474]: time="2025-12-12T16:07:38+01:00" level=trace msg="emitting websocket event: volume" Dec 12 16:07:40 volumio volumio[1161]: info: Starting Streaming Service Transparent Proxy Dec 12 16:07:40 volumio volumio[1161]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 12 16:07:40 volumio volumio[1161]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 12 16:07:40 volumio volumio[1161]: info: Streaming services startup Dec 12 16:07:40 volumio volumio[1161]: info: Starting Streaming Daemon Dec 12 16:07:40 volumio sudo[1490]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 12 16:07:40 volumio sudo[1490]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:40 volumio volumio[1161]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 12 16:07:40 volumio sudo[1490]: pam_unix(sudo:session): session closed for user root Dec 12 16:07:40 volumio volumio[1161]: info: Initializing connection to go-librespot Websocket Dec 12 16:07:40 volumio sudo[1498]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=Ikwoonopnummer69!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.2/music02 /mnt/NAS/music02 Dec 12 16:07:40 volumio sudo[1498]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 12 16:07:40 volumio kernel: CIFS: Attempting to mount //192.168.2.2/music02 Dec 12 16:07:40 volumio volumio[1161]: error: Cannot start Volumio Streaming Daemon Dec 12 16:07:40 volumio volumio[1161]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 12 16:07:40 volumio volumio[1161]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 12 16:07:41 volumio go-librespot[1474]: time="2025-12-12T16:07:41+01:00" level=debug msg="new websocket client" Dec 12 16:07:41 volumio volumio[1161]: STREAMING PROXY: Starting server on port 3245 Dec 12 16:07:41 volumio volumio[1161]: Node JS runtime: 14 Dec 12 16:07:42 volumio volumio[1161]: info: Connection to go-librespot Websocket established Dec 12 16:07:42 volumio volumio[1161]: error: MyVolumio Custom Token format not valid, refreshing it Dec 12 16:07:43 volumio go-librespot[1474]: time="2025-12-12T16:07:43+01:00" level=debug msg="handling transfer player command from f9079920594cc73ec3ff4ddf8cdc3a42ae5fd0c6" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="resolved context of track" uri="spotify:album:5lXINIQSfk4t5kD5pdgs1J" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=trace msg="fetched new page 0 with 26 items (list: 26)" uri="spotify:album:5lXINIQSfk4t5kD5pdgs1J" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="loading track (paused: true, position: 49590ms)" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=trace msg="emitting websocket event: will_play" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2208" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="selected format OGG_VORBIS_320 (694ad27bbd4d4d493c77acd4254f8f81a8cf830c)" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="requested aes key for file 694ad27bbd4d4d493c77acd4254f8f81a8cf830c, gid: 7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="fetched first chunk of 16, total size is 8010164 bytes" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=trace msg="seek to 49590ms (diff: 43ms, samples: 2186919, bytes: 1830018)" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="created new output device" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=info msg="loaded track \"Nach dir, Herr, verlanget mich, BWV 150: II. Chorus \\\"Nach dir, Herr, verlanget mich\\\"\" (paused: true, position: 49590ms, duration: 213200ms, prefetched: false)" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=trace msg="emitting websocket event: metadata" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=trace msg="emitting websocket event: active" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="sending successful reply for dealer request" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="fetched chunk 5/15, size: 524288" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=trace msg="emitting websocket event: paused" Dec 12 16:07:44 volumio go-librespot[1474]: time="2025-12-12T16:07:44+01:00" level=debug msg="fetched chunk 6/15, size: 524288" uri="spotify:track:7hFg0waKcv5aWSZHYFcbsS" Dec 12 16:07:45 volumio volumio[1161]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:5lXINIQSfk4t5kD5pdgs1J","uri":"spotify:track:7hFg0waKcv5aWSZHYFcbsS","play_origin":"com.spotify.service.lockscreen.coldstart"}} Dec 12 16:07:45 volumio volumio[1161]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7hFg0waKcv5aWSZHYFcbsS","name":"Nach dir, Herr, verlanget mich, BWV 150: II. Chorus \"Nach dir, Herr, verlanget mich\"","artist_names":["Johann Sebastian Bach","Vox Luminis","Lionel Meunier"],"album_name":"Bach: Actus Tragicus (Cantatas BWV 106, 150, 131, 12)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0254938d6ff347eafc42241d00","position":49590,"duration":213200,"release_date":"year:2016 month:11 day:1","track_number":10,"disc_number":1}} Dec 12 16:07:45 volumio volumio[1161]: SPOTIFY: received: {"type":"active","data":null} Dec 12 16:07:45 volumio volumio[1161]: info: Aligning Spotify Volume to Volumio Volume Dec 12 16:07:45 volumio volumio[1161]: info: CoreCommandRouter::volumioGetState Dec 12 16:07:45 volumio volumio[1161]: info: CorePlayQueue::getTrack 0 Dec 12 16:07:45 volumio volumio[1161]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:5lXINIQSfk4t5kD5pdgs1J","uri":"spotify:track:7hFg0waKcv5aWSZHYFcbsS","play_origin":"com.spotify.service.lockscreen.coldstart"}} Dec 12 16:07:45 volumio volumio[1161]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 16:07:45 volumio volumio[1161]: TypeError: Cannot read property 'service' of undefined Dec 12 16:07:45 volumio volumio[1161]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 12 16:07:45 volumio volumio[1161]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Dec 12 16:07:45 volumio volumio[1161]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 12 16:07:45 volumio volumio[1161]: at WebSocket.emit (events.js:315:20) Dec 12 16:07:45 volumio volumio[1161]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 12 16:07:45 volumio volumio[1161]: at Receiver.emit (events.js:315:20) Dec 12 16:07:45 volumio volumio[1161]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 12 16:07:45 volumio volumio[1161]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 12 16:07:45 volumio volumio[1161]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 12 16:07:45 volumio volumio[1161]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 12 16:07:45 volumio volumio[1161]: at writeOrBuffer (internal/streams/writable.js:358:12) Dec 12 16:07:45 volumio volumio[1161]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Dec 12 16:07:45 volumio volumio[1161]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 12 16:07:45 volumio volumio[1161]: at Socket.emit (events.js:315:20) Dec 12 16:07:45 volumio volumio[1161]: at addChunk (internal/streams/readable.js:309:12) Dec 12 16:07:45 volumio volumio[1161]: at readableAddChunk (internal/streams/readable.js:284:9) Dec 12 16:07:45 volumio volumio[1161]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 16:07:45 volumio sudo[1525]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-12 16:06 Dec 12 16:07:45 volumio sudo[1525]: 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="cc50ad4a2058d01de272214eb33827883bd2b7d8" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="502750e5d54ecf269d25125b622bfabc030fb553" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 12 Nov 2025 06:58:02 PM CET" VOLUMIO_VERSION="3.874" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4ae6504ed6f22e44c01a6e93b16badbd"