Dec 15 16:39:00 volumio volumio[7317]: info: ------------------------------------------- Dec 15 16:39:00 volumio volumio[7317]: info: ----- Volumio3 ---- Dec 15 16:39:00 volumio volumio[7317]: info: ------------------------------------------- Dec 15 16:39:00 volumio volumio[7317]: info: ----- System startup ---- Dec 15 16:39:00 volumio volumio[7317]: info: ------------------------------------------- Dec 15 16:39:00 volumio volumio[7317]: info: MYVOLUMIO Environment detected Dec 15 16:39:00 volumio volumio[7317]: info: Plugin folders cleanup Dec 15 16:39:00 volumio volumio[7317]: info: Scanning into folder /volumio/app/plugins/ Dec 15 16:39:00 volumio volumio[7317]: info: Scanning category audio_interface Dec 15 16:39:00 volumio volumio[7317]: info: Scanning category miscellanea Dec 15 16:39:00 volumio volumio[7317]: info: Scanning category music_service Dec 15 16:39:00 volumio volumio[7317]: info: Scanning category plugins.json Dec 15 16:39:00 volumio volumio[7317]: info: Scanning category system_controller Dec 15 16:39:00 volumio volumio[7317]: info: Scanning category user_interface Dec 15 16:39:00 volumio volumio[7317]: info: Scanning into folder /data/plugins/ Dec 15 16:39:00 volumio volumio[7317]: info: Scanning category music_service Dec 15 16:39:00 volumio volumio[7317]: info: Plugin folders cleanup completed Dec 15 16:39:00 volumio volumio[7317]: info: ------------------------------------------- Dec 15 16:39:00 volumio volumio[7317]: info: ----- Core plugins startup ---- Dec 15 16:39:00 volumio volumio[7317]: info: ------------------------------------------- Dec 15 16:39:00 volumio volumio[7317]: info: Loading plugins from folder /volumio/app/plugins/ Dec 15 16:39:00 volumio volumio[7317]: info: Adding plugin upnp to MyMusic Plugins Dec 15 16:39:00 volumio volumio[7317]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 15 16:39:00 volumio volumio[7317]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 15 16:39:00 volumio volumio[7317]: info: Loading plugins from folder /data/plugins/ Dec 15 16:39:00 volumio volumio[7317]: info: Loading plugin "system"... Dec 15 16:39:00 volumio volumio[7317]: info: Loading plugin "appearance"... Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "network"... Dec 15 16:39:01 volumio volumio[7317]: info: Refreshing Cached IP Addresses Dec 15 16:39:01 volumio sudo[7352]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 15 16:39:01 volumio sudo[7352]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:01 volumio sudo[7354]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 15 16:39:01 volumio sudo[7354]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:01 volumio sudo[7352]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "services"... Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "alsa_controller"... Dec 15 16:39:01 volumio sudo[7362]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 15 16:39:01 volumio sudo[7354]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:01 volumio sudo[7362]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:01 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "wizard"... Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "networkfs"... Dec 15 16:39:01 volumio volumio[7317]: info: Cannot mount NAS Pi5 at system boot, trial number 1 ,retrying in 5 seconds Dec 15 16:39:01 volumio volumio[7317]: info: Starting Udev Watcher for removable devices Dec 15 16:39:01 volumio volumio[7317]: info: Ignoring mount for partition: boot Dec 15 16:39:01 volumio volumio[7317]: info: Ignoring mount for partition: volumio Dec 15 16:39:01 volumio volumio[7317]: info: Ignoring mount for partition: volumio_data Dec 15 16:39:01 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "volumio_command_line_client"... Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "upnp"... Dec 15 16:39:01 volumio volumio[7317]: info: [1765809541502] Starting Upmpd Daemon Dec 15 16:39:01 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "my_music"... Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "mpd"... Dec 15 16:39:01 volumio volumio[7317]: info: Loading plugin "upnp_browser"... Dec 15 16:39:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 15 16:39:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:02 volumio go-librespot[7382]: go-librespot daemon starting... Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=debug msg="app state loaded" Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=info msg="zeroconf server listening on port 37765" Dec 15 16:39:02 volumio volumio[7317]: info: Starting UPNP Browser Dec 15 16:39:02 volumio volumio[7317]: info: Loading plugin "alarm-clock"... Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=debug msg="obtained new client token: AABYJGdfTJ/YhohBByZZEwQcLVfow4Ewf0IxXSWCeY5+u5QPHRlx/OfYvx2JxRP3Fqql8TZMxrf2P1lsBG5xIqPoNMqhPIbIo+LJ/rAZC5AzFJmCs7ReAD+8ECR9A0X2zood9znmO3B5Cih0RrzTZreaSE2crCcPMxNanT42e+8yM535wj85JwHdlFDqS5K1cdtGPfWGNy22gsViNjWqXOpodok3Z8f0Q+fCN+SX4KZk/SXXWmEDPKFj4Ag=" Dec 15 16:39:02 volumio volumio[7317]: info: Loading plugin "airplay_emulation"... Dec 15 16:39:02 volumio volumio[7317]: info: Starting Shairport Sync Dec 15 16:39:02 volumio volumio[7317]: info: Loading plugin "last_100"... Dec 15 16:39:02 volumio volumio[7317]: info: Loading plugin "webradio"... Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:39:02 volumio volumio[7317]: info: Loading plugin "i2s_dacs"... Dec 15 16:39:02 volumio volumio[7317]: info: Loading plugin "volumiodiscovery"... Dec 15 16:39:02 volumio volumio[7317]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:02 volumio volumio[7317]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:02 volumio volumio[7317]: *** WARNING *** For more information see Dec 15 16:39:02 volumio volumio[7317]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:02 volumio volumio[7317]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:02 volumio volumio[7317]: *** WARNING *** For more information see Dec 15 16:39:02 volumio node[7317]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:02 volumio node[7317]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:02 volumio node[7317]: *** WARNING *** For more information see Dec 15 16:39:02 volumio node[7317]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:02 volumio node[7317]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:02 volumio node[7317]: *** WARNING *** For more information see Dec 15 16:39:02 volumio volumio[7317]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=debug msg="completed keyexchange" Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=debug msg="completed challenge" Dec 15 16:39:02 volumio volumio[7317]: info: Discovery: Started advertising with name: Volumio Dec 15 16:39:02 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:02 volumio volumio[7317]: info: Loading plugin "bandcamp"... Dec 15 16:39:02 volumio go-librespot[7383]: time="2025-12-15T16:39:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:39:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:39:03 volumio volumio[7317]: info: Loading plugin "calmradio"... Dec 15 16:39:03 volumio volumio[7317]: info: Loading plugin "spop"... Dec 15 16:39:03 volumio volumio-remote-updater[800]: [2025-12-15 16:39:03] [connect] Successful connection Dec 15 16:39:04 volumio sudo[7362]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:04 volumio volumio[7317]: info: Loading plugin "outputs"... Dec 15 16:39:04 volumio volumio[7317]: info: Loading plugin "albumart"... Dec 15 16:39:04 volumio volumio[7317]: info: Plugin example_plugin is not enabled Dec 15 16:39:04 volumio volumio[7317]: info: Loading plugin "inputs"... Dec 15 16:39:04 volumio volumio[7317]: info: Loading plugin "updater_comm"... Dec 15 16:39:04 volumio volumio[7317]: info: Plugin mpdemulation is not enabled Dec 15 16:39:04 volumio volumio[7317]: info: Loading plugin "rest_api"... Dec 15 16:39:04 volumio volumio[7317]: info: Loading plugin "websocket"... Dec 15 16:39:04 volumio volumio[7317]: info: Starting Socket.io Server version 1.7.4 Dec 15 16:39:04 volumio volumio[7317]: info: Loading plugin "radio_paradise"... Dec 15 16:39:04 volumio volumio[7317]: info: Applying required configuration parameters for plugin radio_paradise Dec 15 16:39:04 volumio volumio[7317]: info: [1765809544579] [RadioParadise] API delay: 5 Dec 15 16:39:04 volumio volumio[7317]: info: Loading i18n strings for locale en Dec 15 16:39:04 volumio volumio[7317]: Updating browse sources language Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:04 volumio volumio[7395]: Forking 3 albumart workers Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::initPlayerControls Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:39:04 volumio volumio[7317]: Express server listening on port 3000 Dec 15 16:39:04 volumio volumio[7317]: [Metrics] WebUI: 4s 688.50ms Dec 15 16:39:04 volumio volumio[7317]: info: CoreStateMachine::resetVolumioState Dec 15 16:39:04 volumio volumio[7317]: info: CoreStateMachine::getcurrentVolume Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::volumioRetrievevolume Dec 15 16:39:04 volumio volumio[7317]: info: Volumio Network Manager: Network status updated: 1 Dec 15 16:39:04 volumio volumio-remote-updater[800]: [2025-12-15 16:39:04] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765809543 101 Dec 15 16:39:04 volumio volumio[7317]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 15 16:39:04 volumio volumio[7317]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Dec 15 16:39:04 volumio volumio[7317]: info: VolumeController:: Volume=undefined Mute =false Dec 15 16:39:04 volumio volumio[7317]: info: CoreStateMachine::pushState Dec 15 16:39:04 volumio volumio[7317]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::volumioPushState Dec 15 16:39:04 volumio volumio[7317]: info: CoreStateMachine::updateTrackBlock Dec 15 16:39:04 volumio volumio[7317]: info: CorePlayQueue::getTrackBlock Dec 15 16:39:04 volumio volumio[7317]: info: CoreCommandRouter::volumioRetrievevolume Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:05 volumio volumio[7317]: info: Reloading queue from file Dec 15 16:39:05 volumio volumio[7317]: info: CoreStateMachine::setRepeat null single undefined Dec 15 16:39:05 volumio volumio[7317]: info: CoreStateMachine::pushState Dec 15 16:39:05 volumio volumio[7317]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioPushState Dec 15 16:39:05 volumio volumio[7317]: info: CoreStateMachine::setRandom false Dec 15 16:39:05 volumio volumio[7317]: info: CoreStateMachine::pushState Dec 15 16:39:05 volumio volumio[7317]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioPushState Dec 15 16:39:05 volumio volumio[7317]: info: Setting Device type: Raspberry PI Dec 15 16:39:05 volumio volumio[7317]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 15 16:39:05 volumio volumio[7317]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03115 Dec 15 16:39:05 volumio volumio[7317]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 15 16:39:05 volumio volumio[7317]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Dec 15 16:39:05 volumio volumio[7317]: info: Completed loading Core Plugins Dec 15 16:39:05 volumio volumio[7317]: info: Preparing to generate the ALSA configuration file Dec 15 16:39:05 volumio volumio[7317]: info: VolumeController:: Volume=undefined Mute =false Dec 15 16:39:05 volumio volumio[7317]: info: CoreStateMachine::pushState Dec 15 16:39:05 volumio volumio[7317]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioPushState Dec 15 16:39:05 volumio volumio[7317]: info: Asound.conf file unchanged, so no further update is needed Dec 15 16:39:05 volumio volumio[7317]: info: Output device has changed, restarting MPD Dec 15 16:39:05 volumio volumio[7317]: info: Output device has changed, restarting Shairport Sync Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:05 volumio sudo[7451]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 15 16:39:05 volumio volumio[7317]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:39:05 volumio volumio[7317]: info: ___________ START PLUGINS ___________ Dec 15 16:39:05 volumio sudo[7451]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:05 volumio sudo[7451]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:05 volumio sudo[7453]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 15 16:39:05 volumio sudo[7453]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:05 volumio volumio[7317]: info: ControllerMpd::onStart: Initializing MPD Dec 15 16:39:05 volumio volumio[7317]: info: Creating MPD Configuration file Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:05 volumio volumio[7317]: info: [1765809545217] CoreMusicLibrary::Adding element Media Servers Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:05 volumio volumio[7317]: info: UPNP Browser: Client initialized successfully Dec 15 16:39:05 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 15 16:39:05 volumio sudo[7463]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 15 16:39:05 volumio sudo[7463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:05 volumio sudo[7461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 15 16:39:05 volumio sudo[7461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:05 volumio sudo[7461]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:05 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 15 16:39:05 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 15 16:39:05 volumio systemd[1]: mpd.service: Consumed 1.935s CPU time. Dec 15 16:39:05 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 15 16:39:05 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 15 16:39:05 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 15 16:39:05 volumio volumio[7317]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:05 volumio volumio[7317]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:05 volumio volumio[7317]: info: [1765809545350] CoreMusicLibrary::Adding element Last_100 Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:05 volumio volumio[7317]: info: [1765809545353] CoreMusicLibrary::Adding element Webradio Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:05 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:39:05 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 15 16:39:05 volumio volumio[7317]: info: Initializing BBC Radios Dec 15 16:39:05 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 15 16:39:05 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 15 16:39:05 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 15 16:39:05 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 15 16:39:05 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 15 16:39:05 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 15 16:39:05 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:05 volumio volumio[7317]: info: [1765809545482] CoreMusicLibrary::Adding element Bandcamp Discover Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:05 volumio volumio[7317]: Cannot find translation for source Bandcamp Discover Dec 15 16:39:05 volumio volumio[7317]: info: Adding Calm Radio to Browse Sources Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:05 volumio volumio[7317]: info: [1765809545497] CoreMusicLibrary::Adding element Calm Radio Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:05 volumio volumio[7317]: Cannot find translation for source Bandcamp Discover Dec 15 16:39:05 volumio volumio[7317]: Cannot find translation for source Calm Radio Dec 15 16:39:05 volumio volumio[7317]: info: Creating Spotify config file Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:05 volumio sudo[7480]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 15 16:39:05 volumio sudo[7480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 15 16:39:05 volumio sudo[7480]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:05 volumio volumio[7406]: Starting albumart workers Dec 15 16:39:05 volumio volumio[7405]: Starting albumart workers Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:05 volumio volumio[7317]: info: [1765809545758] CoreMusicLibrary::Adding element Radio Paradise Dec 15 16:39:05 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:05 volumio volumio[7317]: Cannot find translation for source Bandcamp Discover Dec 15 16:39:05 volumio volumio[7317]: Cannot find translation for source Calm Radio Dec 15 16:39:05 volumio volumio[7317]: Cannot find translation for source Radio Paradise Dec 15 16:39:05 volumio volumio[7317]: info: Volumio Calling Home Dec 15 16:39:05 volumio volumio[7407]: Starting albumart workers Dec 15 16:39:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 15 16:39:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:05 volumio go-librespot[7496]: go-librespot daemon starting... Dec 15 16:39:06 volumio go-librespot[7497]: time="2025-12-15T16:39:06+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:39:06 volumio volumio[7317]: info: Discovery: adding e79cfe37-08d9-42b5-80d9-7214f71f9b1f Dec 15 16:39:06 volumio volumio[7317]: info: Discovery: Found device Volumio Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::volumioGetState Dec 15 16:39:06 volumio volumio[7317]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:06 volumio volumio[7317]: info: Discovery: this is already registered, e79cfe37-08d9-42b5-80d9-7214f71f9b1f Dec 15 16:39:06 volumio volumio[7317]: info: Discovery: Found device Volumio Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::volumioGetState Dec 15 16:39:06 volumio volumio[7317]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:06 volumio volumio[7317]: info: MPD Permissions set Dec 15 16:39:06 volumio volumio[7317]: info: MPD Permissions set Dec 15 16:39:06 volumio volumio[7317]: info: Volumio called home Dec 15 16:39:06 volumio volumio[7317]: info: Spotify config file written Dec 15 16:39:06 volumio sudo[7505]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 15 16:39:06 volumio sudo[7505]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:06 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 15 16:39:06 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 15 16:39:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:06 volumio volumio[7317]: 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 15 16:39:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:06 volumio go-librespot[7507]: go-librespot daemon starting... Dec 15 16:39:06 volumio sudo[7505]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=debug msg="app state loaded" Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:06 volumio volumio[7317]: info: No need to fix Spotify hosts Dec 15 16:39:06 volumio volumio[7317]: info: Cannot mount NAS Pi5 at system boot, trial number 2 ,retrying in 5 seconds Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=info msg="zeroconf server listening on port 45581" Dec 15 16:39:06 volumio volumio[7317]: info: Starting Shairport Sync Dec 15 16:39:06 volumio volumio[7317]: info: Starting Shairport Sync Dec 15 16:39:06 volumio volumio[7317]: info: Starting Shairport Sync Dec 15 16:39:06 volumio sudo[7545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:39:06 volumio sudo[7545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:06 volumio sudo[7547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:39:06 volumio sudo[7547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:06 volumio volumio[7317]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=debug msg="obtained new client token: AAAKlJv2s7KnjUTH+m11Pczy+uim5uclT8Q6lXJn3HL8HvuDfY5VNO9ZZR9m1++vEqduBnefG2UROnn8BrcMPHAQqtXd1APXBmUolE0mRrUtRqX/MioegkLp7Bi7QnSFK8OvNwAXNZg7R/sH3owkqwzC//jfHq7dMEt3q+usj/iJlvad0fDhzlrnGgZAu+7jr2Y39KeHIkTH3tlqeYFokrKBO8twNqVEiPvAIUM6Jz8V1/Ycb+MDqnvreLY=" Dec 15 16:39:06 volumio sudo[7550]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:39:06 volumio sudo[7550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:06 volumio volumio[7317]: SPOTIFY: BQAW8PpTWzgkFxJRCfIiIGah9clkZ5yuoRQIY8sKBYNXbkAtwf2UZo6OcX9C8jXRal5QDu_THxEGdtMaJqBq4rN2d4YzsXUson18KjFKPinzt8lwuUqoe9r2tWzGIv3QGYDgCHmq5lw4KdkwrOwiT7sKTWaiYPguM6eFtCXNyxtkH_nJT2T4lMd8oGpFtwSR1mo8gwGSNPIvhDaM1Nx7n7GUeG_IbfhUSTvh-Rd9MmN7q7lnJOzSXjCPPtjkY2BetlPeNYNLRnid4EaGVenD17KhjdlgLAQOuEP7VXcgF6HRhnZf3A1zxLyS Dec 15 16:39:06 volumio volumio[7317]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 16:39:06 volumio volumio[7317]: info: New Spotify access token = BQAW8PpTWzgkFxJRCfIiIGah9clkZ5yuoRQIY8sKBYNXbkAtwf2UZo6OcX9C8jXRal5QDu_THxEGdtMaJqBq4rN2d4YzsXUson18KjFKPinzt8lwuUqoe9r2tWzGIv3QGYDgCHmq5lw4KdkwrOwiT7sKTWaiYPguM6eFtCXNyxtkH_nJT2T4lMd8oGpFtwSR1mo8gwGSNPIvhDaM1Nx7n7GUeG_IbfhUSTvh-Rd9MmN7q7lnJOzSXjCPPtjkY2BetlPeNYNLRnid4EaGVenD17KhjdlgLAQOuEP7VXcgF6HRhnZf3A1zxLyS Dec 15 16:39:06 volumio volumio[7317]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 15 16:39:06 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 15 16:39:06 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 15 16:39:06 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:39:06 volumio systemd[1]: shairport-sync.service: Consumed 1.687s CPU time. Dec 15 16:39:06 volumio go-librespot[7514]: time="2025-12-15T16:39:06+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:39:06 volumio volumio[7317]: info: CoreCommandRouter::volumioGetState Dec 15 16:39:06 volumio volumio[7317]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:06 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:39:06 volumio sudo[7547]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:06 volumio sudo[7550]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:06 volumio volumio[7317]: info: Shairport-Sync Started Dec 15 16:39:06 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 15 16:39:06 volumio volumio[7317]: Error adding Membership: Error: addMembership EINVAL Dec 15 16:39:06 volumio volumio[7317]: info: Shairport-Sync Started Dec 15 16:39:06 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 15 16:39:06 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:39:06 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:39:06 volumio sudo[7545]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:06 volumio volumio[7317]: info: Shairport-Sync Started Dec 15 16:39:07 volumio volumio[7317]: SPOTIFY: User informations: {"country":"RO","display_name":"N_lu","email":"nmat2002@yahoo.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/i43j2nve71kxpxm8jld8hbo0i"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/i43j2nve71kxpxm8jld8hbo0i","id":"i43j2nve71kxpxm8jld8hbo0i","images":[],"product":"premium","type":"user","uri":"spotify:user:i43j2nve71kxpxm8jld8hbo0i"} Dec 15 16:39:07 volumio volumio[7317]: info: Spotify Successfully logged in Dec 15 16:39:07 volumio volumio[7317]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:07 volumio volumio[7317]: info: [1765809547018] CoreMusicLibrary::Adding element Spotify Dec 15 16:39:07 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:07 volumio volumio[7317]: Cannot find translation for source Bandcamp Discover Dec 15 16:39:07 volumio volumio[7317]: Cannot find translation for source Calm Radio Dec 15 16:39:07 volumio volumio[7317]: Cannot find translation for source Radio Paradise Dec 15 16:39:07 volumio volumio[7317]: Cannot find translation for source Spotify Dec 15 16:39:07 volumio mpd[7492]: 2025-12-15T16:39:07 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 15 16:39:07 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 15 16:39:07 volumio sudo[7463]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:07 volumio sudo[7453]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:07 volumio volumio[7317]: info: Completed starting Core Plugins Dec 15 16:39:07 volumio volumio[7317]: info: ------------------------------------------- Dec 15 16:39:07 volumio volumio[7317]: info: ----- MyVolumio plugins startup ---- Dec 15 16:39:07 volumio volumio[7317]: info: ------------------------------------------- Dec 15 16:39:07 volumio volumio[7317]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 15 16:39:07 volumio volumio[7317]: error: MPD error: The expression evaluated to a falsy value: Dec 15 16:39:07 volumio volumio[7317]: assert.ok(self.idling) Dec 15 16:39:07 volumio volumio[7317]: error: The expression evaluated to a falsy value: Dec 15 16:39:07 volumio volumio[7317]: assert.ok(self.idling) Dec 15 16:39:07 volumio volumio[7317]: error: updateQueue error: null Dec 15 16:39:07 volumio volumio[7317]: info: MPD running with PID7492 Dec 15 16:39:07 volumio volumio[7317]: ,establishing connection Dec 15 16:39:07 volumio volumio[7317]: error: updateQueue error: null Dec 15 16:39:09 volumio go-librespot[7514]: time="2025-12-15T16:39:09+02:00" level=debug msg="completed keyexchange" Dec 15 16:39:09 volumio go-librespot[7514]: time="2025-12-15T16:39:09+02:00" level=debug msg="completed challenge" Dec 15 16:39:09 volumio go-librespot[7514]: time="2025-12-15T16:39:09+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:39:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:39:09 volumio volumio[7317]: info: go-librespot daemon successfully initialized Dec 15 16:39:10 volumio sudo[7575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 15 16:39:10 volumio sudo[7575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:10 volumio sudo[7577]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 15 16:39:10 volumio sudo[7577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:10 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 15 16:39:10 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 15 16:39:10 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 15 16:39:10 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 15 16:39:10 volumio sudo[7577]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:10 volumio sudo[7575]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:10 volumio mpd_monitor.sh[7580]: MPD Monitor Service: Starting MPD Monitor Service Dec 15 16:39:10 volumio volumio[7317]: info: Successfully started MPD Monitor Dec 15 16:39:10 volumio volumio[7317]: info: Successfully started MPD Monitor Dec 15 16:39:11 volumio sudo[7599]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 15 16:39:11 volumio sudo[7599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:11 volumio sudo[7601]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 15 16:39:11 volumio sudo[7601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:11 volumio sudo[7599]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:11 volumio sudo[7601]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:11 volumio sudo[7605]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 15 16:39:11 volumio sudo[7605]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:11 volumio sudo[7605]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:11 volumio volumio[7317]: info: Upmpdcli Daemon Started Dec 15 16:39:11 volumio volumio[7317]: info: Cannot mount NAS Pi5 at system boot, trial number 3 ,retrying in 5 seconds Dec 15 16:39:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 15 16:39:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:12 volumio go-librespot[7607]: go-librespot daemon starting... Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="app state loaded" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=info msg="zeroconf server listening on port 41185" Dec 15 16:39:12 volumio volumio[7317]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="obtained new client token: AABO5N24CNS356tAAZPv31oGW2RgV9zc1WFU5cnjUmVEyW4nwt+rREiK0Nx7dSaqxky9XHFSykNfhI/W3s8AHM7aTb0u4xui+kW1VnHnU+c4UJbyWbbtsLMcECvbWhF9gHGQCjaih4GayhHgtCz8i6VM2wxFq0HNeYf5k4yUS+gvYMZ9wxpmyFL0K+ac9Td1k1xpHIRTZEyPziAB/R+lHfsU3lAgMYf24opv6EeoOCsDHoTpr3LJDdAL5oI=" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="completed keyexchange" Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="completed challenge" Dec 15 16:39:12 volumio volumio[7317]: info: Initializing connection to go-librespot Websocket Dec 15 16:39:12 volumio go-librespot[7608]: time="2025-12-15T16:39:12+02:00" level=debug msg="new websocket client" Dec 15 16:39:12 volumio volumio[7317]: info: Connection to go-librespot Websocket established Dec 15 16:39:14 volumio go-librespot[7608]: time="2025-12-15T16:39:14+02:00" level=info msg="authenticated AP" username="i4*********************0i" Dec 15 16:39:15 volumio volumio[7317]: info: Getting Spotify volume Dec 15 16:39:15 volumio volumio[7317]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 15 16:39:15 volumio volumio[7317]: info: Adding plugin bluetooth to MyMusic Plugins Dec 15 16:39:15 volumio volumio[7317]: info: Adding plugin multiroom to MyMusic Plugins Dec 15 16:39:15 volumio volumio[7317]: info: Adding plugin metavolumio to MyMusic Plugins Dec 15 16:39:15 volumio volumio[7317]: info: Adding plugin cd_controller to MyMusic Plugins Dec 15 16:39:15 volumio volumio[7317]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 15 16:39:15 volumio volumio[7317]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 15 16:39:15 volumio volumio[7317]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 15 16:39:15 volumio volumio[7317]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 15 16:39:16 volumio volumio[7317]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 15 16:39:16 volumio volumio[7317]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 15 16:39:16 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:16 volumio volumio[7317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:16 volumio volumio[7317]: info: Starting MyVolumio Remote Streaming Endpoints Dec 15 16:39:16 volumio volumio[7317]: info: MyVolumio login type: Token Dec 15 16:39:16 volumio volumio[7317]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 15 16:39:16 volumio volumio[7317]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 15 16:39:16 volumio volumio[7317]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 15 16:39:16 volumio volumio[7317]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 15 16:39:16 volumio volumio[7317]: info: Streaming services startup Dec 15 16:39:16 volumio volumio[7317]: info: Starting Streaming Daemon Dec 15 16:39:16 volumio sudo[7622]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 15 16:39:16 volumio sudo[7622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:16 volumio volumio[7317]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 15 16:39:16 volumio sudo[7622]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:16 volumio volumio[7317]: info: Cannot mount NAS Pi5 at system boot, trial number 4 ,retrying in 5 seconds Dec 15 16:39:16 volumio volumio[7317]: error: Cannot start Volumio Streaming Daemon Dec 15 16:39:16 volumio volumio[7317]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 15 16:39:16 volumio volumio[7317]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 15 16:39:16 volumio volumio[7317]: info: CoreCommandRouter::volumioGetState Dec 15 16:39:16 volumio volumio[7317]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:17 volumio volumio[7317]: error: MyVolumio Custom Token format not valid, refreshing it Dec 15 16:39:17 volumio volumio[7317]: error: Cannot refresh My Volumio Token: [object Object] Dec 15 16:39:21 volumio volumio[7317]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Dec 15 16:39:29 volumio go-librespot[7608]: time="2025-12-15T16:39:29+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed requesting login5 endpoint: faield unmarshalling LoginResponse: proto:\u00a0cannot parse invalid wire-format data" Dec 15 16:39:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:39:29 volumio volumio[7317]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 15 16:39:29 volumio volumio[7317]: Error: socket hang up Dec 15 16:39:29 volumio volumio[7317]: at connResetException (node:internal/errors:720:14) Dec 15 16:39:29 volumio volumio[7317]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 15 16:39:29 volumio volumio[7317]: at Socket.emit (node:events:526:35) Dec 15 16:39:29 volumio volumio[7317]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 15 16:39:29 volumio volumio[7317]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 15 16:39:29 volumio volumio[7317]: code: 'ECONNRESET', Dec 15 16:39:29 volumio volumio[7317]: response: undefined Dec 15 16:39:29 volumio volumio[7317]: } Dec 15 16:39:29 volumio volumio[7317]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 15 16:39:30 volumio sudo[7662]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-15 16:38' Dec 15 16:39:30 volumio sudo[7662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:30 volumio sudo[7662]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:30 volumio volumio-remote-updater[800]: [2025-12-15 16:39:30] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Dec 15 16:39:30 volumio volumio-remote-updater[800]: [2025-12-15 16:39:30] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Dec 15 16:39:30 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:30 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 15 16:39:30 volumio systemd[1]: volumio.service: Consumed 16.941s CPU time. Dec 15 16:39:30 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 15 16:39:30 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 15 16:39:30 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 16. Dec 15 16:39:30 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 15 16:39:30 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 15 16:39:30 volumio systemd[1]: volumio.service: Consumed 16.941s CPU time. Dec 15 16:39:30 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 15 16:39:30 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 15 16:39:32 volumio volumio[7684]: info: ------------------------------------------- Dec 15 16:39:32 volumio volumio[7684]: info: ----- Volumio3 ---- Dec 15 16:39:32 volumio volumio[7684]: info: ------------------------------------------- Dec 15 16:39:32 volumio volumio[7684]: info: ----- System startup ---- Dec 15 16:39:32 volumio volumio[7684]: info: ------------------------------------------- Dec 15 16:39:32 volumio volumio[7684]: info: MYVOLUMIO Environment detected Dec 15 16:39:32 volumio volumio[7684]: info: Plugin folders cleanup Dec 15 16:39:32 volumio volumio[7684]: info: Scanning into folder /volumio/app/plugins/ Dec 15 16:39:32 volumio volumio[7684]: info: Scanning category audio_interface Dec 15 16:39:32 volumio volumio[7684]: info: Scanning category miscellanea Dec 15 16:39:32 volumio volumio[7684]: info: Scanning category music_service Dec 15 16:39:32 volumio volumio[7684]: info: Scanning category plugins.json Dec 15 16:39:32 volumio volumio[7684]: info: Scanning category system_controller Dec 15 16:39:32 volumio volumio[7684]: info: Scanning category user_interface Dec 15 16:39:32 volumio volumio[7684]: info: Scanning into folder /data/plugins/ Dec 15 16:39:32 volumio volumio[7684]: info: Scanning category music_service Dec 15 16:39:32 volumio volumio[7684]: info: Plugin folders cleanup completed Dec 15 16:39:32 volumio volumio[7684]: info: ------------------------------------------- Dec 15 16:39:32 volumio volumio[7684]: info: ----- Core plugins startup ---- Dec 15 16:39:32 volumio volumio[7684]: info: ------------------------------------------- Dec 15 16:39:32 volumio volumio[7684]: info: Loading plugins from folder /volumio/app/plugins/ Dec 15 16:39:32 volumio volumio[7684]: info: Adding plugin upnp to MyMusic Plugins Dec 15 16:39:32 volumio volumio[7684]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 15 16:39:32 volumio volumio[7684]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 15 16:39:32 volumio volumio[7684]: info: Loading plugins from folder /data/plugins/ Dec 15 16:39:32 volumio volumio[7684]: info: Loading plugin "system"... Dec 15 16:39:32 volumio volumio[7684]: info: Loading plugin "appearance"... Dec 15 16:39:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 15 16:39:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:32 volumio go-librespot[7711]: go-librespot daemon starting... Dec 15 16:39:32 volumio go-librespot[7712]: time="2025-12-15T16:39:32+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:39:32 volumio go-librespot[7712]: time="2025-12-15T16:39:32+02:00" level=debug msg="app state loaded" Dec 15 16:39:32 volumio go-librespot[7712]: time="2025-12-15T16:39:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:39:32 volumio go-librespot[7712]: time="2025-12-15T16:39:32+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:39:32 volumio go-librespot[7712]: time="2025-12-15T16:39:32+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:39:32 volumio go-librespot[7712]: time="2025-12-15T16:39:32+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:39:32 volumio go-librespot[7712]: time="2025-12-15T16:39:32+02:00" level=info msg="zeroconf server listening on port 33381" Dec 15 16:39:33 volumio go-librespot[7712]: time="2025-12-15T16:39:33+02:00" level=debug msg="obtained new client token: AACSamIWGKGiFKgKqyGyOHNaH1niz1R07Bld4TO/NcBYzl481G9jT/vIPMWSJcDNpCd7eFvOwFuZDyZFCcy6sv32iV53gUaAViJs9QXbZGWuemPYVnr5r/a6AHv2k4WDVvc1N+yAUO5RQEiPGraIyAiDehqhs+gk1CYUnenO1DG2IxREZ4+DTEvvuYj3SivjXlBfeQjQsEit6g/CfpsaZWRtOR3xHuN1qL73w9EGcMkjx16JjClmEw+5" Dec 15 16:39:33 volumio go-librespot[7712]: time="2025-12-15T16:39:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "network"... Dec 15 16:39:33 volumio volumio[7684]: info: Refreshing Cached IP Addresses Dec 15 16:39:33 volumio sudo[7721]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 15 16:39:33 volumio sudo[7721]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:33 volumio sudo[7723]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 15 16:39:33 volumio sudo[7723]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "services"... Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "alsa_controller"... Dec 15 16:39:33 volumio sudo[7723]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:33 volumio go-librespot[7712]: time="2025-12-15T16:39:33+02:00" level=debug msg="completed keyexchange" Dec 15 16:39:33 volumio go-librespot[7712]: time="2025-12-15T16:39:33+02:00" level=debug msg="completed challenge" Dec 15 16:39:33 volumio sudo[7721]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:33 volumio sudo[7730]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 15 16:39:33 volumio sudo[7730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:33 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "wizard"... Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "networkfs"... Dec 15 16:39:33 volumio volumio[7684]: info: Cannot mount NAS Pi5 at system boot, trial number 1 ,retrying in 5 seconds Dec 15 16:39:33 volumio volumio[7684]: info: Starting Udev Watcher for removable devices Dec 15 16:39:33 volumio volumio[7684]: info: Ignoring mount for partition: boot Dec 15 16:39:33 volumio volumio[7684]: info: Ignoring mount for partition: volumio Dec 15 16:39:33 volumio volumio[7684]: info: Ignoring mount for partition: volumio_data Dec 15 16:39:33 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "volumio_command_line_client"... Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "upnp"... Dec 15 16:39:33 volumio volumio[7684]: info: [1765809573250] Starting Upmpd Daemon Dec 15 16:39:33 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "my_music"... Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "mpd"... Dec 15 16:39:33 volumio volumio[7684]: info: Loading plugin "upnp_browser"... Dec 15 16:39:33 volumio go-librespot[7712]: time="2025-12-15T16:39:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:39:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:39:34 volumio volumio[7684]: info: Starting UPNP Browser Dec 15 16:39:34 volumio volumio[7684]: info: Loading plugin "alarm-clock"... Dec 15 16:39:34 volumio volumio[7684]: info: Loading plugin "airplay_emulation"... Dec 15 16:39:34 volumio volumio[7684]: info: Starting Shairport Sync Dec 15 16:39:34 volumio volumio[7684]: info: Loading plugin "last_100"... Dec 15 16:39:34 volumio volumio[7684]: info: Loading plugin "webradio"... Dec 15 16:39:34 volumio volumio[7684]: info: Loading plugin "i2s_dacs"... Dec 15 16:39:34 volumio volumio[7684]: info: Loading plugin "volumiodiscovery"... Dec 15 16:39:34 volumio volumio[7684]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:34 volumio volumio[7684]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:34 volumio volumio[7684]: *** WARNING *** For more information see Dec 15 16:39:34 volumio volumio[7684]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:34 volumio volumio[7684]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:34 volumio node[7684]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:34 volumio volumio[7684]: *** WARNING *** For more information see Dec 15 16:39:34 volumio node[7684]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:34 volumio node[7684]: *** WARNING *** For more information see Dec 15 16:39:34 volumio node[7684]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:34 volumio node[7684]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:34 volumio node[7684]: *** WARNING *** For more information see Dec 15 16:39:34 volumio volumio[7684]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 15 16:39:34 volumio volumio[7684]: info: Discovery: Started advertising with name: Volumio Dec 15 16:39:34 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:34 volumio volumio[7684]: info: Loading plugin "bandcamp"... Dec 15 16:39:35 volumio volumio[7684]: info: Loading plugin "calmradio"... Dec 15 16:39:35 volumio volumio[7684]: info: Loading plugin "spop"... Dec 15 16:39:35 volumio volumio-remote-updater[800]: [2025-12-15 16:39:35] [connect] Successful connection Dec 15 16:39:35 volumio sudo[7730]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:36 volumio volumio[7684]: info: Loading plugin "outputs"... Dec 15 16:39:36 volumio volumio[7684]: info: Loading plugin "albumart"... Dec 15 16:39:36 volumio volumio[7684]: info: Plugin example_plugin is not enabled Dec 15 16:39:36 volumio volumio[7684]: info: Loading plugin "inputs"... Dec 15 16:39:36 volumio volumio[7684]: info: Loading plugin "updater_comm"... Dec 15 16:39:36 volumio volumio[7684]: info: Plugin mpdemulation is not enabled Dec 15 16:39:36 volumio volumio[7684]: info: Loading plugin "rest_api"... Dec 15 16:39:36 volumio volumio[7684]: info: Loading plugin "websocket"... Dec 15 16:39:36 volumio volumio[7684]: info: Starting Socket.io Server version 1.7.4 Dec 15 16:39:36 volumio volumio[7684]: info: Loading plugin "radio_paradise"... Dec 15 16:39:36 volumio volumio[7684]: info: Applying required configuration parameters for plugin radio_paradise Dec 15 16:39:36 volumio volumio[7684]: info: [1765809576283] [RadioParadise] API delay: 5 Dec 15 16:39:36 volumio volumio[7684]: info: Loading i18n strings for locale en Dec 15 16:39:36 volumio volumio[7684]: Updating browse sources language Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:36 volumio volumio[7753]: Forking 3 albumart workers Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::initPlayerControls Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: Express server listening on port 3000 Dec 15 16:39:36 volumio volumio[7684]: [Metrics] WebUI: 4s 659.67ms Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::resetVolumioState Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::getcurrentVolume Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::volumioRetrievevolume Dec 15 16:39:36 volumio volumio[7684]: info: Volumio Network Manager: Network status updated: 1 Dec 15 16:39:36 volumio volumio[7684]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Dec 15 16:39:36 volumio volumio-remote-updater[800]: [2025-12-15 16:39:36] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765809575 101 Dec 15 16:39:36 volumio volumio[7684]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 15 16:39:36 volumio volumio[7684]: info: VolumeController:: Volume=undefined Mute =false Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::pushState Dec 15 16:39:36 volumio volumio[7684]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::volumioPushState Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::updateTrackBlock Dec 15 16:39:36 volumio volumio[7684]: info: CorePlayQueue::getTrackBlock Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::volumioRetrievevolume Dec 15 16:39:36 volumio volumio[7684]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: Reloading queue from file Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::setRepeat null single undefined Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::pushState Dec 15 16:39:36 volumio volumio[7684]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::volumioPushState Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::setRandom false Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::pushState Dec 15 16:39:36 volumio volumio[7684]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::volumioPushState Dec 15 16:39:36 volumio volumio[7684]: info: Setting Device type: Raspberry PI Dec 15 16:39:36 volumio volumio[7684]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 15 16:39:36 volumio volumio[7684]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03115 Dec 15 16:39:36 volumio volumio[7684]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 15 16:39:36 volumio volumio[7684]: info: Completed loading Core Plugins Dec 15 16:39:36 volumio volumio[7684]: info: Preparing to generate the ALSA configuration file Dec 15 16:39:36 volumio volumio[7684]: info: VolumeController:: Volume=undefined Mute =false Dec 15 16:39:36 volumio volumio[7684]: info: CoreStateMachine::pushState Dec 15 16:39:36 volumio volumio[7684]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::volumioPushState Dec 15 16:39:36 volumio volumio[7684]: info: Discovery: adding e79cfe37-08d9-42b5-80d9-7214f71f9b1f Dec 15 16:39:36 volumio volumio[7684]: info: Discovery: Found device Volumio Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::volumioGetState Dec 15 16:39:36 volumio volumio[7684]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:36 volumio volumio[7684]: info: Asound.conf file unchanged, so no further update is needed Dec 15 16:39:36 volumio volumio[7684]: info: Output device has changed, restarting MPD Dec 15 16:39:36 volumio volumio[7684]: info: Output device has changed, restarting Shairport Sync Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:36 volumio sudo[7811]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 15 16:39:36 volumio sudo[7811]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:36 volumio volumio[7684]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:39:36 volumio volumio[7684]: info: ___________ START PLUGINS ___________ Dec 15 16:39:36 volumio volumio[7684]: info: ControllerMpd::onStart: Initializing MPD Dec 15 16:39:36 volumio volumio[7684]: info: Creating MPD Configuration file Dec 15 16:39:36 volumio sudo[7809]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 15 16:39:36 volumio sudo[7809]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:36 volumio sudo[7809]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:36 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:36 volumio volumio[7684]: info: [1765809576982] CoreMusicLibrary::Adding element Media Servers Dec 15 16:39:36 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:37 volumio sudo[7819]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 15 16:39:37 volumio volumio[7684]: info: UPNP Browser: Client initialized successfully Dec 15 16:39:37 volumio sudo[7819]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:37 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 15 16:39:37 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 15 16:39:37 volumio systemd[1]: mpd.service: Consumed 1.905s CPU time. Dec 15 16:39:37 volumio sudo[7819]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:37 volumio sudo[7821]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 15 16:39:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 15 16:39:37 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 15 16:39:37 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 15 16:39:37 volumio sudo[7821]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:37 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:37 volumio volumio[7684]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:37 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 15 16:39:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:37 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 15 16:39:37 volumio go-librespot[7833]: go-librespot daemon starting... Dec 15 16:39:37 volumio volumio[7684]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:37 volumio volumio[7684]: info: [1765809577084] CoreMusicLibrary::Adding element Last_100 Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:37 volumio volumio[7684]: info: [1765809577087] CoreMusicLibrary::Adding element Webradio Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:39:37 volumio volumio[7684]: info: Initializing BBC Radios Dec 15 16:39:37 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 15 16:39:37 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 15 16:39:37 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 15 16:39:37 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 15 16:39:37 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 15 16:39:37 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 15 16:39:37 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=debug msg="app state loaded" Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:37 volumio volumio[7684]: info: [1765809577235] CoreMusicLibrary::Adding element Bandcamp Discover Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:37 volumio volumio[7684]: Cannot find translation for source Bandcamp Discover Dec 15 16:39:37 volumio volumio[7684]: info: Adding Calm Radio to Browse Sources Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:37 volumio volumio[7684]: info: [1765809577245] CoreMusicLibrary::Adding element Calm Radio Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:37 volumio volumio[7684]: Cannot find translation for source Bandcamp Discover Dec 15 16:39:37 volumio volumio[7684]: Cannot find translation for source Calm Radio Dec 15 16:39:37 volumio volumio[7684]: info: Creating Spotify config file Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:37 volumio sudo[7845]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 15 16:39:37 volumio sudo[7845]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 15 16:39:37 volumio sudo[7845]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=info msg="zeroconf server listening on port 46787" Dec 15 16:39:37 volumio volumio[7765]: Starting albumart workers Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=debug msg="obtained new client token: AABbdRfuWm32KwxhRAqrPzEbsT6ebyuTWF+5+rsB8SA84nD+bitY9pPP1de90l1gjFHvagjQerWYs3O1JYL6s6JHIF9zPKXO18BzGcv3zld7iFH0g1N+/JMPe/N2rhoaNMjhwbJ6KkucrdmAAfZfNnC4pA56Lx4PLfCi9NMLa8ZMvYDr2LJUuQUhGbsJvre54T8UQbKWN9w7ohwEoATDvQHcDn2Jzt35TXzTiVhzrzO/9ugOCNwr902QUsw=" Dec 15 16:39:37 volumio volumio[7763]: Starting albumart workers Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:37 volumio volumio[7684]: info: [1765809577612] CoreMusicLibrary::Adding element Radio Paradise Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:37 volumio volumio[7684]: Cannot find translation for source Bandcamp Discover Dec 15 16:39:37 volumio volumio[7684]: Cannot find translation for source Calm Radio Dec 15 16:39:37 volumio volumio[7764]: Starting albumart workers Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=debug msg="completed keyexchange" Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=debug msg="completed challenge" Dec 15 16:39:37 volumio volumio[7684]: Cannot find translation for source Radio Paradise Dec 15 16:39:37 volumio volumio[7684]: info: Volumio Calling Home Dec 15 16:39:37 volumio go-librespot[7835]: time="2025-12-15T16:39:37+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:39:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:39:37 volumio volumio[7684]: info: Discovery: this is already registered, e79cfe37-08d9-42b5-80d9-7214f71f9b1f Dec 15 16:39:37 volumio volumio[7684]: info: Discovery: Found device Volumio Dec 15 16:39:37 volumio volumio[7684]: info: CoreCommandRouter::volumioGetState Dec 15 16:39:37 volumio volumio[7684]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:38 volumio volumio[7684]: info: MPD Permissions set Dec 15 16:39:38 volumio volumio[7684]: info: MPD Permissions set Dec 15 16:39:38 volumio volumio[7684]: 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 15 16:39:38 volumio volumio[7684]: info: Volumio called home Dec 15 16:39:38 volumio volumio[7684]: info: Spotify config file written Dec 15 16:39:38 volumio sudo[7876]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 15 16:39:38 volumio sudo[7876]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:38 volumio volumio[7684]: info: Cannot mount NAS Pi5 at system boot, trial number 2 ,retrying in 5 seconds Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:39:38 volumio volumio[7684]: info: No need to fix Spotify hosts Dec 15 16:39:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:38 volumio go-librespot[7889]: go-librespot daemon starting... Dec 15 16:39:38 volumio sudo[7876]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=debug msg="app state loaded" Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:39:38 volumio volumio[7684]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 16:39:38 volumio volumio[7684]: SPOTIFY: BQAui3VQp_iNOeylrLvXZDHJ0D3xCbon4YNZRBzBYOgjk7DNFH3IHYGAZwzHFpB39NqzQ15HDtNiFDKrB6qYMUhLwUbvXPsW15BhgcxE8--7hK5nKCoMbcTtgkLAEq4r4gzrAu5_xS70MzR1HNutgPg3p097OcpkXH-hQ7OP7A2pvtSZzXjTMilKrNxwyrxkGpuk4gBB3GHaFpP5duMycOpI5U09LzrWa9D9NNjo1VYRqjqa3OtJ3r088V61vrn_HLA1Otxzv9otxM0xwiuHuDtv6GemTiZ6hve2qGRi5pO9otDTMZUC73pJ Dec 15 16:39:38 volumio volumio[7684]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 16:39:38 volumio volumio[7684]: info: New Spotify access token = BQAui3VQp_iNOeylrLvXZDHJ0D3xCbon4YNZRBzBYOgjk7DNFH3IHYGAZwzHFpB39NqzQ15HDtNiFDKrB6qYMUhLwUbvXPsW15BhgcxE8--7hK5nKCoMbcTtgkLAEq4r4gzrAu5_xS70MzR1HNutgPg3p097OcpkXH-hQ7OP7A2pvtSZzXjTMilKrNxwyrxkGpuk4gBB3GHaFpP5duMycOpI5U09LzrWa9D9NNjo1VYRqjqa3OtJ3r088V61vrn_HLA1Otxzv9otxM0xwiuHuDtv6GemTiZ6hve2qGRi5pO9otDTMZUC73pJ Dec 15 16:39:38 volumio volumio[7684]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 15 16:39:38 volumio volumio[7684]: info: Starting Shairport Sync Dec 15 16:39:38 volumio volumio[7684]: info: Starting Shairport Sync Dec 15 16:39:38 volumio volumio[7684]: info: Starting Shairport Sync Dec 15 16:39:38 volumio sudo[7902]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:39:38 volumio sudo[7902]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:38 volumio sudo[7905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:39:38 volumio sudo[7905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:38 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 15 16:39:38 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 15 16:39:38 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:39:38 volumio systemd[1]: shairport-sync.service: Consumed 1.684s CPU time. Dec 15 16:39:38 volumio sudo[7907]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:39:38 volumio sudo[7907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::volumioGetState Dec 15 16:39:38 volumio volumio[7684]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:38 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:39:38 volumio sudo[7902]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:39:38 volumio volumio[7684]: info: Shairport-Sync Started Dec 15 16:39:38 volumio volumio[7684]: Error adding Membership: Error: addMembership EINVAL Dec 15 16:39:38 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=info msg="zeroconf server listening on port 43365" Dec 15 16:39:38 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 15 16:39:38 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:39:38 volumio volumio[7684]: SPOTIFY: User informations: {"country":"RO","display_name":"N_lu","email":"nmat2002@yahoo.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/i43j2nve71kxpxm8jld8hbo0i"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/i43j2nve71kxpxm8jld8hbo0i","id":"i43j2nve71kxpxm8jld8hbo0i","images":[],"product":"premium","type":"user","uri":"spotify:user:i43j2nve71kxpxm8jld8hbo0i"} Dec 15 16:39:38 volumio volumio[7684]: info: Spotify Successfully logged in Dec 15 16:39:38 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:39:38 volumio volumio[7684]: info: [1765809578643] CoreMusicLibrary::Adding element Spotify Dec 15 16:39:38 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:39:38 volumio volumio[7684]: Cannot find translation for source Bandcamp Discover Dec 15 16:39:38 volumio volumio[7684]: Cannot find translation for source Calm Radio Dec 15 16:39:38 volumio volumio[7684]: Cannot find translation for source Radio Paradise Dec 15 16:39:38 volumio volumio[7684]: Cannot find translation for source Spotify Dec 15 16:39:38 volumio sudo[7905]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:38 volumio sudo[7907]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:38 volumio volumio[7684]: info: Shairport-Sync Started Dec 15 16:39:38 volumio volumio[7684]: info: Shairport-Sync Started Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=debug msg="obtained new client token: AADo2USpN+csa7C2h97pfgvmQm9Gd6QPQzbgvfhCPkYC0JXzJzJpjYch44g5EPIt1D2ctH1fkGGpbEp+bPZWGA5irdDM/vb4ycEQwMiUIC3jihLLFSGFvOUnPk7X3ohSttyZPCOetSzY7uSR9yfM0EK2eHbE14dj5D9tAVbg8Y1FOjGu3HI0FtKKfcvYIop8+dj7EUaq24Ry+i9TCJ6GbG9t1kDlXH7IJ/AkbU2FndcKLz4HMdGvj6P7P1k=" Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=debug msg="completed keyexchange" Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=debug msg="completed challenge" Dec 15 16:39:38 volumio go-librespot[7895]: time="2025-12-15T16:39:38+02:00" level=info msg="authenticated AP" username="i4*********************0i" Dec 15 16:39:39 volumio mpd[7859]: 2025-12-15T16:39:39 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 15 16:39:39 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 15 16:39:39 volumio sudo[7821]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:39 volumio sudo[7811]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:39 volumio volumio[7684]: info: Completed starting Core Plugins Dec 15 16:39:39 volumio volumio[7684]: info: ------------------------------------------- Dec 15 16:39:39 volumio volumio[7684]: info: ----- MyVolumio plugins startup ---- Dec 15 16:39:39 volumio volumio[7684]: info: ------------------------------------------- Dec 15 16:39:39 volumio volumio[7684]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 15 16:39:39 volumio volumio[7684]: error: MPD error: The expression evaluated to a falsy value: Dec 15 16:39:39 volumio volumio[7684]: assert.ok(self.idling) Dec 15 16:39:39 volumio volumio[7684]: error: The expression evaluated to a falsy value: Dec 15 16:39:39 volumio volumio[7684]: assert.ok(self.idling) Dec 15 16:39:39 volumio volumio[7684]: error: updateQueue error: null Dec 15 16:39:39 volumio volumio[7684]: info: MPD running with PID7859 Dec 15 16:39:39 volumio volumio[7684]: ,establishing connection Dec 15 16:39:39 volumio volumio[7684]: error: updateQueue error: null Dec 15 16:39:41 volumio volumio[7684]: info: go-librespot daemon successfully initialized Dec 15 16:39:42 volumio sudo[7936]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 15 16:39:42 volumio sudo[7936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:42 volumio sudo[7938]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 15 16:39:42 volumio sudo[7938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:42 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 15 16:39:42 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 15 16:39:42 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 15 16:39:42 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 15 16:39:42 volumio sudo[7936]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:42 volumio sudo[7938]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:42 volumio mpd_monitor.sh[7941]: MPD Monitor Service: Starting MPD Monitor Service Dec 15 16:39:42 volumio volumio[7684]: info: Successfully started MPD Monitor Dec 15 16:39:42 volumio volumio[7684]: info: Successfully started MPD Monitor Dec 15 16:39:43 volumio volumio[7684]: info: Cannot mount NAS Pi5 at system boot, trial number 3 ,retrying in 5 seconds Dec 15 16:39:43 volumio sudo[7960]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 15 16:39:43 volumio sudo[7960]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:43 volumio sudo[7960]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:43 volumio sudo[7962]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 15 16:39:43 volumio sudo[7962]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:43 volumio sudo[7962]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:43 volumio sudo[7965]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 15 16:39:43 volumio sudo[7965]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:43 volumio sudo[7965]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:43 volumio volumio[7684]: info: Upmpdcli Daemon Started Dec 15 16:39:44 volumio volumio[7684]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 15 16:39:44 volumio volumio[7684]: info: Initializing connection to go-librespot Websocket Dec 15 16:39:44 volumio go-librespot[7895]: time="2025-12-15T16:39:44+02:00" level=debug msg="new websocket client" Dec 15 16:39:44 volumio volumio[7684]: info: Connection to go-librespot Websocket established Dec 15 16:39:47 volumio volumio[7684]: info: Getting Spotify volume Dec 15 16:39:47 volumio volumio[7684]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 15 16:39:47 volumio volumio[7684]: info: CoreCommandRouter::volumioGetState Dec 15 16:39:47 volumio volumio[7684]: info: CorePlayQueue::getTrack 0 Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 15 16:39:47 volumio volumio[7684]: info: Adding plugin bluetooth to MyMusic Plugins Dec 15 16:39:47 volumio volumio[7684]: info: Adding plugin multiroom to MyMusic Plugins Dec 15 16:39:47 volumio volumio[7684]: info: Adding plugin metavolumio to MyMusic Plugins Dec 15 16:39:47 volumio volumio[7684]: info: Adding plugin cd_controller to MyMusic Plugins Dec 15 16:39:47 volumio volumio[7684]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 15 16:39:47 volumio volumio[7684]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 15 16:39:47 volumio volumio[7684]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 15 16:39:47 volumio volumio[7684]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 15 16:39:48 volumio volumio[7684]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 15 16:39:48 volumio volumio[7684]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 15 16:39:48 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:48 volumio volumio[7684]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:39:48 volumio volumio[7684]: info: Starting MyVolumio Remote Streaming Endpoints Dec 15 16:39:48 volumio volumio[7684]: info: MyVolumio login type: Token Dec 15 16:39:48 volumio volumio[7684]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 15 16:39:48 volumio volumio[7684]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 15 16:39:48 volumio volumio[7684]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 15 16:39:48 volumio volumio[7684]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 15 16:39:48 volumio volumio[7684]: info: Streaming services startup Dec 15 16:39:48 volumio volumio[7684]: info: Starting Streaming Daemon Dec 15 16:39:48 volumio sudo[7975]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 15 16:39:48 volumio sudo[7975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:48 volumio volumio[7684]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 15 16:39:48 volumio sudo[7975]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:48 volumio volumio[7684]: info: Cannot mount NAS Pi5 at system boot, trial number 4 ,retrying in 5 seconds Dec 15 16:39:48 volumio volumio[7684]: error: Cannot start Volumio Streaming Daemon Dec 15 16:39:48 volumio volumio[7684]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 15 16:39:48 volumio volumio[7684]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 15 16:39:49 volumio volumio[7684]: error: MyVolumio Custom Token format not valid, refreshing it Dec 15 16:39:49 volumio volumio[7684]: error: Cannot refresh My Volumio Token: [object Object] Dec 15 16:39:53 volumio volumio[7684]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Dec 15 16:39:53 volumio go-librespot[7895]: time="2025-12-15T16:39:53+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: UNKNOWN_ERROR" Dec 15 16:39:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:39:53 volumio volumio[7684]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 15 16:39:53 volumio volumio[7684]: Error: socket hang up Dec 15 16:39:53 volumio volumio[7684]: at connResetException (node:internal/errors:720:14) Dec 15 16:39:53 volumio volumio[7684]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 15 16:39:53 volumio volumio[7684]: at Socket.emit (node:events:526:35) Dec 15 16:39:53 volumio volumio[7684]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 15 16:39:53 volumio volumio[7684]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 15 16:39:53 volumio volumio[7684]: code: 'ECONNRESET', Dec 15 16:39:53 volumio volumio[7684]: response: undefined Dec 15 16:39:53 volumio volumio[7684]: } Dec 15 16:39:53 volumio volumio[7684]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 15 16:39:54 volumio sudo[8010]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-15 16:38' Dec 15 16:39:54 volumio sudo[8010]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:54 volumio sudo[8010]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:54 volumio volumio-remote-updater[800]: [2025-12-15 16:39:54] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 15 16:39:54 volumio volumio-remote-updater[800]: [2025-12-15 16:39:54] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 15 16:39:54 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:54 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 15 16:39:54 volumio systemd[1]: volumio.service: Consumed 16.612s CPU time. Dec 15 16:39:54 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 15 16:39:54 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 15 16:39:54 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 17. Dec 15 16:39:54 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 15 16:39:54 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 15 16:39:54 volumio systemd[1]: volumio.service: Consumed 16.612s CPU time. Dec 15 16:39:54 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 15 16:39:54 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 15 16:39:55 volumio volumio[8022]: info: ------------------------------------------- Dec 15 16:39:55 volumio volumio[8022]: info: ----- Volumio3 ---- Dec 15 16:39:55 volumio volumio[8022]: info: ------------------------------------------- Dec 15 16:39:55 volumio volumio[8022]: info: ----- System startup ---- Dec 15 16:39:55 volumio volumio[8022]: info: ------------------------------------------- Dec 15 16:39:56 volumio volumio[8022]: info: MYVOLUMIO Environment detected Dec 15 16:39:56 volumio volumio[8022]: info: Plugin folders cleanup Dec 15 16:39:56 volumio volumio[8022]: info: Scanning into folder /volumio/app/plugins/ Dec 15 16:39:56 volumio volumio[8022]: info: Scanning category audio_interface Dec 15 16:39:56 volumio volumio[8022]: info: Scanning category miscellanea Dec 15 16:39:56 volumio volumio[8022]: info: Scanning category music_service Dec 15 16:39:56 volumio volumio[8022]: info: Scanning category plugins.json Dec 15 16:39:56 volumio volumio[8022]: info: Scanning category system_controller Dec 15 16:39:56 volumio volumio[8022]: info: Scanning category user_interface Dec 15 16:39:56 volumio volumio[8022]: info: Scanning into folder /data/plugins/ Dec 15 16:39:56 volumio volumio[8022]: info: Scanning category music_service Dec 15 16:39:56 volumio volumio[8022]: info: Plugin folders cleanup completed Dec 15 16:39:56 volumio volumio[8022]: info: ------------------------------------------- Dec 15 16:39:56 volumio volumio[8022]: info: ----- Core plugins startup ---- Dec 15 16:39:56 volumio volumio[8022]: info: ------------------------------------------- Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugins from folder /volumio/app/plugins/ Dec 15 16:39:56 volumio volumio[8022]: info: Adding plugin upnp to MyMusic Plugins Dec 15 16:39:56 volumio volumio[8022]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 15 16:39:56 volumio volumio[8022]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugins from folder /data/plugins/ Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "system"... Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "appearance"... Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "network"... Dec 15 16:39:56 volumio volumio[8022]: info: Refreshing Cached IP Addresses Dec 15 16:39:56 volumio sudo[8050]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 15 16:39:56 volumio sudo[8050]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:56 volumio sudo[8052]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 15 16:39:56 volumio sudo[8052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "services"... Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "alsa_controller"... Dec 15 16:39:56 volumio sudo[8052]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:56 volumio sudo[8050]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:56 volumio sudo[8063]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 15 16:39:56 volumio sudo[8063]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:39:56 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "wizard"... Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "networkfs"... Dec 15 16:39:56 volumio volumio[8022]: info: Cannot mount NAS Pi5 at system boot, trial number 1 ,retrying in 5 seconds Dec 15 16:39:56 volumio volumio[8022]: info: Starting Udev Watcher for removable devices Dec 15 16:39:56 volumio volumio[8022]: info: Ignoring mount for partition: boot Dec 15 16:39:56 volumio volumio[8022]: info: Ignoring mount for partition: volumio Dec 15 16:39:56 volumio volumio[8022]: info: Ignoring mount for partition: volumio_data Dec 15 16:39:56 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "volumio_command_line_client"... Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "upnp"... Dec 15 16:39:56 volumio volumio[8022]: info: [1765809596914] Starting Upmpd Daemon Dec 15 16:39:56 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "my_music"... Dec 15 16:39:56 volumio volumio[8022]: info: Loading plugin "mpd"... Dec 15 16:39:57 volumio volumio[8022]: info: Loading plugin "upnp_browser"... Dec 15 16:39:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 15 16:39:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:39:57 volumio go-librespot[8080]: go-librespot daemon starting... Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=debug msg="app state loaded" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=info msg="zeroconf server listening on port 35169" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=debug msg="obtained new client token: AADYWo9fI4SfMbmWVFw59iOjQU6mfp+WTu73CDbDSLVrBlYmfnIHmARtdnxtpujC4egZRBd14z2rmCwAyTGHNbRXBf+GWKzj81C/ZK9lO09AspBxin4M4G6wb6ikSgrDCHOAeoRbmVigbc4mH5e9RblIFAZRwWN3WTNJEX6Uj/KeSI/creJnFiFkOuVt0yTQk3nWTdx6td/2r2jIkb9sAlgnu0NM12gUykKNLblS5kaYO1pwcVkJRhqGQfw=" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=debug msg="completed keyexchange" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=debug msg="completed challenge" Dec 15 16:39:57 volumio go-librespot[8081]: time="2025-12-15T16:39:57+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:39:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:39:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:39:57 volumio volumio[8022]: info: Starting UPNP Browser Dec 15 16:39:57 volumio volumio[8022]: info: Loading plugin "alarm-clock"... Dec 15 16:39:57 volumio volumio[8022]: info: Loading plugin "airplay_emulation"... Dec 15 16:39:57 volumio volumio[8022]: info: Starting Shairport Sync Dec 15 16:39:57 volumio volumio[8022]: info: Loading plugin "last_100"... Dec 15 16:39:57 volumio volumio[8022]: info: Loading plugin "webradio"... Dec 15 16:39:58 volumio volumio[8022]: info: Loading plugin "i2s_dacs"... Dec 15 16:39:58 volumio volumio[8022]: info: Loading plugin "volumiodiscovery"... Dec 15 16:39:58 volumio volumio[8022]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:58 volumio volumio[8022]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:58 volumio volumio[8022]: *** WARNING *** For more information see Dec 15 16:39:58 volumio volumio[8022]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:58 volumio volumio[8022]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:58 volumio volumio[8022]: *** WARNING *** For more information see Dec 15 16:39:58 volumio node[8022]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:58 volumio node[8022]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:58 volumio node[8022]: *** WARNING *** For more information see Dec 15 16:39:58 volumio node[8022]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 15 16:39:58 volumio node[8022]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 15 16:39:58 volumio node[8022]: *** WARNING *** For more information see Dec 15 16:39:58 volumio volumio[8022]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 15 16:39:58 volumio volumio[8022]: info: Discovery: Started advertising with name: Volumio Dec 15 16:39:58 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 15 16:39:58 volumio volumio[8022]: info: Loading plugin "bandcamp"... Dec 15 16:39:58 volumio volumio[8022]: info: Loading plugin "calmradio"... Dec 15 16:39:59 volumio volumio[8022]: info: Loading plugin "spop"... Dec 15 16:39:59 volumio sudo[8063]: pam_unix(sudo:session): session closed for user root Dec 15 16:39:59 volumio volumio-remote-updater[800]: [2025-12-15 16:39:59] [connect] Successful connection Dec 15 16:39:59 volumio volumio[8022]: info: Loading plugin "outputs"... Dec 15 16:39:59 volumio volumio[8022]: info: Loading plugin "albumart"... Dec 15 16:39:59 volumio volumio[8022]: info: Plugin example_plugin is not enabled Dec 15 16:39:59 volumio volumio[8022]: info: Loading plugin "inputs"... Dec 15 16:39:59 volumio volumio[8022]: info: Loading plugin "updater_comm"... Dec 15 16:39:59 volumio volumio[8022]: info: Plugin mpdemulation is not enabled Dec 15 16:39:59 volumio volumio[8022]: info: Loading plugin "rest_api"... Dec 15 16:39:59 volumio volumio[8022]: info: Loading plugin "websocket"... Dec 15 16:39:59 volumio volumio[8022]: info: Starting Socket.io Server version 1.7.4 Dec 15 16:39:59 volumio volumio[8022]: info: Loading plugin "radio_paradise"... Dec 15 16:39:59 volumio volumio[8022]: info: Applying required configuration parameters for plugin radio_paradise Dec 15 16:39:59 volumio volumio[8022]: info: [1765809599951] [RadioParadise] API delay: 5 Dec 15 16:39:59 volumio volumio[8022]: info: Loading i18n strings for locale en Dec 15 16:39:59 volumio volumio[8022]: Updating browse sources language Dec 15 16:39:59 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:40:00 volumio volumio[8090]: Forking 3 albumart workers Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::initPlayerControls Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: Express server listening on port 3000 Dec 15 16:40:00 volumio volumio[8022]: [Metrics] WebUI: 4s 622.59ms Dec 15 16:40:00 volumio volumio[8022]: info: CoreStateMachine::resetVolumioState Dec 15 16:40:00 volumio volumio[8022]: info: CoreStateMachine::getcurrentVolume Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioRetrievevolume Dec 15 16:40:00 volumio volumio[8022]: info: Volumio Network Manager: Network status updated: 1 Dec 15 16:40:00 volumio volumio-remote-updater[800]: [2025-12-15 16:40:00] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765809599 101 Dec 15 16:40:00 volumio volumio[8022]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 15 16:40:00 volumio volumio[8022]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: Reloading queue from file Dec 15 16:40:00 volumio volumio[8022]: info: CoreStateMachine::setRepeat null single undefined Dec 15 16:40:00 volumio volumio[8022]: info: CoreStateMachine::pushState Dec 15 16:40:00 volumio volumio[8022]: info: CorePlayQueue::getTrack 0 Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioPushState Dec 15 16:40:00 volumio volumio[8022]: info: CoreStateMachine::setRandom false Dec 15 16:40:00 volumio volumio[8022]: info: CoreStateMachine::pushState Dec 15 16:40:00 volumio volumio[8022]: info: CorePlayQueue::getTrack 0 Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioPushState Dec 15 16:40:00 volumio volumio[8022]: info: VolumeController:: Volume=undefined Mute =false Dec 15 16:40:00 volumio volumio[8022]: info: CoreStateMachine::pushState Dec 15 16:40:00 volumio volumio[8022]: info: CorePlayQueue::getTrack 0 Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioPushState Dec 15 16:40:00 volumio volumio[8022]: info: CoreStateMachine::updateTrackBlock Dec 15 16:40:00 volumio volumio[8022]: info: CorePlayQueue::getTrackBlock Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioRetrievevolume Dec 15 16:40:00 volumio volumio[8022]: info: Setting Device type: Raspberry PI Dec 15 16:40:00 volumio volumio[8022]: info: Completed loading Core Plugins Dec 15 16:40:00 volumio volumio[8022]: info: Preparing to generate the ALSA configuration file Dec 15 16:40:00 volumio volumio[8022]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 15 16:40:00 volumio volumio[8022]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03115 Dec 15 16:40:00 volumio volumio[8022]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 15 16:40:00 volumio volumio[8022]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Dec 15 16:40:00 volumio volumio[8022]: info: Asound.conf file unchanged, so no further update is needed Dec 15 16:40:00 volumio volumio[8022]: info: Output device has changed, restarting MPD Dec 15 16:40:00 volumio sudo[8151]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 15 16:40:00 volumio sudo[8151]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:00 volumio volumio[8022]: info: Output device has changed, restarting Shairport Sync Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:00 volumio sudo[8151]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:00 volumio sudo[8153]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 15 16:40:00 volumio volumio[8022]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:40:00 volumio sudo[8153]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:00 volumio volumio[8022]: info: ___________ START PLUGINS ___________ Dec 15 16:40:00 volumio volumio[8022]: info: ControllerMpd::onStart: Initializing MPD Dec 15 16:40:00 volumio volumio[8022]: info: Creating MPD Configuration file Dec 15 16:40:00 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 15 16:40:00 volumio sudo[8162]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 15 16:40:00 volumio sudo[8162]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 15 16:40:00 volumio sudo[8162]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:40:00 volumio volumio[8022]: info: [1765809600650] CoreMusicLibrary::Adding element Media Servers Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:40:00 volumio sudo[8165]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 15 16:40:00 volumio sudo[8165]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:00 volumio volumio[8022]: info: UPNP Browser: Client initialized successfully Dec 15 16:40:00 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 15 16:40:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 15 16:40:00 volumio systemd[1]: mpd.service: Consumed 1.903s CPU time. Dec 15 16:40:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 15 16:40:00 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 15 16:40:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 15 16:40:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 15 16:40:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:00 volumio volumio[8022]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:40:00 volumio volumio[8022]: info: [1765809600761] CoreMusicLibrary::Adding element Last_100 Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:40:00 volumio volumio[8022]: info: [1765809600767] CoreMusicLibrary::Adding element Webradio Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:40:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:40:00 volumio go-librespot[8176]: go-librespot daemon starting... Dec 15 16:40:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 15 16:40:00 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 15 16:40:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 15 16:40:00 volumio volumio[8022]: info: Initializing BBC Radios Dec 15 16:40:00 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 15 16:40:00 volumio go-librespot[8178]: time="2025-12-15T16:40:00+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:40:00 volumio go-librespot[8178]: time="2025-12-15T16:40:00+02:00" level=debug msg="app state loaded" Dec 15 16:40:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 15 16:40:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 15 16:40:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 15 16:40:00 volumio go-librespot[8178]: time="2025-12-15T16:40:00+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:40:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:40:00 volumio volumio[8022]: info: [1765809600908] CoreMusicLibrary::Adding element Bandcamp Discover Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:40:00 volumio volumio[8022]: Cannot find translation for source Bandcamp Discover Dec 15 16:40:00 volumio volumio[8022]: info: Adding Calm Radio to Browse Sources Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:40:00 volumio volumio[8022]: info: [1765809600933] CoreMusicLibrary::Adding element Calm Radio Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:40:00 volumio volumio[8022]: Cannot find translation for source Bandcamp Discover Dec 15 16:40:00 volumio volumio[8022]: Cannot find translation for source Calm Radio Dec 15 16:40:00 volumio volumio[8022]: info: Creating Spotify config file Dec 15 16:40:00 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:00 volumio sudo[8190]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 15 16:40:00 volumio sudo[8190]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 15 16:40:00 volumio sudo[8190]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=info msg="zeroconf server listening on port 40155" Dec 15 16:40:01 volumio volumio[8101]: Starting albumart workers Dec 15 16:40:01 volumio volumio[8100]: Starting albumart workers Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=debug msg="obtained new client token: AABBPTaSjR/BHHShkah1H2UzlWLpLz2m4L2GrYUgVxa6Kq2m4eljYpY5pjE+GaHiDm/i3BPzxnhq7egaeMeRqkENa9R1CpQUF26z8pAmOxxJ95dzCTbyx11cmDPnH6lP1Vevk/CCyue1efpeZXnAf1xazdmY4gNoDURiq1P6l12Vy5v3qI/Tcs+7UDymxFNGhqyPI04d7JVsR/Kt8W5LVQA/NHu/yd1wPatGc5tPzw6cr569Du+Oxhpq" Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:40:01 volumio volumio[8022]: info: [1765809601203] CoreMusicLibrary::Adding element Radio Paradise Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:40:01 volumio volumio[8022]: Cannot find translation for source Bandcamp Discover Dec 15 16:40:01 volumio volumio[8022]: Cannot find translation for source Calm Radio Dec 15 16:40:01 volumio volumio[8022]: Cannot find translation for source Radio Paradise Dec 15 16:40:01 volumio volumio[8022]: info: Volumio Calling Home Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:40:01 volumio volumio[8102]: Starting albumart workers Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=debug msg="completed keyexchange" Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=debug msg="completed challenge" Dec 15 16:40:01 volumio go-librespot[8178]: time="2025-12-15T16:40:01+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:40:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:40:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:40:01 volumio volumio[8022]: info: VolumeController:: Volume=undefined Mute =false Dec 15 16:40:01 volumio volumio[8022]: info: CoreStateMachine::pushState Dec 15 16:40:01 volumio volumio[8022]: info: CorePlayQueue::getTrack 0 Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::volumioPushState Dec 15 16:40:01 volumio volumio[8022]: info: Discovery: adding e79cfe37-08d9-42b5-80d9-7214f71f9b1f Dec 15 16:40:01 volumio volumio[8022]: info: Discovery: Found device Volumio Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::volumioGetState Dec 15 16:40:01 volumio volumio[8022]: info: CorePlayQueue::getTrack 0 Dec 15 16:40:01 volumio volumio[8022]: info: Discovery: this is already registered, e79cfe37-08d9-42b5-80d9-7214f71f9b1f Dec 15 16:40:01 volumio volumio[8022]: info: Discovery: Found device Volumio Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::volumioGetState Dec 15 16:40:01 volumio volumio[8022]: info: CorePlayQueue::getTrack 0 Dec 15 16:40:01 volumio volumio[8022]: info: MPD Permissions set Dec 15 16:40:01 volumio volumio[8022]: info: MPD Permissions set Dec 15 16:40:01 volumio volumio[8022]: info: Volumio called home Dec 15 16:40:01 volumio volumio[8022]: info: Spotify config file written Dec 15 16:40:01 volumio sudo[8209]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 15 16:40:01 volumio sudo[8209]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:01 volumio volumio[8022]: 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 15 16:40:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:01 volumio go-librespot[8219]: go-librespot daemon starting... Dec 15 16:40:01 volumio sudo[8209]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:01 volumio volumio[8022]: info: Cannot mount NAS Pi5 at system boot, trial number 2 ,retrying in 5 seconds Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio go-librespot[8223]: time="2025-12-15T16:40:01+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:40:01 volumio go-librespot[8223]: time="2025-12-15T16:40:01+02:00" level=debug msg="app state loaded" Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio go-librespot[8223]: time="2025-12-15T16:40:01+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 16:40:01 volumio volumio[8022]: info: No need to fix Spotify hosts Dec 15 16:40:02 volumio volumio[8022]: info: Starting Shairport Sync Dec 15 16:40:02 volumio volumio[8022]: info: Starting Shairport Sync Dec 15 16:40:02 volumio volumio[8022]: info: Starting Shairport Sync Dec 15 16:40:02 volumio sudo[8247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=info msg="zeroconf server listening on port 38113" Dec 15 16:40:02 volumio sudo[8247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:02 volumio sudo[8249]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:40:02 volumio sudo[8249]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:02 volumio volumio[8022]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 16:40:02 volumio volumio[8022]: SPOTIFY: BQD8zYhBKSdCzTZt3FFWosHfvHvv1oeGwKaEfvshQVCs_y4DqoR_gRxN9S2wi3MfZReFYzOktPsq5EpqzeY9oQP5kO1wZq5cSUwDTCbRYBi0qH8M_E4INYeg3Swtft03Ee344KM1QMSv_MCUTN0UaoDg1x6LmeoPIYRcI3K1QgwjODnG9nzKjcQmeY65BYxz7SkI9tQWSHMcAQKyZPuOOt9JQ62yxLvzuLVoieNhv8QZC_NtUz2oTO5oCJG7oLoBhfdCu9wKSIoTMMZvKdRSoeQMgSHClUQ5m-O6AhN-hkoMGFTuo7GVk3wT Dec 15 16:40:02 volumio volumio[8022]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 16:40:02 volumio volumio[8022]: info: New Spotify access token = BQD8zYhBKSdCzTZt3FFWosHfvHvv1oeGwKaEfvshQVCs_y4DqoR_gRxN9S2wi3MfZReFYzOktPsq5EpqzeY9oQP5kO1wZq5cSUwDTCbRYBi0qH8M_E4INYeg3Swtft03Ee344KM1QMSv_MCUTN0UaoDg1x6LmeoPIYRcI3K1QgwjODnG9nzKjcQmeY65BYxz7SkI9tQWSHMcAQKyZPuOOt9JQ62yxLvzuLVoieNhv8QZC_NtUz2oTO5oCJG7oLoBhfdCu9wKSIoTMMZvKdRSoeQMgSHClUQ5m-O6AhN-hkoMGFTuo7GVk3wT Dec 15 16:40:02 volumio volumio[8022]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 15 16:40:02 volumio sudo[8251]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 15 16:40:02 volumio sudo[8251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 15 16:40:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 15 16:40:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:40:02 volumio systemd[1]: shairport-sync.service: Consumed 1.691s CPU time. Dec 15 16:40:02 volumio volumio[8022]: info: CoreCommandRouter::volumioGetState Dec 15 16:40:02 volumio volumio[8022]: info: CorePlayQueue::getTrack 0 Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=debug msg="obtained new client token: AADfRuZ6YZ6xTX1iyXcFwpu1oSQrcyaOrrz3dXWc8kWv2fRO0AyHd7I/Bt6hlElM8dsOkkhtFeUbvO9nrMoOSwl9gmWiwDw/2lEA/XWKHnOe2D5N87u7DXMgIqA+koIPg7FpwWNsz58EmuvmyfT7wv00o7ID/8dfS/UTe13f0rJjZbrDwSW6+LPWKFgScL2ciuzHklPGHnpCd4Lyp15xbe29lUwfe1SaTDhp7DgJ6zRmVvzkicCKNc5PdyE=" Dec 15 16:40:02 volumio sudo[8249]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 15 16:40:02 volumio sudo[8247]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:02 volumio sudo[8251]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:02 volumio volumio[8022]: info: Shairport-Sync Started Dec 15 16:40:02 volumio volumio[8022]: Error adding Membership: Error: addMembership EINVAL Dec 15 16:40:02 volumio volumio[8022]: info: Shairport-Sync Started Dec 15 16:40:02 volumio volumio[8022]: info: Shairport-Sync Started Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:40:02 volumio volumio[8022]: SPOTIFY: User informations: {"country":"RO","display_name":"N_lu","email":"nmat2002@yahoo.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/i43j2nve71kxpxm8jld8hbo0i"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/i43j2nve71kxpxm8jld8hbo0i","id":"i43j2nve71kxpxm8jld8hbo0i","images":[],"product":"premium","type":"user","uri":"spotify:user:i43j2nve71kxpxm8jld8hbo0i"} Dec 15 16:40:02 volumio volumio[8022]: info: Spotify Successfully logged in Dec 15 16:40:02 volumio volumio[8022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 16:40:02 volumio volumio[8022]: info: [1765809602411] CoreMusicLibrary::Adding element Spotify Dec 15 16:40:02 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 16:40:02 volumio volumio[8022]: Cannot find translation for source Bandcamp Discover Dec 15 16:40:02 volumio volumio[8022]: Cannot find translation for source Calm Radio Dec 15 16:40:02 volumio volumio[8022]: Cannot find translation for source Radio Paradise Dec 15 16:40:02 volumio volumio[8022]: Cannot find translation for source Spotify Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=debug msg="completed keyexchange" Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=debug msg="completed challenge" Dec 15 16:40:02 volumio go-librespot[8223]: time="2025-12-15T16:40:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:40:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:40:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:40:02 volumio mpd[8201]: 2025-12-15T16:40:02 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 15 16:40:02 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 15 16:40:02 volumio sudo[8153]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:02 volumio sudo[8165]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:02 volumio volumio[8022]: info: Completed starting Core Plugins Dec 15 16:40:02 volumio volumio[8022]: info: ------------------------------------------- Dec 15 16:40:02 volumio volumio[8022]: info: ----- MyVolumio plugins startup ---- Dec 15 16:40:02 volumio volumio[8022]: info: ------------------------------------------- Dec 15 16:40:02 volumio volumio[8022]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 15 16:40:02 volumio volumio[8022]: error: MPD error: The expression evaluated to a falsy value: Dec 15 16:40:02 volumio volumio[8022]: assert.ok(self.idling) Dec 15 16:40:02 volumio volumio[8022]: error: The expression evaluated to a falsy value: Dec 15 16:40:02 volumio volumio[8022]: assert.ok(self.idling) Dec 15 16:40:02 volumio volumio[8022]: error: updateQueue error: null Dec 15 16:40:02 volumio volumio[8022]: info: MPD running with PID8201 Dec 15 16:40:02 volumio volumio[8022]: ,establishing connection Dec 15 16:40:02 volumio volumio[8022]: error: updateQueue error: null Dec 15 16:40:05 volumio volumio[8022]: info: go-librespot daemon successfully initialized Dec 15 16:40:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 15 16:40:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:05 volumio go-librespot[8278]: go-librespot daemon starting... Dec 15 16:40:05 volumio go-librespot[8279]: time="2025-12-15T16:40:05+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:40:05 volumio go-librespot[8279]: time="2025-12-15T16:40:05+02:00" level=debug msg="app state loaded" Dec 15 16:40:05 volumio go-librespot[8279]: time="2025-12-15T16:40:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:40:05 volumio sudo[8287]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 15 16:40:05 volumio sudo[8287]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:05 volumio sudo[8289]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 15 16:40:05 volumio sudo[8289]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:05 volumio go-librespot[8279]: time="2025-12-15T16:40:05+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 15 16:40:05 volumio go-librespot[8279]: time="2025-12-15T16:40:05+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 15 16:40:05 volumio go-librespot[8279]: time="2025-12-15T16:40:05+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 15 16:40:05 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 15 16:40:05 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 15 16:40:05 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 15 16:40:05 volumio go-librespot[8279]: time="2025-12-15T16:40:05+02:00" level=info msg="zeroconf server listening on port 34717" Dec 15 16:40:06 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 15 16:40:06 volumio go-librespot[8279]: time="2025-12-15T16:40:06+02:00" level=debug msg="obtained new client token: AADt2RcaYuKpXzHjf/kA8LOEe9ccQVNv+/CENx6rsUp4FALXxHq2R8ws143y5s+48cZrU1cLupQBxCRfjjSIvdHhJk2VlopuEKEUM8C/BgL4GKRcSlldLc9NKDjs8gpMSoO3fPLLaPkwkb4tAdPQSJ4517SnKp7AhrEoqbwOUVEdy3B7ThqkHvOIjc0Fbz+j+KlBZsCw+VaypxH7iuvGVyiaZb0JgNwYhRyGvPKZpYTStADywCRMhnyA" Dec 15 16:40:06 volumio sudo[8289]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:06 volumio mpd_monitor.sh[8292]: MPD Monitor Service: Starting MPD Monitor Service Dec 15 16:40:06 volumio sudo[8287]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:06 volumio volumio[8022]: info: Successfully started MPD Monitor Dec 15 16:40:06 volumio volumio[8022]: info: Successfully started MPD Monitor Dec 15 16:40:06 volumio go-librespot[8279]: time="2025-12-15T16:40:06+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:40:06 volumio go-librespot[8279]: time="2025-12-15T16:40:06+02:00" level=debug msg="completed keyexchange" Dec 15 16:40:06 volumio go-librespot[8279]: time="2025-12-15T16:40:06+02:00" level=debug msg="completed challenge" Dec 15 16:40:06 volumio go-librespot[8279]: time="2025-12-15T16:40:06+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:40:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:40:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:40:06 volumio volumio[8022]: info: Cannot mount NAS Pi5 at system boot, trial number 3 ,retrying in 5 seconds Dec 15 16:40:06 volumio sudo[8311]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 15 16:40:06 volumio sudo[8311]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:06 volumio sudo[8311]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:06 volumio sudo[8313]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 15 16:40:06 volumio sudo[8313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:06 volumio sudo[8313]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:06 volumio sudo[8316]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 15 16:40:06 volumio sudo[8316]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:06 volumio sudo[8316]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:06 volumio volumio[8022]: info: Upmpdcli Daemon Started Dec 15 16:40:07 volumio volumio[8022]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 15 16:40:08 volumio volumio[8022]: info: Initializing connection to go-librespot Websocket Dec 15 16:40:08 volumio volumio[8022]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 15 16:40:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 15 16:40:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:09 volumio go-librespot[8319]: go-librespot daemon starting... Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=debug msg="app state loaded" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=info msg="zeroconf server listening on port 42545" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=debug msg="obtained new client token: AABnJ+ZHy4F/TTPNvDiLWU61oAU2nzkvG2xhXv4DUmFf4Vrb8jSHOpv/jnxhHWv74rDXGXiIYuU/5Crj1pCa3ndtOAFRuj2KNctEp5RG0bwfCgV9vB759vbwiAgbIa6YMm036rzD2izzWjpqKCSfHnpPF8sJNQ40rXC+qb0I9jfFfrxB+NjNpxifMZ15yWdTgypBVuBkjdivrVs9VJIcUwFpOQtKoblREx8d1wwKppE1168zlxYsRGok/I4=" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=debug msg="completed keyexchange" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=debug msg="completed challenge" Dec 15 16:40:09 volumio go-librespot[8320]: time="2025-12-15T16:40:09+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:40:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:40:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:40:11 volumio volumio[8022]: info: Initializing connection to go-librespot Websocket Dec 15 16:40:11 volumio volumio[8022]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 15 16:40:11 volumio volumio[8022]: info: Adding plugin bluetooth to MyMusic Plugins Dec 15 16:40:11 volumio volumio[8022]: info: Adding plugin multiroom to MyMusic Plugins Dec 15 16:40:11 volumio volumio[8022]: info: Adding plugin metavolumio to MyMusic Plugins Dec 15 16:40:11 volumio volumio[8022]: info: Adding plugin cd_controller to MyMusic Plugins Dec 15 16:40:11 volumio volumio[8022]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 15 16:40:11 volumio volumio[8022]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 15 16:40:11 volumio volumio[8022]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 15 16:40:11 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:11 volumio volumio[8022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 15 16:40:11 volumio volumio[8022]: info: Starting MyVolumio Remote Streaming Endpoints Dec 15 16:40:11 volumio volumio[8022]: info: MyVolumio login type: Token Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 15 16:40:11 volumio volumio[8022]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 15 16:40:12 volumio volumio[8022]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 15 16:40:12 volumio volumio[8022]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 15 16:40:12 volumio volumio[8022]: info: Streaming services startup Dec 15 16:40:12 volumio volumio[8022]: info: Starting Streaming Daemon Dec 15 16:40:12 volumio sudo[8328]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 15 16:40:12 volumio sudo[8328]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 16:40:12 volumio volumio[8022]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 15 16:40:12 volumio sudo[8328]: pam_unix(sudo:session): session closed for user root Dec 15 16:40:12 volumio volumio[8022]: info: Cannot mount NAS Pi5 at system boot, trial number 4 ,retrying in 5 seconds Dec 15 16:40:12 volumio volumio[8022]: error: Cannot start Volumio Streaming Daemon Dec 15 16:40:12 volumio volumio[8022]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 15 16:40:12 volumio volumio[8022]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 15 16:40:12 volumio volumio[8022]: error: MyVolumio Custom Token format not valid, refreshing it Dec 15 16:40:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 15 16:40:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:12 volumio volumio[8022]: error: Cannot refresh My Volumio Token: [object Object] Dec 15 16:40:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:12 volumio go-librespot[8335]: go-librespot daemon starting... Dec 15 16:40:12 volumio go-librespot[8336]: time="2025-12-15T16:40:12+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:40:12 volumio go-librespot[8336]: time="2025-12-15T16:40:12+02:00" level=debug msg="app state loaded" Dec 15 16:40:12 volumio go-librespot[8336]: time="2025-12-15T16:40:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=info msg="zeroconf server listening on port 33277" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=debug msg="obtained new client token: AACJhmq9sT3Fm01EOoxnTQgTBKY/HmHaLbUtb2v/kSg0L7CZ2ElkwPgiOy4OHLcfQV3FBwsqwlu035XmvDFvmxde+fe5GvZ2648cL+1da1pfzgfDHDshqEhCk2sMFTVIFiFLWTNwRydHIND1bhdipgZEZSwOBODSHIZir0ppsth5F+zopcx68YFMiYg/pvu5DTnjead8FkA65g182W171qKBWCnCC7jSJhE7lK3SLyH0c9gFg43CYPJ+" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=debug msg="completed keyexchange" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=debug msg="completed challenge" Dec 15 16:40:13 volumio go-librespot[8336]: time="2025-12-15T16:40:13+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:40:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:40:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:40:14 volumio volumio[8022]: info: Initializing connection to go-librespot Websocket Dec 15 16:40:14 volumio volumio[8022]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 15 16:40:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 15 16:40:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:16 volumio go-librespot[8349]: go-librespot daemon starting... Dec 15 16:40:16 volumio go-librespot[8350]: time="2025-12-15T16:40:16+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:40:16 volumio go-librespot[8350]: time="2025-12-15T16:40:16+02:00" level=debug msg="app state loaded" Dec 15 16:40:16 volumio go-librespot[8350]: time="2025-12-15T16:40:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:40:16 volumio go-librespot[8350]: time="2025-12-15T16:40:16+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 16:40:16 volumio go-librespot[8350]: time="2025-12-15T16:40:16+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 16:40:16 volumio go-librespot[8350]: time="2025-12-15T16:40:16+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 16:40:16 volumio go-librespot[8350]: time="2025-12-15T16:40:16+02:00" level=info msg="zeroconf server listening on port 33441" Dec 15 16:40:17 volumio go-librespot[8350]: time="2025-12-15T16:40:17+02:00" level=debug msg="obtained new client token: AABZT4ijsS9pT1eQ9EbOx4q21ba9eejsm8NiOSm3f0T7lraXMCI1I2SpoD5cAf4bSJB3v16TLvmB4Y/GPheZ5eYrwIPMJpkWyByNDd6U4sGAquKyBeVia7MMrAJzSJUDf42CbWm2aU7yhA2cNQnXJMs38F+TkSaTz+50x9q5Vyw9RhGTT1KS/i1Ael2GzG/VsH0JBNRgli5BesCitcvKXDGN5YcvSLe0XDrfnAe6q385EB3FtDNFpBQG" Dec 15 16:40:17 volumio go-librespot[8350]: time="2025-12-15T16:40:17+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 15 16:40:17 volumio volumio[8022]: info: Initializing connection to go-librespot Websocket Dec 15 16:40:17 volumio go-librespot[8350]: time="2025-12-15T16:40:17+02:00" level=debug msg="new websocket client" Dec 15 16:40:17 volumio volumio[8022]: info: Connection to go-librespot Websocket established Dec 15 16:40:17 volumio go-librespot[8350]: time="2025-12-15T16:40:17+02:00" level=debug msg="completed keyexchange" Dec 15 16:40:17 volumio go-librespot[8350]: time="2025-12-15T16:40:17+02:00" level=debug msg="completed challenge" Dec 15 16:40:17 volumio go-librespot[8350]: time="2025-12-15T16:40:17+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TryAnotherAP " Dec 15 16:40:17 volumio volumio[8022]: info: Connection to go-librespot Websocket closed Dec 15 16:40:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 16:40:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 16:40:17 volumio volumio[8022]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Dec 15 16:40:20 volumio volumio[8022]: info: Getting Spotify volume Dec 15 16:40:20 volumio volumio[8022]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 15 16:40:20 volumio volumio[8022]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 15 16:40:20 volumio volumio[8022]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 15 16:40:20 volumio volumio[8022]: errno: -111, Dec 15 16:40:20 volumio volumio[8022]: code: 'ECONNREFUSED', Dec 15 16:40:20 volumio volumio[8022]: syscall: 'connect', Dec 15 16:40:20 volumio volumio[8022]: address: '127.0.0.1', Dec 15 16:40:20 volumio volumio[8022]: port: 9879, Dec 15 16:40:20 volumio volumio[8022]: response: undefined Dec 15 16:40:20 volumio volumio[8022]: } Dec 15 16:40:20 volumio volumio[8022]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 15 16:40:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Dec 15 16:40:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 16:40:20 volumio go-librespot[8383]: go-librespot daemon starting... Dec 15 16:40:20 volumio go-librespot[8384]: time="2025-12-15T16:40:20+02:00" level=info msg="running go-librespot 0.4.0" Dec 15 16:40:20 volumio go-librespot[8384]: time="2025-12-15T16:40:20+02:00" level=debug msg="app state loaded" Dec 15 16:40:20 volumio go-librespot[8384]: time="2025-12-15T16:40:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 16:40:20 volumio sudo[8392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-15 16:39' Dec 15 16:40:20 volumio sudo[8392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"