Dec 26 19:08:00 music go-librespot[26193]: time="2025-12-26T19:08:00-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:00 music go-librespot[26193]: time="2025-12-26T19:08:00-05:00" level=debug msg="completed challenge" Dec 26 19:08:00 music go-librespot[26193]: time="2025-12-26T19:08:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:00 music volumio[26177]: info: MYVOLUMIO Environment detected Dec 26 19:08:00 music volumio[26177]: info: Plugin folders cleanup Dec 26 19:08:00 music volumio[26177]: info: Scanning into folder /volumio/app/plugins/ Dec 26 19:08:00 music volumio[26177]: info: Scanning category audio_interface Dec 26 19:08:00 music volumio[26177]: info: Scanning category miscellanea Dec 26 19:08:00 music volumio[26177]: info: Scanning category music_service Dec 26 19:08:00 music volumio[26177]: info: Scanning category plugins.json Dec 26 19:08:00 music volumio[26177]: info: Scanning category system_controller Dec 26 19:08:00 music volumio[26177]: info: Scanning category user_interface Dec 26 19:08:00 music volumio[26177]: info: Scanning into folder /data/plugins/ Dec 26 19:08:00 music volumio[26177]: info: Scanning category music_service Dec 26 19:08:00 music volumio[26177]: info: Plugin folders cleanup completed Dec 26 19:08:00 music volumio[26177]: info: ------------------------------------------- Dec 26 19:08:00 music volumio[26177]: info: ----- Core plugins startup ---- Dec 26 19:08:00 music volumio[26177]: info: ------------------------------------------- Dec 26 19:08:00 music volumio[26177]: info: Loading plugins from folder /volumio/app/plugins/ Dec 26 19:08:00 music volumio[26177]: info: Adding plugin upnp to MyMusic Plugins Dec 26 19:08:00 music volumio[26177]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 26 19:08:00 music volumio[26177]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 26 19:08:00 music volumio[26177]: info: Loading plugins from folder /data/plugins/ Dec 26 19:08:00 music volumio[26177]: info: Loading plugin "system"... Dec 26 19:08:00 music volumio[26177]: info: Loading plugin "appearance"... Dec 26 19:08:00 music go-librespot[26193]: time="2025-12-26T19:08:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:08:00 music go-librespot[26193]: time="2025-12-26T19:08:00-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:00 music go-librespot[26193]: time="2025-12-26T19:08:00-05:00" level=debug msg="completed challenge" Dec 26 19:08:00 music go-librespot[26193]: time="2025-12-26T19:08:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:01 music go-librespot[26193]: time="2025-12-26T19:08:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:08:01 music go-librespot[26193]: time="2025-12-26T19:08:01-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:01 music go-librespot[26193]: time="2025-12-26T19:08:01-05:00" level=debug msg="completed challenge" Dec 26 19:08:01 music go-librespot[26193]: time="2025-12-26T19:08:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "network"... Dec 26 19:08:01 music volumio[26177]: info: Refreshing Cached IP Addresses Dec 26 19:08:01 music sudo[26215]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 19:08:01 music sudo[26215]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:01 music sudo[26217]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 19:08:01 music sudo[26217]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "services"... Dec 26 19:08:01 music sudo[26215]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:01 music sudo[26217]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "alsa_controller"... Dec 26 19:08:01 music sudo[26224]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 26 19:08:01 music sudo[26224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:01 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "wizard"... Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "networkfs"... Dec 26 19:08:01 music volumio[26177]: info: Starting Udev Watcher for removable devices Dec 26 19:08:01 music volumio[26177]: info: Ignoring mount for partition: boot Dec 26 19:08:01 music volumio[26177]: info: Ignoring mount for partition: volumio Dec 26 19:08:01 music volumio[26177]: info: Ignoring mount for partition: volumio_data Dec 26 19:08:01 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "volumio_command_line_client"... Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "upnp"... Dec 26 19:08:01 music volumio[26177]: info: [1766794081966] Starting Upmpd Daemon Dec 26 19:08:01 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "my_music"... Dec 26 19:08:01 music volumio[26177]: info: Loading plugin "mpd"... Dec 26 19:08:02 music go-librespot[26193]: time="2025-12-26T19:08:02-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 19:08:02 music volumio[26177]: info: Loading plugin "upnp_browser"... Dec 26 19:08:02 music volumio-remote-updater[735]: [2025-12-27 00:08:02] [connect] Successful connection Dec 26 19:08:02 music sudo[26224]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:02 music go-librespot[26193]: time="2025-12-26T19:08:02-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:02 music go-librespot[26193]: time="2025-12-26T19:08:02-05:00" level=debug msg="completed challenge" Dec 26 19:08:02 music go-librespot[26193]: time="2025-12-26T19:08:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:03 music go-librespot[26193]: time="2025-12-26T19:08:03-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 26 19:08:03 music go-librespot[26193]: time="2025-12-26T19:08:03-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:03 music go-librespot[26193]: time="2025-12-26T19:08:03-05:00" level=debug msg="completed challenge" Dec 26 19:08:03 music volumio[26177]: info: Starting UPNP Browser Dec 26 19:08:03 music volumio[26177]: info: Loading plugin "alarm-clock"... Dec 26 19:08:03 music go-librespot[26193]: time="2025-12-26T19:08:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:04 music volumio[26177]: info: Loading plugin "airplay_emulation"... Dec 26 19:08:04 music volumio[26177]: info: Starting Shairport Sync Dec 26 19:08:04 music volumio[26177]: info: Loading plugin "last_100"... Dec 26 19:08:04 music volumio[26177]: info: Loading plugin "webradio"... Dec 26 19:08:04 music volumio[26177]: info: Loading plugin "i2s_dacs"... Dec 26 19:08:04 music volumio[26177]: info: I2S DAC not set, start Auto-detection Dec 26 19:08:04 music volumio[26177]: info: Loading plugin "volumiodiscovery"... Dec 26 19:08:04 music volumio[26177]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:04 music volumio[26177]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:04 music volumio[26177]: *** WARNING *** For more information see Dec 26 19:08:04 music volumio[26177]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:04 music volumio[26177]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:04 music volumio[26177]: *** WARNING *** For more information see Dec 26 19:08:04 music node[26177]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:04 music node[26177]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:04 music node[26177]: *** WARNING *** For more information see Dec 26 19:08:04 music node[26177]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:04 music node[26177]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:04 music node[26177]: *** WARNING *** For more information see Dec 26 19:08:04 music volumio[26177]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 26 19:08:04 music volumio[26177]: info: Discovery: Started advertising with name: music Dec 26 19:08:04 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:04 music volumio[26177]: info: Loading plugin "spop"... Dec 26 19:08:04 music go-librespot[26193]: time="2025-12-26T19:08:04-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 26 19:08:04 music go-librespot[26193]: time="2025-12-26T19:08:04-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:04 music go-librespot[26193]: time="2025-12-26T19:08:04-05:00" level=debug msg="completed challenge" Dec 26 19:08:04 music go-librespot[26193]: time="2025-12-26T19:08:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:04 music go-librespot[26193]: time="2025-12-26T19:08:04-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:04 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:04 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:08:05 music volumio[26177]: info: Loading plugin "outputs"... Dec 26 19:08:05 music volumio[26177]: info: Loading plugin "albumart"... Dec 26 19:08:05 music volumio[26177]: info: Plugin example_plugin is not enabled Dec 26 19:08:05 music volumio[26177]: info: Loading plugin "inputs"... Dec 26 19:08:05 music volumio[26177]: info: Loading plugin "updater_comm"... Dec 26 19:08:05 music volumio[26177]: info: Plugin mpdemulation is not enabled Dec 26 19:08:05 music volumio[26177]: info: Loading plugin "rest_api"... Dec 26 19:08:05 music volumio[26177]: info: Loading plugin "websocket"... Dec 26 19:08:05 music volumio[26177]: info: Starting Socket.io Server version 1.7.4 Dec 26 19:08:05 music volumio[26177]: info: Loading i18n strings for locale en Dec 26 19:08:05 music volumio[26177]: Updating browse sources language Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::initPlayerControls Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:05 music volumio[26177]: Express server listening on port 3000 Dec 26 19:08:05 music volumio[26177]: [Metrics] WebUI: 6s 639.01ms Dec 26 19:08:05 music volumio[26177]: info: CoreStateMachine::resetVolumioState Dec 26 19:08:05 music volumio[26177]: info: CoreStateMachine::getcurrentVolume Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:05 music volumio[26177]: info: Volumio Network Manager: Network status updated: 1 Dec 26 19:08:05 music volumio-remote-updater[735]: [2025-12-27 00:08:05] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766794082 101 Dec 26 19:08:05 music volumio[26252]: Forking 3 albumart workers Dec 26 19:08:05 music volumio[26177]: 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 26 19:08:05 music volumio[26177]: info: VolumeController:: Volume=86 Mute =false Dec 26 19:08:05 music volumio[26177]: info: CoreStateMachine::pushState Dec 26 19:08:05 music volumio[26177]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:05 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:06 music volumio[26177]: info: CoreStateMachine::updateTrackBlock Dec 26 19:08:06 music volumio[26177]: info: CorePlayQueue::getTrackBlock Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 19:08:06 music volumio[26177]: info: Reloading queue from file Dec 26 19:08:06 music volumio[26177]: info: CoreStateMachine::setRepeat null single undefined Dec 26 19:08:06 music volumio[26177]: info: CoreStateMachine::pushState Dec 26 19:08:06 music volumio[26177]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:06 music volumio[26177]: info: CoreStateMachine::setRandom null Dec 26 19:08:06 music volumio[26177]: info: CoreStateMachine::pushState Dec 26 19:08:06 music volumio[26177]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:06 music volumio[26177]: info: Setting Device type: Raspberry PI Dec 26 19:08:06 music volumio[26177]: info: VolumeController:: Volume=86 Mute =false Dec 26 19:08:06 music volumio[26177]: info: CoreStateMachine::pushState Dec 26 19:08:06 music volumio[26177]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:06 music volumio[26177]: info: Completed loading Core Plugins Dec 26 19:08:06 music volumio[26177]: info: Preparing to generate the ALSA configuration file Dec 26 19:08:06 music volumio[26177]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 26 19:08:06 music volumio[26177]: info: Discovery: Found device music Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioGetState Dec 26 19:08:06 music volumio[26177]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:06 music volumio[26177]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 26 19:08:06 music volumio[26177]: info: Discovery: Found device music Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioGetState Dec 26 19:08:06 music volumio[26177]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:06 music volumio[26177]: info: Asound.conf file unchanged, so no further update is needed Dec 26 19:08:06 music volumio[26177]: info: Output device has changed, restarting MPD Dec 26 19:08:06 music volumio[26177]: info: Output device has changed, restarting Shairport Sync Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:06 music sudo[26308]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 19:08:06 music sudo[26308]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:06 music sudo[26309]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 19:08:06 music volumio[26177]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:06 music sudo[26308]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:06 music sudo[26309]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:06 music volumio[26177]: info: ___________ START PLUGINS ___________ Dec 26 19:08:06 music volumio[26177]: info: ControllerMpd::onStart: Initializing MPD Dec 26 19:08:06 music volumio[26177]: info: Creating MPD Configuration file Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:06 music volumio[26177]: info: [1766794086425] CoreMusicLibrary::Adding element Media Servers Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:06 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 26 19:08:06 music volumio[26177]: info: UPNP Browser: Client initialized successfully Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:06 music sudo[26317]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 19:08:06 music sudo[26317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:06 music systemd[1]: mpd.service: Deactivated successfully. Dec 26 19:08:06 music sudo[26319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 19:08:06 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 19:08:06 music sudo[26319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:06 music systemd[1]: mpd.service: Consumed 4.255s CPU time. Dec 26 19:08:06 music systemd[1]: mpd.socket: Deactivated successfully. Dec 26 19:08:06 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 19:08:06 music sudo[26317]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:06 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 19:08:06 music volumio[26177]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:06 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 19:08:06 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 19:08:06 music volumio[26177]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:06 music volumio[26177]: info: [1766794086622] CoreMusicLibrary::Adding element Last_100 Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:06 music volumio[26177]: info: [1766794086629] CoreMusicLibrary::Adding element Webradio Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:06 music systemd[1]: mpd.service: Deactivated successfully. Dec 26 19:08:06 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 19:08:06 music systemd[1]: mpd.socket: Deactivated successfully. Dec 26 19:08:06 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 19:08:06 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 19:08:06 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:06 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 19:08:06 music volumio[26177]: info: Initializing BBC Radios Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:06 music volumio[26177]: info: Creating Spotify config file Dec 26 19:08:06 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:06 music sudo[26333]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 19:08:06 music sudo[26333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 19:08:06 music sudo[26333]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:07 music volumio[26177]: info: Volumio Calling Home Dec 26 19:08:07 music volumio[26270]: Starting albumart workers Dec 26 19:08:07 music volumio[26269]: Starting albumart workers Dec 26 19:08:07 music volumio[26177]: info: MPD Permissions set Dec 26 19:08:07 music volumio[26177]: info: MPD Permissions set Dec 26 19:08:08 music volumio[26177]: info: Spotify config file written Dec 26 19:08:08 music volumio[26268]: Starting albumart workers Dec 26 19:08:08 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 26 19:08:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:08 music sudo[26354]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 26 19:08:08 music sudo[26354]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:08 music volumio[26177]: 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 26 19:08:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:08 music volumio[26177]: info: No need to fix Spotify hosts Dec 26 19:08:08 music go-librespot[26355]: go-librespot daemon starting... Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music go-librespot[26357]: time="2025-12-26T19:08:08-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:08 music go-librespot[26357]: time="2025-12-26T19:08:08-05:00" level=debug msg="app state loaded" Dec 26 19:08:08 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 26 19:08:08 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 26 19:08:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:08 music sudo[26354]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:08 music go-librespot[26368]: go-librespot daemon starting... Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music go-librespot[26369]: time="2025-12-26T19:08:08-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:08 music go-librespot[26369]: time="2025-12-26T19:08:08-05:00" level=debug msg="app state loaded" Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:08 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:08 music go-librespot[26369]: time="2025-12-26T19:08:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:08:08 music volumio[26177]: info: Volumio called home Dec 26 19:08:08 music go-librespot[26369]: time="2025-12-26T19:08:08-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:08:08 music go-librespot[26369]: time="2025-12-26T19:08:08-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:08:08 music go-librespot[26369]: time="2025-12-26T19:08:08-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:08:08 music go-librespot[26369]: time="2025-12-26T19:08:08-05:00" level=info msg="zeroconf server listening on port 44877" Dec 26 19:08:08 music volumio[26177]: info: Starting Shairport Sync Dec 26 19:08:08 music volumio[26177]: info: Starting Shairport Sync Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:08-05:00" level=debug msg="obtained new client token: AAB47/CVvkWXDcnN7IwlF8lQGZlcubID/UqryOOth5r/M/JhXEE/PmW1uz6cW9mv9zn8MoNDJCcvPeaQ/IYe8jc7UBwjnL8sY9BOlHeosWcc2o9sL+73/mVEWeYVgNeXHDSDqfPgcNP+MPyzCWpLJYP3BWzOpAZ6eGqcYoAnrWW33ui40HqbtzseY75xjgGUix5YzH2XKZntpWfkjxQ5QG8kJ8MynJMwQdMKU3mKQC1ayt6hfVOy2jBV" Dec 26 19:08:09 music volumio[26177]: info: Starting Shairport Sync Dec 26 19:08:09 music sudo[26387]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:08:09 music sudo[26387]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:09 music sudo[26390]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:08:09 music sudo[26390]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:09 music volumio[26177]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:09-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:09-05:00" level=debug msg="completed challenge" Dec 26 19:08:09 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 19:08:09 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 19:08:09 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:08:09 music systemd[1]: shairport-sync.service: Consumed 1.868s CPU time. Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:09 music sudo[26392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:08:09 music sudo[26392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:09 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:08:09 music sudo[26387]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:09 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 19:08:09 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 19:08:09 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:08:09 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:08:09 music sudo[26390]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:09 music sudo[26392]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:09 music volumio[26177]: info: Shairport-Sync Started Dec 26 19:08:09 music volumio[26177]: Error adding Membership: Error: addMembership EINVAL Dec 26 19:08:09 music volumio[26177]: info: Shairport-Sync Started Dec 26 19:08:09 music volumio[26177]: info: Shairport-Sync Started Dec 26 19:08:09 music volumio[26177]: info: CoreCommandRouter::volumioGetState Dec 26 19:08:09 music volumio[26177]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:09-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:09-05:00" level=debug msg="completed challenge" Dec 26 19:08:09 music go-librespot[26369]: time="2025-12-26T19:08:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:10 music go-librespot[26369]: time="2025-12-26T19:08:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:08:10 music go-librespot[26369]: time="2025-12-26T19:08:10-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:10 music go-librespot[26369]: time="2025-12-26T19:08:10-05:00" level=debug msg="completed challenge" Dec 26 19:08:10 music go-librespot[26369]: time="2025-12-26T19:08:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:11 music mpd[26348]: 2025-12-26T19:08:11 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 19:08:11 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 26 19:08:11 music sudo[26319]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:11 music sudo[26309]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:11 music volumio[26177]: info: Completed starting Core Plugins Dec 26 19:08:11 music volumio[26177]: info: ------------------------------------------- Dec 26 19:08:11 music volumio[26177]: info: ----- MyVolumio plugins startup ---- Dec 26 19:08:11 music volumio[26177]: info: ------------------------------------------- Dec 26 19:08:11 music volumio[26177]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 26 19:08:11 music go-librespot[26369]: time="2025-12-26T19:08:11-05:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Dec 26 19:08:11 music volumio[26177]: error: MPD error: The expression evaluated to a falsy value: Dec 26 19:08:11 music volumio[26177]: assert.ok(self.idling) Dec 26 19:08:11 music volumio[26177]: error: The expression evaluated to a falsy value: Dec 26 19:08:11 music volumio[26177]: assert.ok(self.idling) Dec 26 19:08:11 music volumio[26177]: error: updateQueue error: null Dec 26 19:08:11 music volumio[26177]: info: MPD running with PID26348 Dec 26 19:08:11 music volumio[26177]: ,establishing connection Dec 26 19:08:11 music volumio[26177]: error: updateQueue error: null Dec 26 19:08:11 music go-librespot[26369]: time="2025-12-26T19:08:11-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 26 19:08:11 music go-librespot[26369]: time="2025-12-26T19:08:11-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:11 music go-librespot[26369]: time="2025-12-26T19:08:11-05:00" level=debug msg="completed challenge" Dec 26 19:08:11 music go-librespot[26369]: time="2025-12-26T19:08:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:11 music volumio[26177]: info: go-librespot daemon successfully initialized Dec 26 19:08:11 music sudo[26460]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 19:08:12 music sudo[26460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:12 music sudo[26460]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:12 music sudo[26462]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 19:08:12 music sudo[26462]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:12 music sudo[26462]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:12 music sudo[26465]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 26 19:08:12 music sudo[26465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:12 music sudo[26465]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:12 music volumio[26177]: info: Upmpdcli Daemon Started Dec 26 19:08:12 music go-librespot[26369]: time="2025-12-26T19:08:12-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:08:12 music go-librespot[26369]: time="2025-12-26T19:08:12-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:12 music go-librespot[26369]: time="2025-12-26T19:08:12-05:00" level=debug msg="completed challenge" Dec 26 19:08:12 music go-librespot[26369]: time="2025-12-26T19:08:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:12 music go-librespot[26369]: time="2025-12-26T19:08:12-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:13 music go-librespot[26369]: time="2025-12-26T19:08:13-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:13 music go-librespot[26369]: time="2025-12-26T19:08:13-05:00" level=debug msg="completed challenge" Dec 26 19:08:13 music go-librespot[26369]: time="2025-12-26T19:08:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:13 music go-librespot[26369]: time="2025-12-26T19:08:13-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:13 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:13 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:08:14 music sudo[26469]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 19:08:14 music sudo[26469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:14 music sudo[26471]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 19:08:14 music sudo[26471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:14 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 19:08:14 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 19:08:14 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 19:08:14 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 19:08:14 music sudo[26469]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:14 music volumio[26177]: info: Successfully started MPD Monitor Dec 26 19:08:14 music mpd_monitor.sh[26474]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 19:08:14 music sudo[26471]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:14 music volumio[26177]: info: Successfully started MPD Monitor Dec 26 19:08:14 music volumio[26177]: info: Initializing connection to go-librespot Websocket Dec 26 19:08:14 music volumio[26177]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 19:08:16 music volumio[26177]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 26 19:08:16 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 26 19:08:16 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:16 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:16 music go-librespot[26478]: go-librespot daemon starting... Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=debug msg="app state loaded" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=info msg="zeroconf server listening on port 46173" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=debug msg="obtained new client token: AAD1kfog6O+UcuW18CJ4I4XYzli7OuFzDahgU9iZFbuGnV9tp8ip6rPVWU3FlUOO01PA1+/kOmoIiEjJpssi931TU28hplDDo92vAj1l8FLZQXM4qIzI46sNKwdJL5ocin2kbp5z+/h2KXNV0JsuYEDbPZS5zT5JuU8WocztSpTd31kiogz5UZq1uMg8vl3imNOewOspUSyXc9Ed9VylnfJZPzmccF5NTuC7voN8ZppPAjKTYXSwZuaE" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:16 music go-librespot[26479]: time="2025-12-26T19:08:16-05:00" level=debug msg="completed challenge" Dec 26 19:08:17 music go-librespot[26479]: time="2025-12-26T19:08:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:17 music go-librespot[26479]: time="2025-12-26T19:08:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:08:17 music go-librespot[26479]: time="2025-12-26T19:08:17-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:17 music go-librespot[26479]: time="2025-12-26T19:08:17-05:00" level=debug msg="completed challenge" Dec 26 19:08:17 music go-librespot[26479]: time="2025-12-26T19:08:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:17 music volumio[26177]: info: Initializing connection to go-librespot Websocket Dec 26 19:08:17 music go-librespot[26479]: time="2025-12-26T19:08:17-05:00" level=debug msg="new websocket client" Dec 26 19:08:17 music volumio[26177]: info: Connection to go-librespot Websocket established Dec 26 19:08:18 music go-librespot[26479]: time="2025-12-26T19:08:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:08:18 music go-librespot[26479]: time="2025-12-26T19:08:18-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:18 music go-librespot[26479]: time="2025-12-26T19:08:18-05:00" level=debug msg="completed challenge" Dec 26 19:08:18 music go-librespot[26479]: time="2025-12-26T19:08:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:18 music go-librespot[26479]: time="2025-12-26T19:08:18-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 19:08:19 music go-librespot[26479]: time="2025-12-26T19:08:19-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:19 music go-librespot[26479]: time="2025-12-26T19:08:19-05:00" level=debug msg="completed challenge" Dec 26 19:08:19 music go-librespot[26479]: time="2025-12-26T19:08:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 26 19:08:19 music volumio[26177]: info: Adding plugin bluetooth to MyMusic Plugins Dec 26 19:08:19 music volumio[26177]: info: Adding plugin multiroom to MyMusic Plugins Dec 26 19:08:19 music volumio[26177]: info: Adding plugin metavolumio to MyMusic Plugins Dec 26 19:08:19 music volumio[26177]: info: Adding plugin cd_controller to MyMusic Plugins Dec 26 19:08:19 music volumio[26177]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 26 19:08:19 music volumio[26177]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 26 19:08:19 music volumio[26177]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 26 19:08:19 music volumio[26177]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 26 19:08:19 music go-librespot[26479]: time="2025-12-26T19:08:19-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 26 19:08:20 music go-librespot[26479]: time="2025-12-26T19:08:20-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:20 music go-librespot[26479]: time="2025-12-26T19:08:20-05:00" level=debug msg="completed challenge" Dec 26 19:08:20 music go-librespot[26479]: time="2025-12-26T19:08:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:20 music volumio[26177]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 26 19:08:20 music volumio[26177]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 26 19:08:20 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:20 music volumio[26177]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:20 music volumio[26177]: info: Starting MyVolumio Remote Streaming Endpoints Dec 26 19:08:20 music volumio[26177]: info: MyVolumio login type: Token Dec 26 19:08:20 music volumio[26177]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 26 19:08:20 music volumio[26177]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 26 19:08:20 music go-librespot[26479]: time="2025-12-26T19:08:20-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:08:20 music go-librespot[26479]: time="2025-12-26T19:08:20-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:20 music go-librespot[26479]: time="2025-12-26T19:08:20-05:00" level=debug msg="completed challenge" Dec 26 19:08:21 music go-librespot[26479]: time="2025-12-26T19:08:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:21 music go-librespot[26479]: time="2025-12-26T19:08:21-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:21 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:21 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:08:21 music volumio[26177]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 26 19:08:21 music volumio[26177]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 26 19:08:21 music volumio[26177]: info: Streaming services startup Dec 26 19:08:21 music volumio[26177]: info: Starting Streaming Daemon Dec 26 19:08:21 music sudo[26489]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 26 19:08:21 music sudo[26489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:21 music volumio[26177]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 26 19:08:21 music sudo[26489]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:21 music volumio[26177]: info: Getting Spotify volume Dec 26 19:08:21 music volumio[26177]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 19:08:21 music volumio[26177]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 19:08:21 music volumio[26177]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 26 19:08:21 music volumio[26177]: errno: -111, Dec 26 19:08:21 music volumio[26177]: code: 'ECONNREFUSED', Dec 26 19:08:21 music volumio[26177]: syscall: 'connect', Dec 26 19:08:21 music volumio[26177]: address: '127.0.0.1', Dec 26 19:08:21 music volumio[26177]: port: 9879, Dec 26 19:08:21 music volumio[26177]: response: undefined Dec 26 19:08:21 music volumio[26177]: } Dec 26 19:08:21 music volumio[26177]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 19:08:22 music sudo[26523]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 19:07' Dec 26 19:08:22 music sudo[26523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:22 music sudo[26523]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:23 music volumio-remote-updater[735]: [2025-12-27 00:08:23] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 26 19:08:23 music volumio-remote-updater[735]: [2025-12-27 00:08:23] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 26 19:08:23 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:23 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 26 19:08:23 music systemd[1]: volumio.service: Consumed 26.472s CPU time. Dec 26 19:08:23 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 26 19:08:23 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 26 19:08:23 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2856. Dec 26 19:08:23 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 26 19:08:23 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 26 19:08:23 music systemd[1]: volumio.service: Consumed 26.472s CPU time. Dec 26 19:08:23 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 26 19:08:23 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 26 19:08:24 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 26 19:08:24 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:24 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:24 music go-librespot[26553]: go-librespot daemon starting... Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=debug msg="app state loaded" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=info msg="zeroconf server listening on port 36851" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=debug msg="obtained new client token: AAC0F+JBzHpJydbPjWiD/RtIkZ4EQ7vX3f3fbo3sDI2UaXQyTBp82YEQq8aMkrv8LN50sYZxvfdlC9FsGjGxXnSlcN3TPkf3UdTkdrk64ykPTlUrQrSDm0+4rlF0qTHi6nDJc/AppbidYz7+29igiSkcO45ZCGoubshWtzwKqpE6+KtWVfvs8chT/x0m7B8JZqAzUGw+h4xwMSHSfpz1mfdY6NpQ4CaaCiO2mz16ZPtf/vx3tDZQBsDl" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=debug msg="completed challenge" Dec 26 19:08:24 music go-librespot[26554]: time="2025-12-26T19:08:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:25 music go-librespot[26554]: time="2025-12-26T19:08:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:08:25 music go-librespot[26554]: time="2025-12-26T19:08:25-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:25 music go-librespot[26554]: time="2025-12-26T19:08:25-05:00" level=debug msg="completed challenge" Dec 26 19:08:25 music go-librespot[26554]: time="2025-12-26T19:08:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:25 music volumio[26538]: info: ------------------------------------------- Dec 26 19:08:25 music volumio[26538]: info: ----- Volumio3 ---- Dec 26 19:08:25 music volumio[26538]: info: ------------------------------------------- Dec 26 19:08:25 music volumio[26538]: info: ----- System startup ---- Dec 26 19:08:25 music volumio[26538]: info: ------------------------------------------- Dec 26 19:08:26 music go-librespot[26554]: time="2025-12-26T19:08:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:08:26 music go-librespot[26554]: time="2025-12-26T19:08:26-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:26 music go-librespot[26554]: time="2025-12-26T19:08:26-05:00" level=debug msg="completed challenge" Dec 26 19:08:26 music go-librespot[26554]: time="2025-12-26T19:08:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:26 music volumio[26538]: info: MYVOLUMIO Environment detected Dec 26 19:08:26 music volumio[26538]: info: Plugin folders cleanup Dec 26 19:08:26 music volumio[26538]: info: Scanning into folder /volumio/app/plugins/ Dec 26 19:08:26 music volumio[26538]: info: Scanning category audio_interface Dec 26 19:08:26 music volumio[26538]: info: Scanning category miscellanea Dec 26 19:08:26 music volumio[26538]: info: Scanning category music_service Dec 26 19:08:26 music volumio[26538]: info: Scanning category plugins.json Dec 26 19:08:26 music volumio[26538]: info: Scanning category system_controller Dec 26 19:08:26 music volumio[26538]: info: Scanning category user_interface Dec 26 19:08:26 music volumio[26538]: info: Scanning into folder /data/plugins/ Dec 26 19:08:26 music volumio[26538]: info: Scanning category music_service Dec 26 19:08:26 music volumio[26538]: info: Plugin folders cleanup completed Dec 26 19:08:26 music volumio[26538]: info: ------------------------------------------- Dec 26 19:08:26 music volumio[26538]: info: ----- Core plugins startup ---- Dec 26 19:08:26 music volumio[26538]: info: ------------------------------------------- Dec 26 19:08:26 music volumio[26538]: info: Loading plugins from folder /volumio/app/plugins/ Dec 26 19:08:26 music volumio[26538]: info: Adding plugin upnp to MyMusic Plugins Dec 26 19:08:26 music volumio[26538]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 26 19:08:26 music volumio[26538]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 26 19:08:26 music volumio[26538]: info: Loading plugins from folder /data/plugins/ Dec 26 19:08:26 music volumio[26538]: info: Loading plugin "system"... Dec 26 19:08:26 music volumio[26538]: info: Loading plugin "appearance"... Dec 26 19:08:27 music go-librespot[26554]: time="2025-12-26T19:08:27-05:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Dec 26 19:08:27 music go-librespot[26554]: time="2025-12-26T19:08:27-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 26 19:08:27 music go-librespot[26554]: time="2025-12-26T19:08:27-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:27 music go-librespot[26554]: time="2025-12-26T19:08:27-05:00" level=debug msg="completed challenge" Dec 26 19:08:27 music go-librespot[26554]: time="2025-12-26T19:08:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "network"... Dec 26 19:08:27 music volumio[26538]: info: Refreshing Cached IP Addresses Dec 26 19:08:27 music sudo[26577]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 19:08:27 music sudo[26577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:27 music sudo[26577]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:27 music sudo[26579]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 19:08:27 music sudo[26579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:27 music sudo[26579]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "services"... Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "alsa_controller"... Dec 26 19:08:27 music sudo[26587]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 26 19:08:27 music sudo[26587]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:27 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "wizard"... Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "networkfs"... Dec 26 19:08:27 music volumio[26538]: info: Starting Udev Watcher for removable devices Dec 26 19:08:27 music volumio[26538]: info: Ignoring mount for partition: boot Dec 26 19:08:27 music volumio[26538]: info: Ignoring mount for partition: volumio Dec 26 19:08:27 music volumio[26538]: info: Ignoring mount for partition: volumio_data Dec 26 19:08:27 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "volumio_command_line_client"... Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "upnp"... Dec 26 19:08:27 music volumio[26538]: info: [1766794107932] Starting Upmpd Daemon Dec 26 19:08:27 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "my_music"... Dec 26 19:08:27 music volumio[26538]: info: Loading plugin "mpd"... Dec 26 19:08:28 music go-librespot[26554]: time="2025-12-26T19:08:28-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:08:28 music go-librespot[26554]: time="2025-12-26T19:08:28-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:28 music go-librespot[26554]: time="2025-12-26T19:08:28-05:00" level=debug msg="completed challenge" Dec 26 19:08:28 music volumio[26538]: info: Loading plugin "upnp_browser"... Dec 26 19:08:28 music volumio-remote-updater[735]: [2025-12-27 00:08:28] [connect] Successful connection Dec 26 19:08:28 music go-librespot[26554]: time="2025-12-26T19:08:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:28 music sudo[26587]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:28 music go-librespot[26554]: time="2025-12-26T19:08:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:28 music go-librespot[26554]: time="2025-12-26T19:08:28-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:28 music go-librespot[26554]: time="2025-12-26T19:08:28-05:00" level=debug msg="completed challenge" Dec 26 19:08:29 music go-librespot[26554]: time="2025-12-26T19:08:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:29 music go-librespot[26554]: time="2025-12-26T19:08:29-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:29 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:29 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:08:29 music volumio[26538]: info: Starting UPNP Browser Dec 26 19:08:29 music volumio[26538]: info: Loading plugin "alarm-clock"... Dec 26 19:08:30 music volumio[26538]: info: Loading plugin "airplay_emulation"... Dec 26 19:08:30 music volumio[26538]: info: Starting Shairport Sync Dec 26 19:08:30 music volumio[26538]: info: Loading plugin "last_100"... Dec 26 19:08:30 music volumio[26538]: info: Loading plugin "webradio"... Dec 26 19:08:30 music volumio[26538]: info: Loading plugin "i2s_dacs"... Dec 26 19:08:30 music volumio[26538]: info: I2S DAC not set, start Auto-detection Dec 26 19:08:30 music volumio[26538]: info: Loading plugin "volumiodiscovery"... Dec 26 19:08:30 music volumio[26538]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:30 music volumio[26538]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:30 music volumio[26538]: *** WARNING *** For more information see Dec 26 19:08:30 music volumio[26538]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:30 music volumio[26538]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:30 music volumio[26538]: *** WARNING *** For more information see Dec 26 19:08:30 music node[26538]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:30 music node[26538]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:30 music node[26538]: *** WARNING *** For more information see Dec 26 19:08:30 music node[26538]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:30 music node[26538]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:30 music node[26538]: *** WARNING *** For more information see Dec 26 19:08:30 music volumio[26538]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 26 19:08:30 music volumio[26538]: info: Discovery: Started advertising with name: music Dec 26 19:08:30 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:30 music volumio[26538]: info: Loading plugin "spop"... Dec 26 19:08:31 music volumio[26538]: info: Loading plugin "outputs"... Dec 26 19:08:31 music volumio[26538]: info: Loading plugin "albumart"... Dec 26 19:08:31 music volumio[26538]: info: Plugin example_plugin is not enabled Dec 26 19:08:31 music volumio[26538]: info: Loading plugin "inputs"... Dec 26 19:08:31 music volumio[26538]: info: Loading plugin "updater_comm"... Dec 26 19:08:31 music volumio[26538]: info: Plugin mpdemulation is not enabled Dec 26 19:08:31 music volumio[26538]: info: Loading plugin "rest_api"... Dec 26 19:08:31 music volumio[26538]: info: Loading plugin "websocket"... Dec 26 19:08:31 music volumio[26538]: info: Starting Socket.io Server version 1.7.4 Dec 26 19:08:31 music volumio[26538]: info: Loading i18n strings for locale en Dec 26 19:08:31 music volumio[26538]: Updating browse sources language Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::initPlayerControls Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:31 music volumio[26538]: Express server listening on port 3000 Dec 26 19:08:31 music volumio[26538]: [Metrics] WebUI: 6s 624.96ms Dec 26 19:08:31 music volumio[26538]: info: CoreStateMachine::resetVolumioState Dec 26 19:08:31 music volumio[26538]: info: CoreStateMachine::getcurrentVolume Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:31 music volumio[26538]: info: Volumio Network Manager: Network status updated: 1 Dec 26 19:08:31 music volumio-remote-updater[735]: [2025-12-27 00:08:31] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766794108 101 Dec 26 19:08:31 music volumio[26538]: 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 26 19:08:31 music volumio[26538]: info: VolumeController:: Volume=86 Mute =false Dec 26 19:08:31 music volumio[26538]: info: CoreStateMachine::pushState Dec 26 19:08:31 music volumio[26538]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 19:08:31 music volumio[26538]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:32 music volumio[26538]: info: CoreStateMachine::updateTrackBlock Dec 26 19:08:32 music volumio[26612]: Forking 3 albumart workers Dec 26 19:08:32 music volumio[26538]: info: CorePlayQueue::getTrackBlock Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 19:08:32 music volumio[26538]: info: Reloading queue from file Dec 26 19:08:32 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 26 19:08:32 music volumio[26538]: info: CoreStateMachine::setRepeat null single undefined Dec 26 19:08:32 music volumio[26538]: info: CoreStateMachine::pushState Dec 26 19:08:32 music volumio[26538]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:32 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:32 music volumio[26538]: info: CoreStateMachine::setRandom null Dec 26 19:08:32 music volumio[26538]: info: CoreStateMachine::pushState Dec 26 19:08:32 music volumio[26538]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:32 music volumio[26538]: info: Setting Device type: Raspberry PI Dec 26 19:08:32 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:32 music go-librespot[26660]: go-librespot daemon starting... Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=debug msg="app state loaded" Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:08:32 music volumio[26538]: info: VolumeController:: Volume=86 Mute =false Dec 26 19:08:32 music volumio[26538]: info: CoreStateMachine::pushState Dec 26 19:08:32 music volumio[26538]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:32 music volumio[26538]: info: Completed loading Core Plugins Dec 26 19:08:32 music volumio[26538]: info: Preparing to generate the ALSA configuration file Dec 26 19:08:32 music volumio[26538]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 26 19:08:32 music volumio[26538]: info: Discovery: Found device music Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioGetState Dec 26 19:08:32 music volumio[26538]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:32 music volumio[26538]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 26 19:08:32 music volumio[26538]: info: Discovery: Found device music Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioGetState Dec 26 19:08:32 music volumio[26538]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:32 music volumio[26538]: info: Asound.conf file unchanged, so no further update is needed Dec 26 19:08:32 music volumio[26538]: info: Output device has changed, restarting MPD Dec 26 19:08:32 music volumio[26538]: info: Output device has changed, restarting Shairport Sync Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:32 music sudo[26677]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 19:08:32 music sudo[26677]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:32 music sudo[26677]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:32 music volumio[26538]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:32 music volumio[26538]: info: ___________ START PLUGINS ___________ Dec 26 19:08:32 music sudo[26678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 19:08:32 music sudo[26678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:32 music volumio[26538]: info: ControllerMpd::onStart: Initializing MPD Dec 26 19:08:32 music volumio[26538]: info: Creating MPD Configuration file Dec 26 19:08:32 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:32 music volumio[26538]: info: [1766794112603] CoreMusicLibrary::Adding element Media Servers Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:32 music sudo[26689]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 19:08:32 music sudo[26689]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:32 music systemd[1]: mpd.service: Deactivated successfully. Dec 26 19:08:32 music volumio[26538]: info: UPNP Browser: Client initialized successfully Dec 26 19:08:32 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 19:08:32 music systemd[1]: mpd.service: Consumed 4.240s CPU time. Dec 26 19:08:32 music sudo[26688]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 19:08:32 music sudo[26688]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:32 music sudo[26688]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:32 music systemd[1]: mpd.socket: Deactivated successfully. Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:08:32 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 19:08:32 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=info msg="zeroconf server listening on port 46829" Dec 26 19:08:32 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 19:08:32 music volumio[26538]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:32 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:32 music systemd[1]: mpd.service: Deactivated successfully. Dec 26 19:08:32 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 19:08:32 music systemd[1]: mpd.socket: Deactivated successfully. Dec 26 19:08:32 music volumio[26538]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:32 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 19:08:32 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 19:08:32 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 19:08:32 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:32 music volumio[26538]: info: [1766794112828] CoreMusicLibrary::Adding element Last_100 Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:32 music volumio[26538]: info: [1766794112840] CoreMusicLibrary::Adding element Webradio Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=debug msg="obtained new client token: AADHtWSEofiscNe0/gKxpbaqTEkL6HIko2xP6eRd3GMRB2ISOsRqvdl2WLOvYdcEz/xom0JycLC+YS++GKKVvQ9zyv6W0BvKyzX40wmejF9CxM96gvJrelbem2DCgLm3Jelute363Xzic5pTnQBy6mETNR/8h6ijx1ds2uhNzfChcfxBAnS9bv08pamNAXjeHTiJLiwijCtdZgoLGYikl5juWH9eYB+nU3Upr3nruYrPoYHo3OJ/CEVD" Dec 26 19:08:32 music volumio[26538]: info: Initializing BBC Radios Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:32 music volumio[26538]: info: Creating Spotify config file Dec 26 19:08:32 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:32 music go-librespot[26661]: time="2025-12-26T19:08:32-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:33 music go-librespot[26661]: time="2025-12-26T19:08:33-05:00" level=debug msg="completed challenge" Dec 26 19:08:33 music go-librespot[26661]: time="2025-12-26T19:08:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:33 music sudo[26703]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 19:08:33 music sudo[26703]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 19:08:33 music sudo[26703]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:33 music volumio[26538]: info: Volumio Calling Home Dec 26 19:08:33 music go-librespot[26661]: time="2025-12-26T19:08:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:08:33 music go-librespot[26661]: time="2025-12-26T19:08:33-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:33 music go-librespot[26661]: time="2025-12-26T19:08:33-05:00" level=debug msg="completed challenge" Dec 26 19:08:33 music go-librespot[26661]: time="2025-12-26T19:08:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:33 music volumio[26632]: Starting albumart workers Dec 26 19:08:34 music volumio[26538]: info: MPD Permissions set Dec 26 19:08:34 music volumio[26538]: info: MPD Permissions set Dec 26 19:08:34 music volumio[26538]: info: Spotify config file written Dec 26 19:08:34 music sudo[26723]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 26 19:08:34 music sudo[26723]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:34 music volumio[26538]: 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 26 19:08:34 music volumio[26538]: info: Volumio called home Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 26 19:08:34 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 26 19:08:34 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26629]: Starting albumart workers Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:34 music volumio[26538]: info: No need to fix Spotify hosts Dec 26 19:08:34 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:34 music go-librespot[26730]: go-librespot daemon starting... Dec 26 19:08:34 music sudo[26723]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:34 music go-librespot[26736]: time="2025-12-26T19:08:34-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:34 music go-librespot[26736]: time="2025-12-26T19:08:34-05:00" level=debug msg="app state loaded" Dec 26 19:08:34 music volumio[26631]: Starting albumart workers Dec 26 19:08:34 music go-librespot[26736]: time="2025-12-26T19:08:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:08:34 music go-librespot[26736]: time="2025-12-26T19:08:34-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:08:34 music go-librespot[26736]: time="2025-12-26T19:08:34-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:08:34 music go-librespot[26736]: time="2025-12-26T19:08:34-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:08:34 music go-librespot[26736]: time="2025-12-26T19:08:34-05:00" level=info msg="zeroconf server listening on port 35785" Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=debug msg="obtained new client token: AAC4asR8tfyFYy8/WfH+gPj/nlgYWNybNTHhzXZr4LW2edS+E5N65xNIDxzffMf141HTUpmkH9HeXpT90lOZfMNwCqhTfTHKuxbrI11u1BYuBEXCTwti3iFfU7ywnlYx+1JkDETqPSM6kMYi3RtzkSu9YTU5vdZcZ1zr/rao/GD9h+xFOQal9KhZ6uWUD6wVeLS22fQweW7KqRuAWi/sxmPg27XcXJ9s4w/aEOka6EqDVC9crVPfEg==" Dec 26 19:08:35 music volumio[26538]: info: Starting Shairport Sync Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:35 music volumio[26538]: info: Starting Shairport Sync Dec 26 19:08:35 music volumio[26538]: info: Starting Shairport Sync Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=debug msg="completed challenge" Dec 26 19:08:35 music sudo[26748]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:08:35 music sudo[26748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:35 music sudo[26750]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:08:35 music sudo[26750]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:35 music volumio[26538]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 26 19:08:35 music sudo[26752]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:35 music sudo[26752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:35 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 19:08:35 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 19:08:35 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:08:35 music systemd[1]: shairport-sync.service: Consumed 1.848s CPU time. Dec 26 19:08:35 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:08:35 music sudo[26748]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:35 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 19:08:35 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 19:08:35 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:08:35 music sudo[26752]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:35 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:08:35 music sudo[26750]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:35 music volumio[26538]: info: Shairport-Sync Started Dec 26 19:08:35 music volumio[26538]: Error adding Membership: Error: addMembership EINVAL Dec 26 19:08:35 music volumio[26538]: info: Shairport-Sync Started Dec 26 19:08:35 music volumio[26538]: info: Shairport-Sync Started Dec 26 19:08:35 music volumio[26538]: info: CoreCommandRouter::volumioGetState Dec 26 19:08:35 music volumio[26538]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=debug msg="completed challenge" Dec 26 19:08:35 music go-librespot[26736]: time="2025-12-26T19:08:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:36 music go-librespot[26736]: time="2025-12-26T19:08:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:08:36 music go-librespot[26736]: time="2025-12-26T19:08:36-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:36 music go-librespot[26736]: time="2025-12-26T19:08:36-05:00" level=debug msg="completed challenge" Dec 26 19:08:36 music go-librespot[26736]: time="2025-12-26T19:08:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:37 music go-librespot[26736]: time="2025-12-26T19:08:37-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 19:08:37 music go-librespot[26736]: time="2025-12-26T19:08:37-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:37 music go-librespot[26736]: time="2025-12-26T19:08:37-05:00" level=debug msg="completed challenge" Dec 26 19:08:37 music mpd[26718]: 2025-12-26T19:08:37 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 19:08:37 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 26 19:08:37 music sudo[26678]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:37 music sudo[26689]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:37 music go-librespot[26736]: time="2025-12-26T19:08:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:37 music volumio[26538]: info: Completed starting Core Plugins Dec 26 19:08:37 music volumio[26538]: info: ------------------------------------------- Dec 26 19:08:37 music volumio[26538]: info: ----- MyVolumio plugins startup ---- Dec 26 19:08:37 music volumio[26538]: info: ------------------------------------------- Dec 26 19:08:37 music volumio[26538]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 26 19:08:37 music volumio[26538]: error: MPD error: The expression evaluated to a falsy value: Dec 26 19:08:37 music volumio[26538]: assert.ok(self.idling) Dec 26 19:08:37 music volumio[26538]: error: The expression evaluated to a falsy value: Dec 26 19:08:37 music volumio[26538]: assert.ok(self.idling) Dec 26 19:08:37 music volumio[26538]: error: updateQueue error: null Dec 26 19:08:37 music volumio[26538]: info: MPD running with PID26718 Dec 26 19:08:37 music volumio[26538]: ,establishing connection Dec 26 19:08:37 music volumio[26538]: error: updateQueue error: null Dec 26 19:08:37 music go-librespot[26736]: time="2025-12-26T19:08:37-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 26 19:08:37 music sudo[26811]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 19:08:37 music sudo[26811]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:37 music sudo[26813]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 19:08:37 music sudo[26811]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:37 music sudo[26813]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:37 music sudo[26813]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:37 music sudo[26816]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 26 19:08:37 music sudo[26816]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:38 music volumio[26538]: info: go-librespot daemon successfully initialized Dec 26 19:08:38 music go-librespot[26736]: time="2025-12-26T19:08:38-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:38 music go-librespot[26736]: time="2025-12-26T19:08:38-05:00" level=debug msg="completed challenge" Dec 26 19:08:38 music sudo[26816]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:38 music volumio[26538]: info: Upmpdcli Daemon Started Dec 26 19:08:38 music go-librespot[26736]: time="2025-12-26T19:08:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:38 music go-librespot[26736]: time="2025-12-26T19:08:38-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:08:38 music go-librespot[26736]: time="2025-12-26T19:08:38-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:38 music go-librespot[26736]: time="2025-12-26T19:08:38-05:00" level=debug msg="completed challenge" Dec 26 19:08:39 music go-librespot[26736]: time="2025-12-26T19:08:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:39 music go-librespot[26736]: time="2025-12-26T19:08:39-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:39 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:39 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:08:40 music sudo[26820]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 19:08:40 music sudo[26820]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:40 music sudo[26822]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 19:08:40 music sudo[26822]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:40 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 19:08:40 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 19:08:40 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 19:08:40 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 19:08:40 music mpd_monitor.sh[26825]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 19:08:40 music sudo[26822]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:40 music sudo[26820]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:40 music volumio[26538]: info: Successfully started MPD Monitor Dec 26 19:08:40 music volumio[26538]: info: Successfully started MPD Monitor Dec 26 19:08:41 music volumio[26538]: info: Initializing connection to go-librespot Websocket Dec 26 19:08:41 music volumio[26538]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 19:08:42 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 26 19:08:42 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:42 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:42 music go-librespot[26829]: go-librespot daemon starting... Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=debug msg="app state loaded" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:08:42 music volumio[26538]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=info msg="zeroconf server listening on port 39067" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=debug msg="obtained new client token: AADg4hlgJ6E7gqwcdfcuHuIFqMZeLb6Nplm/dXY3DKUwcPBOw5NKyg2JCQTg7Y7l33VDET9F7cAoUBKRHvMPGcsG9j7jyLfjzzKJhuVuC+qtSyLkd9LGwHUOHKm20SIjkObv8MB89EIYoY3u35HLGjbJJSikwxZZUpJIkc7rFAMbMrmGdpGisL0TRb63/vsKNU57ebjKw+rq6eVwerFl8QeKkJhmmVFYhViuYs+c1ygJOZMuux8jBpAz" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=debug msg="completed challenge" Dec 26 19:08:42 music go-librespot[26830]: time="2025-12-26T19:08:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:43 music go-librespot[26830]: time="2025-12-26T19:08:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:08:43 music go-librespot[26830]: time="2025-12-26T19:08:43-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:43 music go-librespot[26830]: time="2025-12-26T19:08:43-05:00" level=debug msg="completed challenge" Dec 26 19:08:43 music go-librespot[26830]: time="2025-12-26T19:08:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:08:44 music volumio[26538]: info: Initializing connection to go-librespot Websocket Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=debug msg="new websocket client" Dec 26 19:08:44 music volumio[26538]: info: Connection to go-librespot Websocket established Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=debug msg="completed challenge" Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=debug msg="completed challenge" Dec 26 19:08:44 music go-librespot[26830]: time="2025-12-26T19:08:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:45 music go-librespot[26830]: time="2025-12-26T19:08:45-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 26 19:08:45 music volumio[26538]: info: Adding plugin bluetooth to MyMusic Plugins Dec 26 19:08:45 music volumio[26538]: info: Adding plugin multiroom to MyMusic Plugins Dec 26 19:08:45 music volumio[26538]: info: Adding plugin metavolumio to MyMusic Plugins Dec 26 19:08:45 music volumio[26538]: info: Adding plugin cd_controller to MyMusic Plugins Dec 26 19:08:45 music volumio[26538]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 26 19:08:45 music volumio[26538]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 26 19:08:45 music volumio[26538]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 26 19:08:45 music volumio[26538]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 26 19:08:45 music go-librespot[26830]: time="2025-12-26T19:08:45-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:45 music go-librespot[26830]: time="2025-12-26T19:08:45-05:00" level=debug msg="completed challenge" Dec 26 19:08:45 music go-librespot[26830]: time="2025-12-26T19:08:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:46 music go-librespot[26830]: time="2025-12-26T19:08:46-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 26 19:08:46 music volumio[26538]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 26 19:08:46 music volumio[26538]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 26 19:08:46 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:46 music volumio[26538]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:46 music volumio[26538]: info: Starting MyVolumio Remote Streaming Endpoints Dec 26 19:08:46 music volumio[26538]: info: MyVolumio login type: Token Dec 26 19:08:46 music go-librespot[26830]: time="2025-12-26T19:08:46-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:46 music go-librespot[26830]: time="2025-12-26T19:08:46-05:00" level=debug msg="completed challenge" Dec 26 19:08:46 music volumio[26538]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 26 19:08:46 music volumio[26538]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 26 19:08:46 music go-librespot[26830]: time="2025-12-26T19:08:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:46 music go-librespot[26830]: time="2025-12-26T19:08:46-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:46 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:46 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:08:47 music volumio[26538]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 26 19:08:47 music volumio[26538]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 26 19:08:47 music volumio[26538]: info: Streaming services startup Dec 26 19:08:47 music volumio[26538]: info: Starting Streaming Daemon Dec 26 19:08:47 music sudo[26840]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 26 19:08:47 music sudo[26840]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:47 music volumio[26538]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 26 19:08:47 music sudo[26840]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:47 music volumio[26538]: info: Getting Spotify volume Dec 26 19:08:47 music volumio[26538]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 19:08:47 music volumio[26538]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 19:08:47 music volumio[26538]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 26 19:08:47 music volumio[26538]: errno: -111, Dec 26 19:08:47 music volumio[26538]: code: 'ECONNREFUSED', Dec 26 19:08:47 music volumio[26538]: syscall: 'connect', Dec 26 19:08:47 music volumio[26538]: address: '127.0.0.1', Dec 26 19:08:47 music volumio[26538]: port: 9879, Dec 26 19:08:47 music volumio[26538]: response: undefined Dec 26 19:08:47 music volumio[26538]: } Dec 26 19:08:47 music volumio[26538]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 19:08:48 music sudo[26875]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 19:07' Dec 26 19:08:48 music sudo[26875]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:48 music sudo[26875]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:48 music volumio-remote-updater[735]: [2025-12-27 00:08:48] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 26 19:08:48 music volumio-remote-updater[735]: [2025-12-27 00:08:48] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 26 19:08:48 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:48 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 26 19:08:48 music systemd[1]: volumio.service: Consumed 26.530s CPU time. Dec 26 19:08:48 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 26 19:08:48 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 26 19:08:49 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2857. Dec 26 19:08:49 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 26 19:08:49 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 26 19:08:49 music systemd[1]: volumio.service: Consumed 26.530s CPU time. Dec 26 19:08:49 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 26 19:08:49 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 26 19:08:49 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 26 19:08:49 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:49 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:49 music go-librespot[26902]: go-librespot daemon starting... Dec 26 19:08:49 music go-librespot[26903]: time="2025-12-26T19:08:49-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:49 music go-librespot[26903]: time="2025-12-26T19:08:49-05:00" level=debug msg="app state loaded" Dec 26 19:08:49 music go-librespot[26903]: time="2025-12-26T19:08:49-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=info msg="zeroconf server listening on port 45329" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=debug msg="obtained new client token: AACEwxwjn09OJDkSFiE+Zvpz/bL6B5loem8b2LjtNqYb4OXNlLqFB6ov9o5LShdmNLy9C5kknTJcltWK8d2hddhWyzOCsrkPeszc3ovLQ6fskyw1PRSdcv4MLwgAnyUpexrgMELI3HRkvit06rKFIvnS1a/rzMusyfq8BlcKqvGzd/m5B3v5Gqj3FBU5/vhCTe0yrVr5RmbfEmg23Wyk2VMSj48x6DW9YvSCHFRXKZ5XnWwjY2MZe4Re" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=debug msg="completed challenge" Dec 26 19:08:50 music go-librespot[26903]: time="2025-12-26T19:08:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:51 music volumio[26887]: info: ------------------------------------------- Dec 26 19:08:51 music volumio[26887]: info: ----- Volumio3 ---- Dec 26 19:08:51 music volumio[26887]: info: ------------------------------------------- Dec 26 19:08:51 music volumio[26887]: info: ----- System startup ---- Dec 26 19:08:51 music volumio[26887]: info: ------------------------------------------- Dec 26 19:08:51 music go-librespot[26903]: time="2025-12-26T19:08:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:08:51 music go-librespot[26903]: time="2025-12-26T19:08:51-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:51 music go-librespot[26903]: time="2025-12-26T19:08:51-05:00" level=debug msg="completed challenge" Dec 26 19:08:51 music go-librespot[26903]: time="2025-12-26T19:08:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:51 music go-librespot[26903]: time="2025-12-26T19:08:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:08:51 music volumio[26887]: info: MYVOLUMIO Environment detected Dec 26 19:08:52 music go-librespot[26903]: time="2025-12-26T19:08:52-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:52 music go-librespot[26903]: time="2025-12-26T19:08:52-05:00" level=debug msg="completed challenge" Dec 26 19:08:52 music volumio[26887]: info: Plugin folders cleanup Dec 26 19:08:52 music volumio[26887]: info: Scanning into folder /volumio/app/plugins/ Dec 26 19:08:52 music volumio[26887]: info: Scanning category audio_interface Dec 26 19:08:52 music volumio[26887]: info: Scanning category miscellanea Dec 26 19:08:52 music volumio[26887]: info: Scanning category music_service Dec 26 19:08:52 music volumio[26887]: info: Scanning category plugins.json Dec 26 19:08:52 music volumio[26887]: info: Scanning category system_controller Dec 26 19:08:52 music volumio[26887]: info: Scanning category user_interface Dec 26 19:08:52 music volumio[26887]: info: Scanning into folder /data/plugins/ Dec 26 19:08:52 music volumio[26887]: info: Scanning category music_service Dec 26 19:08:52 music volumio[26887]: info: Plugin folders cleanup completed Dec 26 19:08:52 music volumio[26887]: info: ------------------------------------------- Dec 26 19:08:52 music volumio[26887]: info: ----- Core plugins startup ---- Dec 26 19:08:52 music volumio[26887]: info: ------------------------------------------- Dec 26 19:08:52 music volumio[26887]: info: Loading plugins from folder /volumio/app/plugins/ Dec 26 19:08:52 music volumio[26887]: info: Adding plugin upnp to MyMusic Plugins Dec 26 19:08:52 music volumio[26887]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 26 19:08:52 music volumio[26887]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 26 19:08:52 music volumio[26887]: info: Loading plugins from folder /data/plugins/ Dec 26 19:08:52 music volumio[26887]: info: Loading plugin "system"... Dec 26 19:08:52 music go-librespot[26903]: time="2025-12-26T19:08:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:52 music volumio[26887]: info: Loading plugin "appearance"... Dec 26 19:08:52 music go-librespot[26903]: time="2025-12-26T19:08:52-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 19:08:52 music go-librespot[26903]: time="2025-12-26T19:08:52-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:52 music go-librespot[26903]: time="2025-12-26T19:08:52-05:00" level=debug msg="completed challenge" Dec 26 19:08:52 music go-librespot[26903]: time="2025-12-26T19:08:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "network"... Dec 26 19:08:53 music volumio[26887]: info: Refreshing Cached IP Addresses Dec 26 19:08:53 music sudo[26926]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 19:08:53 music sudo[26926]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:53 music sudo[26928]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 19:08:53 music sudo[26928]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:53 music sudo[26926]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "services"... Dec 26 19:08:53 music sudo[26928]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "alsa_controller"... Dec 26 19:08:53 music sudo[26937]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 26 19:08:53 music sudo[26937]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:53 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "wizard"... Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "networkfs"... Dec 26 19:08:53 music volumio[26887]: info: Starting Udev Watcher for removable devices Dec 26 19:08:53 music go-librespot[26903]: time="2025-12-26T19:08:53-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 26 19:08:53 music volumio[26887]: info: Ignoring mount for partition: boot Dec 26 19:08:53 music volumio[26887]: info: Ignoring mount for partition: volumio Dec 26 19:08:53 music volumio[26887]: info: Ignoring mount for partition: volumio_data Dec 26 19:08:53 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "volumio_command_line_client"... Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "upnp"... Dec 26 19:08:53 music volumio[26887]: info: [1766794133404] Starting Upmpd Daemon Dec 26 19:08:53 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "my_music"... Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "mpd"... Dec 26 19:08:53 music volumio[26887]: info: Loading plugin "upnp_browser"... Dec 26 19:08:53 music sudo[26937]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:53 music volumio-remote-updater[735]: [2025-12-27 00:08:53] [connect] Successful connection Dec 26 19:08:54 music go-librespot[26903]: time="2025-12-26T19:08:54-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:54 music go-librespot[26903]: time="2025-12-26T19:08:54-05:00" level=debug msg="completed challenge" Dec 26 19:08:54 music go-librespot[26903]: time="2025-12-26T19:08:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:54 music go-librespot[26903]: time="2025-12-26T19:08:54-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:08:55 music go-librespot[26903]: time="2025-12-26T19:08:55-05:00" level=debug msg="completed keyexchange" Dec 26 19:08:55 music go-librespot[26903]: time="2025-12-26T19:08:55-05:00" level=debug msg="completed challenge" Dec 26 19:08:55 music go-librespot[26903]: time="2025-12-26T19:08:55-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:55 music go-librespot[26903]: time="2025-12-26T19:08:55-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:08:55 music volumio[26887]: info: Starting UPNP Browser Dec 26 19:08:55 music volumio[26887]: info: Loading plugin "alarm-clock"... Dec 26 19:08:55 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:08:55 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:08:55 music volumio[26887]: info: Loading plugin "airplay_emulation"... Dec 26 19:08:55 music volumio[26887]: info: Starting Shairport Sync Dec 26 19:08:55 music volumio[26887]: info: Loading plugin "last_100"... Dec 26 19:08:55 music volumio[26887]: info: Loading plugin "webradio"... Dec 26 19:08:55 music volumio[26887]: info: Loading plugin "i2s_dacs"... Dec 26 19:08:55 music volumio[26887]: info: I2S DAC not set, start Auto-detection Dec 26 19:08:55 music volumio[26887]: info: Loading plugin "volumiodiscovery"... Dec 26 19:08:55 music volumio[26887]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:55 music volumio[26887]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:55 music volumio[26887]: *** WARNING *** For more information see Dec 26 19:08:55 music volumio[26887]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:55 music volumio[26887]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:55 music volumio[26887]: *** WARNING *** For more information see Dec 26 19:08:55 music node[26887]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:55 music node[26887]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:55 music node[26887]: *** WARNING *** For more information see Dec 26 19:08:55 music node[26887]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 19:08:55 music node[26887]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:08:55 music node[26887]: *** WARNING *** For more information see Dec 26 19:08:55 music volumio[26887]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 26 19:08:55 music volumio[26887]: info: Discovery: Started advertising with name: music Dec 26 19:08:55 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:08:55 music volumio[26887]: info: Loading plugin "spop"... Dec 26 19:08:56 music volumio[26887]: info: Loading plugin "outputs"... Dec 26 19:08:56 music volumio[26887]: info: Loading plugin "albumart"... Dec 26 19:08:56 music volumio[26887]: info: Plugin example_plugin is not enabled Dec 26 19:08:56 music volumio[26887]: info: Loading plugin "inputs"... Dec 26 19:08:56 music volumio[26887]: info: Loading plugin "updater_comm"... Dec 26 19:08:56 music volumio[26887]: info: Plugin mpdemulation is not enabled Dec 26 19:08:56 music volumio[26887]: info: Loading plugin "rest_api"... Dec 26 19:08:56 music volumio[26887]: info: Loading plugin "websocket"... Dec 26 19:08:57 music volumio[26887]: info: Starting Socket.io Server version 1.7.4 Dec 26 19:08:57 music volumio[26887]: info: Loading i18n strings for locale en Dec 26 19:08:57 music volumio[26887]: Updating browse sources language Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::initPlayerControls Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:57 music volumio[26887]: Express server listening on port 3000 Dec 26 19:08:57 music volumio[26887]: [Metrics] WebUI: 6s 575.77ms Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::resetVolumioState Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::getcurrentVolume Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: Volumio Network Manager: Network status updated: 1 Dec 26 19:08:57 music volumio-remote-updater[735]: [2025-12-27 00:08:57] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766794133 101 Dec 26 19:08:57 music volumio[26961]: Forking 3 albumart workers Dec 26 19:08:57 music volumio[26887]: 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 26 19:08:57 music volumio[26887]: info: VolumeController:: Volume=86 Mute =false Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::pushState Dec 26 19:08:57 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::updateTrackBlock Dec 26 19:08:57 music volumio[26887]: info: CorePlayQueue::getTrackBlock Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 19:08:57 music volumio[26887]: info: Reloading queue from file Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::setRepeat null single undefined Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::pushState Dec 26 19:08:57 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::setRandom null Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::pushState Dec 26 19:08:57 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:57 music volumio[26887]: info: Setting Device type: Raspberry PI Dec 26 19:08:57 music volumio[26887]: info: VolumeController:: Volume=86 Mute =false Dec 26 19:08:57 music volumio[26887]: info: CoreStateMachine::pushState Dec 26 19:08:57 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioPushState Dec 26 19:08:57 music volumio[26887]: info: Completed loading Core Plugins Dec 26 19:08:57 music volumio[26887]: info: Preparing to generate the ALSA configuration file Dec 26 19:08:57 music volumio[26887]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 26 19:08:57 music volumio[26887]: info: Discovery: Found device music Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioGetState Dec 26 19:08:57 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:57 music volumio[26887]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 26 19:08:57 music volumio[26887]: info: Discovery: Found device music Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioGetState Dec 26 19:08:57 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:08:57 music volumio[26887]: info: Asound.conf file unchanged, so no further update is needed Dec 26 19:08:57 music volumio[26887]: info: Output device has changed, restarting MPD Dec 26 19:08:57 music volumio[26887]: info: Output device has changed, restarting Shairport Sync Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:57 music sudo[27017]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 19:08:57 music sudo[27017]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:57 music sudo[27017]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:57 music sudo[27018]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 19:08:57 music sudo[27018]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:57 music volumio[26887]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:57 music volumio[26887]: info: ___________ START PLUGINS ___________ Dec 26 19:08:57 music volumio[26887]: info: ControllerMpd::onStart: Initializing MPD Dec 26 19:08:57 music volumio[26887]: info: Creating MPD Configuration file Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:57 music volumio[26887]: info: [1766794137853] CoreMusicLibrary::Adding element Media Servers Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:57 music volumio[26887]: info: UPNP Browser: Client initialized successfully Dec 26 19:08:57 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 26 19:08:57 music sudo[27026]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 19:08:57 music sudo[27026]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:57 music sudo[27028]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 19:08:57 music sudo[27028]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:57 music sudo[27026]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:57 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:57 music systemd[1]: mpd.service: Deactivated successfully. Dec 26 19:08:57 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 19:08:57 music systemd[1]: mpd.service: Consumed 4.153s CPU time. Dec 26 19:08:57 music systemd[1]: mpd.socket: Deactivated successfully. Dec 26 19:08:57 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 19:08:57 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 19:08:58 music volumio[26887]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:58 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 19:08:58 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 19:08:58 music volumio[26887]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:58 music volumio[26887]: info: [1766794138065] CoreMusicLibrary::Adding element Last_100 Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:08:58 music volumio[26887]: info: [1766794138072] CoreMusicLibrary::Adding element Webradio Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:58 music systemd[1]: mpd.service: Deactivated successfully. Dec 26 19:08:58 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 19:08:58 music systemd[1]: mpd.socket: Deactivated successfully. Dec 26 19:08:58 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 19:08:58 music volumio[26887]: info: Initializing BBC Radios Dec 26 19:08:58 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 19:08:58 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 19:08:58 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:08:58 music volumio[26887]: info: Creating Spotify config file Dec 26 19:08:58 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:08:58 music sudo[27044]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 19:08:58 music sudo[27044]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 19:08:58 music sudo[27044]: pam_unix(sudo:session): session closed for user root Dec 26 19:08:58 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 26 19:08:58 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:58 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:08:58 music go-librespot[27058]: go-librespot daemon starting... Dec 26 19:08:58 music go-librespot[27059]: time="2025-12-26T19:08:58-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:08:59 music volumio[26887]: info: Volumio Calling Home Dec 26 19:08:59 music go-librespot[27059]: time="2025-12-26T19:08:59-05:00" level=info msg="zeroconf server listening on port 41731" Dec 26 19:08:59 music volumio[26978]: Starting albumart workers Dec 26 19:08:59 music volumio[26979]: Starting albumart workers Dec 26 19:08:59 music volumio[26887]: info: MPD Permissions set Dec 26 19:08:59 music volumio[26887]: info: MPD Permissions set Dec 26 19:08:59 music volumio[26977]: Starting albumart workers Dec 26 19:08:59 music volumio[26887]: info: Volumio called home Dec 26 19:08:59 music volumio[26887]: info: Spotify config file written Dec 26 19:08:59 music sudo[27072]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 26 19:08:59 music sudo[27072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:08:59 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 26 19:08:59 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 26 19:09:00 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:00 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:00 music go-librespot[27074]: go-librespot daemon starting... Dec 26 19:09:00 music sudo[27072]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=debug msg="app state loaded" Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:09:00 music volumio[26887]: 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 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:00 music volumio[26887]: info: No need to fix Spotify hosts Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=info msg="zeroconf server listening on port 39075" Dec 26 19:09:00 music volumio[26887]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=debug msg="obtained new client token: AADZiI9Yp4SDT9ZJhk2s40SemfVZ63ApdIYwbkBE+QvzwCvE2cP1RFly0ZrpJ2hOETNnaQ29gLh71vgQzIV3OpgGDDjz+Hg6UBsny0DVutdONbpR6+8N4Clew4Q1zX6pxMOTJ2guZm1yMRGNn+8ssBqt3OTvAMWEk0OQ56HJXk2wBVEfNSHVGEsuNqpyGzsuAWJF6K1XdiE3qPjm5bKYdADwjIxM16qRl6hzveVsZZGSgHY4RDewXoN/" Dec 26 19:09:00 music volumio[26887]: info: Starting Shairport Sync Dec 26 19:09:00 music volumio[26887]: info: Starting Shairport Sync Dec 26 19:09:00 music sudo[27110]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:09:00 music sudo[27110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:09:00 music volumio[26887]: info: Starting Shairport Sync Dec 26 19:09:00 music sudo[27113]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:09:00 music sudo[27113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:00 music go-librespot[27076]: time="2025-12-26T19:09:00-05:00" level=debug msg="completed challenge" Dec 26 19:09:00 music sudo[27115]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:09:00 music sudo[27115]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:00 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 19:09:01 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 19:09:01 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:09:01 music systemd[1]: shairport-sync.service: Consumed 1.848s CPU time. Dec 26 19:09:01 music go-librespot[27076]: time="2025-12-26T19:09:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:01 music volumio[26887]: info: CoreCommandRouter::volumioGetState Dec 26 19:09:01 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:01 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:09:01 music sudo[27110]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:01 music sudo[27113]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:01 music volumio[26887]: info: Shairport-Sync Started Dec 26 19:09:01 music volumio[26887]: Error adding Membership: Error: addMembership EINVAL Dec 26 19:09:01 music volumio[26887]: info: Shairport-Sync Started Dec 26 19:09:01 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 19:09:01 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 19:09:01 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:09:01 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:09:01 music sudo[27115]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:01 music volumio[26887]: info: Shairport-Sync Started Dec 26 19:09:01 music go-librespot[27076]: time="2025-12-26T19:09:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:09:01 music go-librespot[27076]: time="2025-12-26T19:09:01-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:01 music go-librespot[27076]: time="2025-12-26T19:09:01-05:00" level=debug msg="completed challenge" Dec 26 19:09:01 music go-librespot[27076]: time="2025-12-26T19:09:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:02 music go-librespot[27076]: time="2025-12-26T19:09:02-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.255.62:80: connect: connection refused" Dec 26 19:09:02 music go-librespot[27076]: time="2025-12-26T19:09:02-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 19:09:02 music go-librespot[27076]: time="2025-12-26T19:09:02-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:02 music go-librespot[27076]: time="2025-12-26T19:09:02-05:00" level=debug msg="completed challenge" Dec 26 19:09:02 music go-librespot[27076]: time="2025-12-26T19:09:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:02 music mpd[27057]: 2025-12-26T19:09:02 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 19:09:02 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 26 19:09:02 music sudo[27028]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:02 music sudo[27018]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:02 music volumio[26887]: info: Completed starting Core Plugins Dec 26 19:09:02 music volumio[26887]: info: ------------------------------------------- Dec 26 19:09:02 music volumio[26887]: info: ----- MyVolumio plugins startup ---- Dec 26 19:09:02 music volumio[26887]: info: ------------------------------------------- Dec 26 19:09:02 music volumio[26887]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 26 19:09:02 music volumio[26887]: error: MPD error: The expression evaluated to a falsy value: Dec 26 19:09:02 music volumio[26887]: assert.ok(self.idling) Dec 26 19:09:02 music volumio[26887]: error: The expression evaluated to a falsy value: Dec 26 19:09:02 music volumio[26887]: assert.ok(self.idling) Dec 26 19:09:02 music volumio[26887]: info: MPD running with PID27057 Dec 26 19:09:02 music volumio[26887]: ,establishing connection Dec 26 19:09:02 music volumio[26887]: error: updateQueue error: null Dec 26 19:09:02 music volumio[26887]: error: updateQueue error: null Dec 26 19:09:03 music go-librespot[27076]: time="2025-12-26T19:09:03-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 26 19:09:03 music go-librespot[27076]: time="2025-12-26T19:09:03-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:03 music go-librespot[27076]: time="2025-12-26T19:09:03-05:00" level=debug msg="completed challenge" Dec 26 19:09:03 music sudo[27161]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 19:09:03 music sudo[27161]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:03 music sudo[27161]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:03 music sudo[27163]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 19:09:03 music sudo[27163]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:03 music sudo[27163]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:03 music sudo[27166]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 26 19:09:03 music sudo[27166]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:03 music sudo[27166]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:03 music volumio[26887]: info: Upmpdcli Daemon Started Dec 26 19:09:03 music go-librespot[27076]: time="2025-12-26T19:09:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:03 music volumio[26887]: info: go-librespot daemon successfully initialized Dec 26 19:09:04 music go-librespot[27076]: time="2025-12-26T19:09:04-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:09:04 music go-librespot[27076]: time="2025-12-26T19:09:04-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:04 music go-librespot[27076]: time="2025-12-26T19:09:04-05:00" level=debug msg="completed challenge" Dec 26 19:09:04 music go-librespot[27076]: time="2025-12-26T19:09:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:05 music go-librespot[27076]: time="2025-12-26T19:09:05-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:09:05 music go-librespot[27076]: time="2025-12-26T19:09:05-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:05 music go-librespot[27076]: time="2025-12-26T19:09:05-05:00" level=debug msg="completed challenge" Dec 26 19:09:05 music go-librespot[27076]: time="2025-12-26T19:09:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:05 music go-librespot[27076]: time="2025-12-26T19:09:05-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:05 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:09:05 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:09:05 music sudo[27170]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 19:09:05 music sudo[27170]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:05 music sudo[27173]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 19:09:05 music sudo[27173]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:05 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 19:09:05 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 19:09:05 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 19:09:05 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 19:09:05 music mpd_monitor.sh[27175]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 19:09:05 music sudo[27170]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:05 music volumio[26887]: info: Successfully started MPD Monitor Dec 26 19:09:05 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 19:09:05 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 19:09:05 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 19:09:05 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 19:09:05 music sudo[27173]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:05 music mpd_monitor.sh[27179]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 19:09:05 music volumio[26887]: info: Successfully started MPD Monitor Dec 26 19:09:06 music volumio[26887]: info: Initializing connection to go-librespot Websocket Dec 26 19:09:06 music volumio[26887]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 19:09:07 music volumio[26887]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 26 19:09:08 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 26 19:09:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:08 music go-librespot[27183]: go-librespot daemon starting... Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=debug msg="app state loaded" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=info msg="zeroconf server listening on port 33415" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=debug msg="obtained new client token: AADm7o7BCvxBMunMPt8bXeo6A19wv7cD5qCYrgykw4Vc6h4PwTDCrw0PqRw10RoyRPFKrdIn14HeakbR5t8v/gc1ULplhrwZ8CltRBQPeNdDFlOITD0Lxn4IxUKL1pWxMqXL4O9L91y6qBy48k59cqpo0mzfK8abYjy9tpC3Oph9X860JX2hgpibskRyUh2NGE+gYOG4M4jbioNRgmoBfkgSiE60MRQQvk8M4iyq42gYBZ/54+5DF3Mp" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:08 music go-librespot[27184]: time="2025-12-26T19:09:08-05:00" level=debug msg="completed challenge" Dec 26 19:09:09 music go-librespot[27184]: time="2025-12-26T19:09:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:09 music go-librespot[27184]: time="2025-12-26T19:09:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:09:09 music go-librespot[27184]: time="2025-12-26T19:09:09-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:09 music go-librespot[27184]: time="2025-12-26T19:09:09-05:00" level=debug msg="completed challenge" Dec 26 19:09:09 music go-librespot[27184]: time="2025-12-26T19:09:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:09 music volumio[26887]: info: Initializing connection to go-librespot Websocket Dec 26 19:09:09 music go-librespot[27184]: time="2025-12-26T19:09:09-05:00" level=debug msg="new websocket client" Dec 26 19:09:09 music volumio[26887]: info: Connection to go-librespot Websocket established Dec 26 19:09:10 music go-librespot[27184]: time="2025-12-26T19:09:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:09:10 music go-librespot[27184]: time="2025-12-26T19:09:10-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:10 music go-librespot[27184]: time="2025-12-26T19:09:10-05:00" level=debug msg="completed challenge" Dec 26 19:09:10 music go-librespot[27184]: time="2025-12-26T19:09:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 26 19:09:10 music volumio[26887]: info: Adding plugin bluetooth to MyMusic Plugins Dec 26 19:09:10 music volumio[26887]: info: Adding plugin multiroom to MyMusic Plugins Dec 26 19:09:10 music volumio[26887]: info: Adding plugin metavolumio to MyMusic Plugins Dec 26 19:09:10 music volumio[26887]: info: Adding plugin cd_controller to MyMusic Plugins Dec 26 19:09:10 music volumio[26887]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 26 19:09:10 music volumio[26887]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 26 19:09:10 music volumio[26887]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 26 19:09:10 music volumio[26887]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 26 19:09:11 music go-librespot[27184]: time="2025-12-26T19:09:11-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 26 19:09:11 music go-librespot[27184]: time="2025-12-26T19:09:11-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:11 music go-librespot[27184]: time="2025-12-26T19:09:11-05:00" level=debug msg="completed challenge" Dec 26 19:09:11 music go-librespot[27184]: time="2025-12-26T19:09:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:11 music volumio[26887]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 26 19:09:11 music volumio[26887]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 26 19:09:11 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:11 music volumio[26887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:11 music volumio[26887]: info: Starting MyVolumio Remote Streaming Endpoints Dec 26 19:09:11 music volumio[26887]: info: MyVolumio login type: Token Dec 26 19:09:12 music volumio[26887]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 26 19:09:12 music volumio[26887]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 26 19:09:12 music go-librespot[27184]: time="2025-12-26T19:09:12-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 26 19:09:12 music go-librespot[27184]: time="2025-12-26T19:09:12-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:12 music go-librespot[27184]: time="2025-12-26T19:09:12-05:00" level=debug msg="completed challenge" Dec 26 19:09:12 music go-librespot[27184]: time="2025-12-26T19:09:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:12 music volumio[26887]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 26 19:09:12 music volumio[26887]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 26 19:09:12 music volumio[26887]: info: Streaming services startup Dec 26 19:09:12 music volumio[26887]: info: Starting Streaming Daemon Dec 26 19:09:12 music sudo[27195]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 26 19:09:12 music sudo[27195]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:12 music volumio[26887]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 26 19:09:13 music sudo[27195]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:13 music volumio[26887]: info: Getting Spotify volume Dec 26 19:09:13 music volumio[26887]: error: Cannot start Volumio Streaming Daemon Dec 26 19:09:13 music volumio[26887]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 26 19:09:13 music volumio[26887]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 26 19:09:13 music volumio[26887]: 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 26 19:09:13 music go-librespot[27184]: time="2025-12-26T19:09:13-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:09:13 music volumio[26887]: info: CoreCommandRouter::volumioGetState Dec 26 19:09:13 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:13 music volumio[26887]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 26 19:09:13 music volumio[26887]: SPOTIFY: SPOTIFY VOLUME undefined Dec 26 19:09:13 music volumio[26887]: SPOTIFY: VOLUMIO VOLUME 86 Dec 26 19:09:13 music volumio[26887]: info: Aligning Spotify Volume to Volumio Volume Dec 26 19:09:13 music volumio[26887]: info: CoreCommandRouter::volumioGetState Dec 26 19:09:13 music volumio[26887]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:13 music volumio[26887]: info: Setting Spotify Volume from Volumio: 86 Dec 26 19:09:13 music go-librespot[27184]: time="2025-12-26T19:09:13-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:13 music go-librespot[27184]: time="2025-12-26T19:09:13-05:00" level=debug msg="completed challenge" Dec 26 19:09:13 music go-librespot[27184]: time="2025-12-26T19:09:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:13 music go-librespot[27184]: time="2025-12-26T19:09:13-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:13 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:09:13 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:09:13 music volumio[26887]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 26 19:09:13 music volumio[26887]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 19:09:13 music volumio[26887]: Error: socket hang up Dec 26 19:09:13 music volumio[26887]: at connResetException (node:internal/errors:720:14) Dec 26 19:09:13 music volumio[26887]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 26 19:09:13 music volumio[26887]: at Socket.emit (node:events:526:35) Dec 26 19:09:13 music volumio[26887]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 26 19:09:13 music volumio[26887]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 26 19:09:13 music volumio[26887]: code: 'ECONNRESET', Dec 26 19:09:13 music volumio[26887]: response: undefined Dec 26 19:09:13 music volumio[26887]: } Dec 26 19:09:13 music volumio[26887]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 19:09:14 music sudo[27230]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 19:08' Dec 26 19:09:14 music sudo[27230]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:14 music sudo[27230]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:15 music volumio-remote-updater[735]: [2025-12-27 00:09:15] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 26 19:09:15 music volumio-remote-updater[735]: [2025-12-27 00:09:15] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 26 19:09:15 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:09:15 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 26 19:09:15 music systemd[1]: volumio.service: Consumed 26.887s CPU time. Dec 26 19:09:15 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 26 19:09:15 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 26 19:09:15 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2858. Dec 26 19:09:15 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 26 19:09:15 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 26 19:09:15 music systemd[1]: volumio.service: Consumed 26.887s CPU time. Dec 26 19:09:15 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 26 19:09:15 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 26 19:09:16 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 26 19:09:16 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:16 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:16 music go-librespot[27263]: go-librespot daemon starting... Dec 26 19:09:16 music go-librespot[27264]: time="2025-12-26T19:09:16-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:09:16 music go-librespot[27264]: time="2025-12-26T19:09:16-05:00" level=debug msg="app state loaded" Dec 26 19:09:16 music go-librespot[27264]: time="2025-12-26T19:09:16-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:09:16 music go-librespot[27264]: time="2025-12-26T19:09:16-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:09:16 music go-librespot[27264]: time="2025-12-26T19:09:16-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:09:16 music go-librespot[27264]: time="2025-12-26T19:09:16-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:09:17 music go-librespot[27264]: time="2025-12-26T19:09:17-05:00" level=info msg="zeroconf server listening on port 46061" Dec 26 19:09:17 music go-librespot[27264]: time="2025-12-26T19:09:17-05:00" level=debug msg="obtained new client token: AABPF4im7g22hnS1ZeFQ4++V4axAsUgIyZ/rPrkDQwshwrl5So/hldIFNj8lRO0IS8ga5vsmqkdrJzFarZx9cLU0WHdciYYwcm/df57EPQAJ8w21BVJySzc0JHwl057VCXkLVDI2unLMVVV+0gKCgtzCBAdMZ98w3p6IFb5mjrHGJBflkfSMLtnf9+Gkay4mwMd18z9QO96QQoC8PDPUfOiLm1guHkkC3W2tawuA8F45QM9jrP5ObQ==" Dec 26 19:09:17 music go-librespot[27264]: time="2025-12-26T19:09:17-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Dec 26 19:09:17 music go-librespot[27264]: time="2025-12-26T19:09:17-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Dec 26 19:09:17 music go-librespot[27264]: time="2025-12-26T19:09:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:09:17 music volumio[27248]: info: ------------------------------------------- Dec 26 19:09:17 music volumio[27248]: info: ----- Volumio3 ---- Dec 26 19:09:17 music volumio[27248]: info: ------------------------------------------- Dec 26 19:09:17 music volumio[27248]: info: ----- System startup ---- Dec 26 19:09:17 music volumio[27248]: info: ------------------------------------------- Dec 26 19:09:17 music go-librespot[27264]: time="2025-12-26T19:09:17-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:17 music go-librespot[27264]: time="2025-12-26T19:09:17-05:00" level=debug msg="completed challenge" Dec 26 19:09:17 music go-librespot[27264]: time="2025-12-26T19:09:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:18 music volumio[27248]: info: MYVOLUMIO Environment detected Dec 26 19:09:18 music go-librespot[27264]: time="2025-12-26T19:09:18-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 26 19:09:18 music volumio[27248]: info: Plugin folders cleanup Dec 26 19:09:18 music volumio[27248]: info: Scanning into folder /volumio/app/plugins/ Dec 26 19:09:18 music volumio[27248]: info: Scanning category audio_interface Dec 26 19:09:18 music volumio[27248]: info: Scanning category miscellanea Dec 26 19:09:18 music volumio[27248]: info: Scanning category music_service Dec 26 19:09:18 music volumio[27248]: info: Scanning category plugins.json Dec 26 19:09:18 music volumio[27248]: info: Scanning category system_controller Dec 26 19:09:18 music volumio[27248]: info: Scanning category user_interface Dec 26 19:09:18 music volumio[27248]: info: Scanning into folder /data/plugins/ Dec 26 19:09:18 music volumio[27248]: info: Scanning category music_service Dec 26 19:09:18 music volumio[27248]: info: Plugin folders cleanup completed Dec 26 19:09:18 music volumio[27248]: info: ------------------------------------------- Dec 26 19:09:18 music volumio[27248]: info: ----- Core plugins startup ---- Dec 26 19:09:18 music volumio[27248]: info: ------------------------------------------- Dec 26 19:09:18 music volumio[27248]: info: Loading plugins from folder /volumio/app/plugins/ Dec 26 19:09:18 music volumio[27248]: info: Adding plugin upnp to MyMusic Plugins Dec 26 19:09:18 music volumio[27248]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 26 19:09:18 music volumio[27248]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 26 19:09:18 music volumio[27248]: info: Loading plugins from folder /data/plugins/ Dec 26 19:09:18 music volumio[27248]: info: Loading plugin "system"... Dec 26 19:09:18 music volumio[27248]: info: Loading plugin "appearance"... Dec 26 19:09:18 music go-librespot[27264]: time="2025-12-26T19:09:18-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:18 music go-librespot[27264]: time="2025-12-26T19:09:18-05:00" level=debug msg="completed challenge" Dec 26 19:09:18 music go-librespot[27264]: time="2025-12-26T19:09:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:19 music go-librespot[27264]: time="2025-12-26T19:09:19-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 26 19:09:19 music go-librespot[27264]: time="2025-12-26T19:09:19-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:19 music go-librespot[27264]: time="2025-12-26T19:09:19-05:00" level=debug msg="completed challenge" Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "network"... Dec 26 19:09:19 music volumio[27248]: info: Refreshing Cached IP Addresses Dec 26 19:09:19 music sudo[27286]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 19:09:19 music sudo[27286]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:19 music sudo[27286]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:19 music go-librespot[27264]: time="2025-12-26T19:09:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:19 music sudo[27288]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 19:09:19 music sudo[27288]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "services"... Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "alsa_controller"... Dec 26 19:09:19 music sudo[27288]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:19 music sudo[27296]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 26 19:09:19 music sudo[27296]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:19 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "wizard"... Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "networkfs"... Dec 26 19:09:19 music volumio[27248]: info: Starting Udev Watcher for removable devices Dec 26 19:09:19 music volumio[27248]: info: Ignoring mount for partition: boot Dec 26 19:09:19 music volumio[27248]: info: Ignoring mount for partition: volumio Dec 26 19:09:19 music volumio[27248]: info: Ignoring mount for partition: volumio_data Dec 26 19:09:19 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "volumio_command_line_client"... Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "upnp"... Dec 26 19:09:19 music volumio[27248]: info: [1766794159734] Starting Upmpd Daemon Dec 26 19:09:19 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "my_music"... Dec 26 19:09:19 music volumio[27248]: info: Loading plugin "mpd"... Dec 26 19:09:20 music volumio[27248]: info: Loading plugin "upnp_browser"... Dec 26 19:09:20 music volumio-remote-updater[735]: [2025-12-27 00:09:20] [connect] Successful connection Dec 26 19:09:20 music go-librespot[27264]: time="2025-12-26T19:09:20-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:09:20 music sudo[27296]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:20 music go-librespot[27264]: time="2025-12-26T19:09:20-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:20 music go-librespot[27264]: time="2025-12-26T19:09:20-05:00" level=debug msg="completed challenge" Dec 26 19:09:20 music go-librespot[27264]: time="2025-12-26T19:09:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:20 music go-librespot[27264]: time="2025-12-26T19:09:20-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:09:21 music go-librespot[27264]: time="2025-12-26T19:09:21-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:21 music go-librespot[27264]: time="2025-12-26T19:09:21-05:00" level=debug msg="completed challenge" Dec 26 19:09:21 music go-librespot[27264]: time="2025-12-26T19:09:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:21 music go-librespot[27264]: time="2025-12-26T19:09:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:09:21 music volumio[27248]: info: Starting UPNP Browser Dec 26 19:09:21 music volumio[27248]: info: Loading plugin "alarm-clock"... Dec 26 19:09:21 music go-librespot[27264]: time="2025-12-26T19:09:21-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:21 music go-librespot[27264]: time="2025-12-26T19:09:21-05:00" level=debug msg="completed challenge" Dec 26 19:09:21 music go-librespot[27264]: time="2025-12-26T19:09:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:21 music go-librespot[27264]: time="2025-12-26T19:09:21-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:21 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:09:21 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:09:21 music volumio[27248]: info: Loading plugin "airplay_emulation"... Dec 26 19:09:21 music volumio[27248]: info: Starting Shairport Sync Dec 26 19:09:21 music volumio[27248]: info: Loading plugin "last_100"... Dec 26 19:09:21 music volumio[27248]: info: Loading plugin "webradio"... Dec 26 19:09:21 music volumio[27248]: info: Loading plugin "i2s_dacs"... Dec 26 19:09:21 music volumio[27248]: info: I2S DAC not set, start Auto-detection Dec 26 19:09:21 music volumio[27248]: info: Loading plugin "volumiodiscovery"... Dec 26 19:09:22 music volumio[27248]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 19:09:22 music volumio[27248]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:09:22 music volumio[27248]: *** WARNING *** For more information see Dec 26 19:09:22 music volumio[27248]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 19:09:22 music volumio[27248]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:09:22 music volumio[27248]: *** WARNING *** For more information see Dec 26 19:09:22 music node[27248]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 19:09:22 music node[27248]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:09:22 music node[27248]: *** WARNING *** For more information see Dec 26 19:09:22 music node[27248]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 19:09:22 music node[27248]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 19:09:22 music node[27248]: *** WARNING *** For more information see Dec 26 19:09:22 music volumio[27248]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 26 19:09:22 music volumio[27248]: info: Discovery: Started advertising with name: music Dec 26 19:09:22 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 19:09:22 music volumio[27248]: info: Loading plugin "spop"... Dec 26 19:09:23 music volumio[27248]: info: Loading plugin "outputs"... Dec 26 19:09:23 music volumio[27248]: info: Loading plugin "albumart"... Dec 26 19:09:23 music volumio[27248]: info: Plugin example_plugin is not enabled Dec 26 19:09:23 music volumio[27248]: info: Loading plugin "inputs"... Dec 26 19:09:23 music volumio[27248]: info: Loading plugin "updater_comm"... Dec 26 19:09:23 music volumio[27248]: info: Plugin mpdemulation is not enabled Dec 26 19:09:23 music volumio[27248]: info: Loading plugin "rest_api"... Dec 26 19:09:23 music volumio[27248]: info: Loading plugin "websocket"... Dec 26 19:09:23 music volumio[27248]: info: Starting Socket.io Server version 1.7.4 Dec 26 19:09:23 music volumio[27248]: info: Loading i18n strings for locale en Dec 26 19:09:23 music volumio[27248]: Updating browse sources language Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::initPlayerControls Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:09:23 music volumio[27248]: Express server listening on port 3000 Dec 26 19:09:23 music volumio[27248]: [Metrics] WebUI: 6s 613.67ms Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::resetVolumioState Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::getcurrentVolume Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:23 music volumio[27248]: info: Volumio Network Manager: Network status updated: 1 Dec 26 19:09:23 music volumio-remote-updater[735]: [2025-12-27 00:09:23] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766794160 101 Dec 26 19:09:23 music volumio[27321]: Forking 3 albumart workers Dec 26 19:09:23 music volumio[27248]: 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 26 19:09:23 music volumio[27248]: info: VolumeController:: Volume=86 Mute =false Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::pushState Dec 26 19:09:23 music volumio[27248]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::volumioPushState Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::updateTrackBlock Dec 26 19:09:23 music volumio[27248]: info: CorePlayQueue::getTrackBlock Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 19:09:23 music volumio[27248]: info: Reloading queue from file Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::setRepeat null single undefined Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::pushState Dec 26 19:09:23 music volumio[27248]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::volumioPushState Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::setRandom null Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::pushState Dec 26 19:09:23 music volumio[27248]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::volumioPushState Dec 26 19:09:23 music volumio[27248]: info: Setting Device type: Raspberry PI Dec 26 19:09:23 music volumio[27248]: info: VolumeController:: Volume=86 Mute =false Dec 26 19:09:23 music volumio[27248]: info: CoreStateMachine::pushState Dec 26 19:09:23 music volumio[27248]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::volumioPushState Dec 26 19:09:23 music volumio[27248]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 26 19:09:23 music volumio[27248]: info: Discovery: Found device music Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::volumioGetState Dec 26 19:09:23 music volumio[27248]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:23 music volumio[27248]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 26 19:09:23 music volumio[27248]: info: Discovery: Found device music Dec 26 19:09:23 music volumio[27248]: info: CoreCommandRouter::volumioGetState Dec 26 19:09:23 music volumio[27248]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:23 music volumio[27248]: info: Completed loading Core Plugins Dec 26 19:09:24 music volumio[27248]: info: Preparing to generate the ALSA configuration file Dec 26 19:09:24 music volumio[27248]: info: Asound.conf file unchanged, so no further update is needed Dec 26 19:09:24 music volumio[27248]: info: Output device has changed, restarting MPD Dec 26 19:09:24 music volumio[27248]: info: Output device has changed, restarting Shairport Sync Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:24 music sudo[27376]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 19:09:24 music volumio[27248]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:09:24 music sudo[27376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:24 music volumio[27248]: info: ___________ START PLUGINS ___________ Dec 26 19:09:24 music sudo[27376]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:24 music sudo[27378]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 19:09:24 music sudo[27378]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:24 music volumio[27248]: info: ControllerMpd::onStart: Initializing MPD Dec 26 19:09:24 music volumio[27248]: info: Creating MPD Configuration file Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:09:24 music volumio[27248]: info: [1766794164159] CoreMusicLibrary::Adding element Media Servers Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:09:24 music sudo[27386]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 19:09:24 music sudo[27386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:24 music volumio[27248]: info: UPNP Browser: Client initialized successfully Dec 26 19:09:24 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 26 19:09:24 music sudo[27386]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:24 music sudo[27388]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 19:09:24 music sudo[27388]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:24 music systemd[1]: mpd.service: Deactivated successfully. Dec 26 19:09:24 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 19:09:24 music systemd[1]: mpd.service: Consumed 4.149s CPU time. Dec 26 19:09:24 music systemd[1]: mpd.socket: Deactivated successfully. Dec 26 19:09:24 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 19:09:24 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 19:09:24 music volumio[27248]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:24 music volumio[27248]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:09:24 music volumio[27248]: info: [1766794164367] CoreMusicLibrary::Adding element Last_100 Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 19:09:24 music volumio[27248]: info: [1766794164372] CoreMusicLibrary::Adding element Webradio Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:09:24 music volumio[27248]: info: Initializing BBC Radios Dec 26 19:09:24 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 19:09:24 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 19:09:24 music systemd[1]: mpd.service: Deactivated successfully. Dec 26 19:09:24 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 19:09:24 music systemd[1]: mpd.socket: Deactivated successfully. Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:24 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 19:09:24 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 19:09:24 music volumio[27248]: info: Creating Spotify config file Dec 26 19:09:24 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:24 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 19:09:24 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 19:09:24 music sudo[27415]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 19:09:24 music sudo[27415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 19:09:24 music sudo[27415]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:24 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 26 19:09:24 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:24 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:24 music go-librespot[27418]: go-librespot daemon starting... Dec 26 19:09:25 music go-librespot[27419]: time="2025-12-26T19:09:25-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:09:25 music volumio[27248]: info: Volumio Calling Home Dec 26 19:09:25 music go-librespot[27419]: time="2025-12-26T19:09:25-05:00" level=info msg="zeroconf server listening on port 40215" Dec 26 19:09:25 music volumio[27340]: Starting albumart workers Dec 26 19:09:25 music volumio[27337]: Starting albumart workers Dec 26 19:09:25 music volumio[27338]: Starting albumart workers Dec 26 19:09:26 music volumio[27248]: info: MPD Permissions set Dec 26 19:09:26 music volumio[27248]: info: MPD Permissions set Dec 26 19:09:26 music volumio[27248]: info: Spotify config file written Dec 26 19:09:26 music sudo[27434]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 26 19:09:26 music sudo[27434]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:26 music volumio[27248]: 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 26 19:09:26 music volumio[27248]: info: Volumio called home Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 26 19:09:26 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 26 19:09:26 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:26 music go-librespot[27447]: go-librespot daemon starting... Dec 26 19:09:26 music sudo[27434]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:26 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 19:09:26 music go-librespot[27449]: time="2025-12-26T19:09:26-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:09:26 music go-librespot[27449]: time="2025-12-26T19:09:26-05:00" level=debug msg="app state loaded" Dec 26 19:09:26 music volumio[27248]: info: No need to fix Spotify hosts Dec 26 19:09:26 music go-librespot[27449]: time="2025-12-26T19:09:26-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:09:27 music volumio[27248]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=info msg="zeroconf server listening on port 35931" Dec 26 19:09:27 music volumio[27248]: info: Starting Shairport Sync Dec 26 19:09:27 music volumio[27248]: info: Starting Shairport Sync Dec 26 19:09:27 music volumio[27248]: info: Starting Shairport Sync Dec 26 19:09:27 music sudo[27475]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:09:27 music sudo[27475]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:27 music sudo[27477]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:09:27 music sudo[27477]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:27 music sudo[27479]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 19:09:27 music sudo[27479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=debug msg="obtained new client token: AABt4sG0ce8cYDBbh77x28gJXuf7n22CLCM8hEl0r/lf6UMwk6Ytu5myDZmpVsipfa2KhI2ZtMhhodh2j+jyxYsk+IRoUXPunTB9yVy+sdadnX0mHliepUcz2QKuavVq7QxiWh/VgmwFnDWRli7pWZOXBJ1E+TmISnIH1mnc18/sBfRVLqTcFSpoBZhMPwR63PhXWwi3zP5dQAiRlxlaZLgmk9DoBpzU/DCOVc7JoEKZfk12vOE9KWfg" Dec 26 19:09:27 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 19:09:27 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 19:09:27 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:09:27 music systemd[1]: shairport-sync.service: Consumed 1.885s CPU time. Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:09:27 music volumio[27248]: info: CoreCommandRouter::volumioGetState Dec 26 19:09:27 music volumio[27248]: info: CorePlayQueue::getTrack 0 Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=debug msg="completed challenge" Dec 26 19:09:27 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:09:27 music sudo[27475]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:27 music sudo[27477]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:27 music volumio[27248]: info: Shairport-Sync Started Dec 26 19:09:27 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 19:09:27 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 19:09:27 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:09:27 music volumio[27248]: Error adding Membership: Error: addMembership EINVAL Dec 26 19:09:27 music volumio[27248]: info: Shairport-Sync Started Dec 26 19:09:27 music go-librespot[27449]: time="2025-12-26T19:09:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:27 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 19:09:27 music sudo[27479]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:27 music volumio[27248]: info: Shairport-Sync Started Dec 26 19:09:28 music go-librespot[27449]: time="2025-12-26T19:09:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:09:28 music go-librespot[27449]: time="2025-12-26T19:09:28-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:28 music go-librespot[27449]: time="2025-12-26T19:09:28-05:00" level=debug msg="completed challenge" Dec 26 19:09:28 music go-librespot[27449]: time="2025-12-26T19:09:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:28 music go-librespot[27449]: time="2025-12-26T19:09:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:09:28 music go-librespot[27449]: time="2025-12-26T19:09:28-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:28 music go-librespot[27449]: time="2025-12-26T19:09:28-05:00" level=debug msg="completed challenge" Dec 26 19:09:28 music go-librespot[27449]: time="2025-12-26T19:09:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:29 music mpd[27417]: 2025-12-26T19:09:28 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 19:09:29 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 26 19:09:29 music sudo[27378]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:29 music sudo[27388]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:29 music volumio[27248]: info: Completed starting Core Plugins Dec 26 19:09:29 music volumio[27248]: info: ------------------------------------------- Dec 26 19:09:29 music volumio[27248]: info: ----- MyVolumio plugins startup ---- Dec 26 19:09:29 music volumio[27248]: info: ------------------------------------------- Dec 26 19:09:29 music volumio[27248]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 26 19:09:29 music volumio[27248]: error: MPD error: The expression evaluated to a falsy value: Dec 26 19:09:29 music volumio[27248]: assert.ok(self.idling) Dec 26 19:09:29 music volumio[27248]: error: The expression evaluated to a falsy value: Dec 26 19:09:29 music volumio[27248]: assert.ok(self.idling) Dec 26 19:09:29 music volumio[27248]: info: MPD running with PID27417 Dec 26 19:09:29 music volumio[27248]: ,establishing connection Dec 26 19:09:29 music volumio[27248]: error: updateQueue error: null Dec 26 19:09:29 music volumio[27248]: error: updateQueue error: null Dec 26 19:09:29 music go-librespot[27449]: time="2025-12-26T19:09:29-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 19:09:29 music go-librespot[27449]: time="2025-12-26T19:09:29-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:29 music go-librespot[27449]: time="2025-12-26T19:09:29-05:00" level=debug msg="completed challenge" Dec 26 19:09:29 music go-librespot[27449]: time="2025-12-26T19:09:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:29 music sudo[27520]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 19:09:29 music sudo[27520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:29 music sudo[27522]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 19:09:29 music sudo[27522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:29 music sudo[27520]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:29 music sudo[27522]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:29 music sudo[27525]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 26 19:09:29 music sudo[27525]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:29 music sudo[27525]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:29 music volumio[27248]: info: Upmpdcli Daemon Started Dec 26 19:09:30 music volumio[27248]: info: go-librespot daemon successfully initialized Dec 26 19:09:30 music go-librespot[27449]: time="2025-12-26T19:09:30-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 26 19:09:30 music go-librespot[27449]: time="2025-12-26T19:09:30-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:30 music go-librespot[27449]: time="2025-12-26T19:09:30-05:00" level=debug msg="completed challenge" Dec 26 19:09:30 music go-librespot[27449]: time="2025-12-26T19:09:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:31 music go-librespot[27449]: time="2025-12-26T19:09:31-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:09:31 music go-librespot[27449]: time="2025-12-26T19:09:31-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:31 music go-librespot[27449]: time="2025-12-26T19:09:31-05:00" level=debug msg="completed challenge" Dec 26 19:09:31 music go-librespot[27449]: time="2025-12-26T19:09:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:31 music go-librespot[27449]: time="2025-12-26T19:09:31-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:31 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:09:31 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:09:32 music sudo[27530]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 19:09:32 music sudo[27530]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:32 music sudo[27532]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 19:09:32 music sudo[27532]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:32 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 19:09:32 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 19:09:32 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 19:09:32 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 19:09:32 music mpd_monitor.sh[27535]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 19:09:32 music sudo[27532]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:32 music sudo[27530]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:32 music volumio[27248]: info: Successfully started MPD Monitor Dec 26 19:09:32 music volumio[27248]: info: Successfully started MPD Monitor Dec 26 19:09:33 music volumio[27248]: info: Initializing connection to go-librespot Websocket Dec 26 19:09:33 music volumio[27248]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 19:09:34 music volumio[27248]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 26 19:09:34 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 26 19:09:34 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:34 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 19:09:34 music go-librespot[27539]: go-librespot daemon starting... Dec 26 19:09:34 music go-librespot[27540]: time="2025-12-26T19:09:34-05:00" level=info msg="running go-librespot 0.6.2" Dec 26 19:09:34 music go-librespot[27540]: time="2025-12-26T19:09:34-05:00" level=debug msg="app state loaded" Dec 26 19:09:34 music go-librespot[27540]: time="2025-12-26T19:09:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 19:09:34 music go-librespot[27540]: time="2025-12-26T19:09:34-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 26 19:09:34 music go-librespot[27540]: time="2025-12-26T19:09:34-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 26 19:09:34 music go-librespot[27540]: time="2025-12-26T19:09:34-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 26 19:09:34 music go-librespot[27540]: time="2025-12-26T19:09:34-05:00" level=info msg="zeroconf server listening on port 38655" Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=debug msg="obtained new client token: AACmY45lTLzPkpjghxg5aSNH9dRp9OwGNAYFijJMVQ8Ln/As2fcj3wlrkeksbc0239R/rHxqtjAMavEnd7QiWOzm4R30GCZvorXZicuRNdymP2N7uPVH4TEGdW5owIq2cfkei5xW7kxLbWJmpqfsOQZOzggeRsuULv7CS265evK+pVe+CE3Cmd5tzwvX8zkIyqzWF9eqmkjlyhlvn1IuNrcBQSKCD/AQvPtrmMrZ1n1zSs07/gOe/w==" Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=debug msg="completed challenge" Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=debug msg="completed challenge" Dec 26 19:09:35 music go-librespot[27540]: time="2025-12-26T19:09:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:36 music volumio[27248]: info: Initializing connection to go-librespot Websocket Dec 26 19:09:36 music volumio[27248]: info: Connection to go-librespot Websocket established Dec 26 19:09:36 music go-librespot[27540]: time="2025-12-26T19:09:36-05:00" level=debug msg="new websocket client" Dec 26 19:09:36 music go-librespot[27540]: time="2025-12-26T19:09:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 26 19:09:36 music go-librespot[27540]: time="2025-12-26T19:09:36-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:36 music go-librespot[27540]: time="2025-12-26T19:09:36-05:00" level=debug msg="completed challenge" Dec 26 19:09:36 music go-librespot[27540]: time="2025-12-26T19:09:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:37 music go-librespot[27540]: time="2025-12-26T19:09:37-05:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Dec 26 19:09:37 music go-librespot[27540]: time="2025-12-26T19:09:37-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 26 19:09:37 music go-librespot[27540]: time="2025-12-26T19:09:37-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:37 music volumio[27248]: info: Adding plugin bluetooth to MyMusic Plugins Dec 26 19:09:37 music go-librespot[27540]: time="2025-12-26T19:09:37-05:00" level=debug msg="completed challenge" Dec 26 19:09:37 music volumio[27248]: info: Adding plugin multiroom to MyMusic Plugins Dec 26 19:09:37 music volumio[27248]: info: Adding plugin metavolumio to MyMusic Plugins Dec 26 19:09:37 music volumio[27248]: info: Adding plugin cd_controller to MyMusic Plugins Dec 26 19:09:37 music volumio[27248]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 26 19:09:37 music volumio[27248]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 26 19:09:37 music volumio[27248]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 26 19:09:37 music volumio[27248]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 26 19:09:37 music go-librespot[27540]: time="2025-12-26T19:09:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:38 music go-librespot[27540]: time="2025-12-26T19:09:38-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 26 19:09:38 music go-librespot[27540]: time="2025-12-26T19:09:38-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:38 music go-librespot[27540]: time="2025-12-26T19:09:38-05:00" level=debug msg="completed challenge" Dec 26 19:09:38 music go-librespot[27540]: time="2025-12-26T19:09:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:38 music volumio[27248]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 26 19:09:38 music volumio[27248]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 26 19:09:38 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:38 music volumio[27248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 19:09:38 music volumio[27248]: info: Starting MyVolumio Remote Streaming Endpoints Dec 26 19:09:38 music volumio[27248]: info: MyVolumio login type: Token Dec 26 19:09:38 music volumio[27248]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 26 19:09:38 music volumio[27248]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 26 19:09:38 music go-librespot[27540]: time="2025-12-26T19:09:38-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 26 19:09:39 music go-librespot[27540]: time="2025-12-26T19:09:39-05:00" level=debug msg="completed keyexchange" Dec 26 19:09:39 music go-librespot[27540]: time="2025-12-26T19:09:39-05:00" level=debug msg="completed challenge" Dec 26 19:09:39 music go-librespot[27540]: time="2025-12-26T19:09:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:39 music go-librespot[27540]: time="2025-12-26T19:09:39-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 19:09:39 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 19:09:39 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 19:09:39 music volumio[27248]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 26 19:09:39 music volumio[27248]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 26 19:09:39 music volumio[27248]: info: Streaming services startup Dec 26 19:09:39 music volumio[27248]: info: Starting Streaming Daemon Dec 26 19:09:39 music sudo[27550]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 26 19:09:39 music sudo[27550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 19:09:39 music volumio[27248]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 26 19:09:39 music sudo[27550]: pam_unix(sudo:session): session closed for user root Dec 26 19:09:39 music volumio[27248]: info: Getting Spotify volume Dec 26 19:09:39 music volumio[27248]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 19:09:39 music volumio[27248]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 19:09:39 music volumio[27248]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 26 19:09:39 music volumio[27248]: errno: -111, Dec 26 19:09:39 music volumio[27248]: code: 'ECONNREFUSED', Dec 26 19:09:39 music volumio[27248]: syscall: 'connect', Dec 26 19:09:39 music volumio[27248]: address: '127.0.0.1', Dec 26 19:09:39 music volumio[27248]: port: 9879, Dec 26 19:09:39 music volumio[27248]: response: undefined Dec 26 19:09:39 music volumio[27248]: } Dec 26 19:09:39 music volumio[27248]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 19:09:40 music sudo[27584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 19:08' Dec 26 19:09:40 music sudo[27584]: 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"