Nov 01 12:55:00 volumiosalon volumio[2225]: info: Applying required configuration parameters for plugin 80s80s Nov 01 12:55:00 volumiosalon volumio[2225]: info: [1761998100020] [80s80s] API delay: 30 Nov 01 12:55:00 volumiosalon volumio[2225]: info: Loading plugin "podcast"... Nov 01 12:55:00 volumiosalon volumio[2362]: Forking 3 albumart workers Nov 01 12:55:00 volumiosalon volumio[2225]: info: ControllerPodcast::constructor Nov 01 12:55:00 volumiosalon volumio[2225]: info: Loading plugin "Systeminfo"... Nov 01 12:55:01 volumiosalon volumio[2225]: info: Loading i18n strings for locale fr Nov 01 12:55:01 volumiosalon volumio[2225]: Updating browse sources language Nov 01 12:55:01 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:01 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 01 12:55:01 volumiosalon volumio[2225]: info: CoreCommandRouter::initPlayerControls Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: Express server listening on port 3000 Nov 01 12:55:02 volumiosalon volumio[2225]: [Metrics] WebUI: 27s 9.29ms Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreStateMachine::resetVolumioState Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreStateMachine::getcurrentVolume Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioRetrievevolume Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:02 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:02 volumiosalon volumio[2225]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Nov 01 12:55:02 volumiosalon volumio[2225]: info: Volumio Network Manager: Network status updated: 1 Nov 01 12:55:02 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Nov 01 12:55:02 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:02 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:02 volumiosalon go-librespot[2419]: go-librespot daemon starting... Nov 01 12:55:02 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:02+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:02 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:02+01:00" level=debug msg="app state loaded" Nov 01 12:55:02 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:02+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:02 volumiosalon volumio[2225]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.105 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Nov 01 12:55:02 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:02 volumiosalon volumio[2225]: info: Reloading queue from file Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreStateMachine::setRepeat null single undefined Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:03 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreStateMachine::setRandom true Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:03 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:03 volumiosalon volumio[2225]: info: Setting Device type: Raspberry PI Nov 01 12:55:03 volumiosalon volumio[2225]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.105 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 01 12:55:03 volumiosalon volumio[2225]: info: Completed loading Core Plugins Nov 01 12:55:03 volumiosalon volumio[2225]: info: Preparing to generate the ALSA configuration file Nov 01 12:55:03 volumiosalon volumio[2225]: info: Discovery: adding 9080a7df-a081-4c2d-afb5-c9e324a7ab93 Nov 01 12:55:03 volumiosalon volumio[2225]: info: Discovery: Found device VolumioComble Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=info msg="zeroconf server listening on port 33929" Nov 01 12:55:03 volumiosalon volumio[2225]: info: Discovery: Connecting to remote: 192.168.3.105 Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=debug msg="obtained new client token: AAAjfyU5bbW9Lp6MdMNQoqVXmyIgpQ0OLKgLaHyzG4prPahQ1mHQ94CcBXeedwgQddFfcz5XN0Lg4ICjoO/lLxg4iDnHYM9mapSlHEYTo38v8YPANbSficETPIzyVbKlDq28Rb2rqvDEHnOlR/fs6pVzG/uPA8YEFtGg5H5iW2LloREhqOru7Jf0I9LZGX6PhH3u6ZuV8dHu7PXqW3c3FRYte9s1VSE2m6NwAFaPvmVaj+C/lkzofGS8oKU=" Nov 01 12:55:03 volumiosalon volumio[2387]: Starting albumart workers Nov 01 12:55:03 volumiosalon volumio[2225]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.105 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=debug msg="completed challenge" Nov 01 12:55:03 volumiosalon volumio[2225]: info: Asound.conf file unchanged, so no further update is needed Nov 01 12:55:03 volumiosalon volumio[2225]: info: Output device has changed, restarting MPD Nov 01 12:55:03 volumiosalon go-librespot[2420]: time="2025-11-01T12:55:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:03 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:03 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:03 volumiosalon volumio[2225]: info: Output device has changed, restarting Shairport Sync Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:03 volumiosalon volumio[2225]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:55:03 volumiosalon sudo[2436]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 01 12:55:03 volumiosalon sudo[2436]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:03 volumiosalon sudo[2436]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:03 volumiosalon sudo[2438]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 01 12:55:03 volumiosalon sudo[2438]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:03 volumiosalon volumio[2225]: info: ___________ START PLUGINS ___________ Nov 01 12:55:03 volumiosalon volumio[2388]: Starting albumart workers Nov 01 12:55:03 volumiosalon volumio[2225]: info: ControllerMpd::onStart: Initializing MPD Nov 01 12:55:03 volumiosalon volumio[2225]: info: Creating MPD Configuration file Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:03 volumiosalon volumio[2225]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:03 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:03 volumiosalon systemd[1]: Stopping mpd.service - Music Player Daemon... Nov 01 12:55:03 volumiosalon sudo[2449]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 01 12:55:03 volumiosalon sudo[2449]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:04 volumiosalon sudo[2447]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 01 12:55:04 volumiosalon volumio[2386]: Starting albumart workers Nov 01 12:55:04 volumiosalon sudo[2447]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:04 volumiosalon sudo[2447]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:04 volumiosalon volumio[2225]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:55:04 volumiosalon volumio[2225]: info: [1761998104096] CoreMusicLibrary::Adding element Last_100 Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:04 volumiosalon systemd[1]: mpd.service: Deactivated successfully. Nov 01 12:55:04 volumiosalon systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 01 12:55:04 volumiosalon systemd[1]: mpd.service: Consumed 6.391s CPU time. Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:55:04 volumiosalon volumio[2225]: info: [1761998104114] CoreMusicLibrary::Adding element Webradio Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:04 volumiosalon systemd[1]: mpd.socket: Deactivated successfully. Nov 01 12:55:04 volumiosalon systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 01 12:55:04 volumiosalon systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:55:04 volumiosalon volumio[2225]: info: Initializing BBC Radios Nov 01 12:55:04 volumiosalon systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 01 12:55:04 volumiosalon systemd[1]: Starting mpd.service - Music Player Daemon... Nov 01 12:55:04 volumiosalon systemd[1]: mpd.service: Deactivated successfully. Nov 01 12:55:04 volumiosalon systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 01 12:55:04 volumiosalon systemd[1]: mpd.socket: Deactivated successfully. Nov 01 12:55:04 volumiosalon systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 01 12:55:04 volumiosalon systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 01 12:55:04 volumiosalon systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 01 12:55:04 volumiosalon systemd[1]: Starting mpd.service - Music Player Daemon... Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:04 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:55:04] [connect] Successful connection Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:55:04 volumiosalon volumio[2225]: info: [1761998104552] CoreMusicLibrary::Adding element Mixcloud Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:04 volumiosalon volumio[2225]: Cannot find translation for source Mixcloud Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:55:04 volumiosalon volumio[2225]: info: [1761998104623] CoreMusicLibrary::Adding element SoundCloud Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:04 volumiosalon volumio[2225]: Cannot find translation for source Mixcloud Nov 01 12:55:04 volumiosalon volumio[2225]: Cannot find translation for source SoundCloud Nov 01 12:55:04 volumiosalon volumio[2225]: info: Creating Spotify config file Nov 01 12:55:04 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:04 volumiosalon sudo[2470]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 01 12:55:04 volumiosalon sudo[2470]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Nov 01 12:55:04 volumiosalon sudo[2470]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:05 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:55:05 volumiosalon volumio[2225]: info: [1761998105933] CoreMusicLibrary::Adding element YouTube2 Nov 01 12:55:05 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source Mixcloud Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source SoundCloud Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source YouTube2 Nov 01 12:55:05 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:55:05 volumiosalon volumio[2225]: info: [1761998105956] CoreMusicLibrary::Adding element YouTube Music Nov 01 12:55:05 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source Mixcloud Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source SoundCloud Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source YouTube2 Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source YouTube Music Nov 01 12:55:05 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:55:05 volumiosalon volumio[2225]: info: [1761998105983] CoreMusicLibrary::Adding element 80s80s Radio Nov 01 12:55:05 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source Mixcloud Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source SoundCloud Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source YouTube2 Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source YouTube Music Nov 01 12:55:05 volumiosalon volumio[2225]: Cannot find translation for source 80s80s Radio Nov 01 12:55:06 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:55:06 volumiosalon volumio[2225]: info: [1761998106008] CoreMusicLibrary::Adding element Podcast Nov 01 12:55:06 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:55:06 volumiosalon volumio[2225]: Cannot find translation for source Mixcloud Nov 01 12:55:06 volumiosalon volumio[2225]: Cannot find translation for source SoundCloud Nov 01 12:55:06 volumiosalon volumio[2225]: Cannot find translation for source YouTube2 Nov 01 12:55:06 volumiosalon volumio[2225]: Cannot find translation for source YouTube Music Nov 01 12:55:06 volumiosalon volumio[2225]: Cannot find translation for source 80s80s Radio Nov 01 12:55:06 volumiosalon volumio[2225]: Cannot find translation for source Podcast Nov 01 12:55:06 volumiosalon volumio[2225]: info: Volumio Calling Home Nov 01 12:55:06 volumiosalon volumio[2225]: info: Discovery: adding 8e36d70c-1812-4fc0-9282-89074ef539a8 Nov 01 12:55:06 volumiosalon volumio[2225]: info: Discovery: Found device VolumioSalon Nov 01 12:55:06 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioGetState Nov 01 12:55:06 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:06 volumiosalon volumio[2225]: info: Discovery: this is already registered, 8e36d70c-1812-4fc0-9282-89074ef539a8 Nov 01 12:55:06 volumiosalon volumio[2225]: info: Discovery: Found device VolumioSalon Nov 01 12:55:06 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioGetState Nov 01 12:55:06 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:06 volumiosalon volumio[2225]: info: MPD Permissions set Nov 01 12:55:06 volumiosalon volumio[2225]: info: MPD Permissions set Nov 01 12:55:06 volumiosalon volumio[2225]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.105 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Nov 01 12:55:06 volumiosalon volumio[2225]: info: Discovery: Connected to remote: 192.168.3.105 Nov 01 12:55:06 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Nov 01 12:55:06 volumiosalon volumio[2225]: info: Volumio called home Nov 01 12:55:06 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:06 volumiosalon volumio[2225]: info: Spotify config file written Nov 01 12:55:06 volumiosalon sudo[2503]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 01 12:55:06 volumiosalon sudo[2503]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:06 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:06 volumiosalon go-librespot[2502]: go-librespot daemon starting... Nov 01 12:55:06 volumiosalon systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Nov 01 12:55:06 volumiosalon systemd[1]: go-librespot-daemon.service: Killing process 2509 (go-librespot) with signal SIGKILL. Nov 01 12:55:06 volumiosalon systemd[1]: go-librespot-daemon.service: Deactivated successfully. Nov 01 12:55:06 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:07 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:07 volumiosalon go-librespot[2510]: go-librespot daemon starting... Nov 01 12:55:07 volumiosalon sudo[2503]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:07 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:55:07] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761998104 101 Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=debug msg="app state loaded" Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:07 volumiosalon volumio[2225]: 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: 5 Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:07 volumiosalon volumio[2225]: info: No need to fix Spotify hosts Nov 01 12:55:07 volumiosalon volumio[2225]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 01 12:55:07 volumiosalon volumio[2225]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Nov 01 12:55:07 volumiosalon volumio[2225]: info: An error occurred while refreshing Spotify Token Error: Bad Request Nov 01 12:55:07 volumiosalon volumio[2225]: info: Starting Shairport Sync Nov 01 12:55:07 volumiosalon volumio[2225]: info: Starting Shairport Sync Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:07 volumiosalon volumio[2225]: info: Starting Shairport Sync Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=info msg="zeroconf server listening on port 45425" Nov 01 12:55:07 volumiosalon sudo[2531]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:55:07 volumiosalon sudo[2531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Nov 01 12:55:07 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioGetState Nov 01 12:55:07 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:07 volumiosalon sudo[2533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:55:07 volumiosalon sudo[2533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:07 volumiosalon sudo[2535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:55:07 volumiosalon sudo[2535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=debug msg="obtained new client token: AAADedvb63wcMjfFtrzHKB0n5YLlxFmJk6ooIfi86eJTJ57qf26sz4/+WtSWIidb3o/+hUx8s5xm4aRNcYaCVoYQO/3HGCyFcGUVmXYpTLy1CnK5FviBpZ8evcma/oA1UFPXjWE2VFxXDWdPO0waBme1cnGjxkdGZV+sNAY0eTAsvuG3kxK4NV/ZXDUj54zlxa2iMELc0/UeRsErXJLJIavZJ3kRz280iSdWq8p2/+93nA4D08H5WoJYoYg=" Nov 01 12:55:07 volumiosalon shairport-sync[2093]: {"time":1761998057667,"response":"airplayActive Success"} Nov 01 12:55:07 volumiosalon systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Nov 01 12:55:07 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:07+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:07 volumiosalon systemd[1]: shairport-sync.service: Deactivated successfully. Nov 01 12:55:07 volumiosalon systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 01 12:55:07 volumiosalon systemd[1]: shairport-sync.service: Consumed 9.257s CPU time. Nov 01 12:55:08 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:08+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:08 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:08+01:00" level=debug msg="completed challenge" Nov 01 12:55:08 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioGetState Nov 01 12:55:08 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:08 volumiosalon go-librespot[2511]: time="2025-11-01T12:55:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:08 volumiosalon systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 01 12:55:08 volumiosalon sudo[2533]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:08 volumiosalon sudo[2531]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:08 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:08 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:08 volumiosalon volumio[2225]: info: Shairport-Sync Started Nov 01 12:55:08 volumiosalon volumio[2225]: Error adding Membership: Error: addMembership EINVAL Nov 01 12:55:08 volumiosalon volumio[2225]: info: Shairport-Sync Started Nov 01 12:55:08 volumiosalon sudo[2535]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:08 volumiosalon volumio[2225]: info: Shairport-Sync Started Nov 01 12:55:10 volumiosalon volumio[2225]: info: go-librespot daemon successfully initialized Nov 01 12:55:10 volumiosalon mpd[2478]: 2025-11-01T12:55:10 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 01 12:55:10 volumiosalon systemd[1]: Started mpd.service - Music Player Daemon. Nov 01 12:55:10 volumiosalon sudo[2449]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:10 volumiosalon sudo[2438]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:10 volumiosalon volumio[2225]: info: Completed starting Core Plugins Nov 01 12:55:10 volumiosalon volumio[2225]: info: ------------------------------------------- Nov 01 12:55:10 volumiosalon volumio[2225]: info: ----- MyVolumio plugins startup ---- Nov 01 12:55:10 volumiosalon volumio[2225]: info: ------------------------------------------- Nov 01 12:55:10 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 01 12:55:11 volumiosalon volumio[2225]: error: MPD error: The expression evaluated to a falsy value: Nov 01 12:55:11 volumiosalon volumio[2225]: assert.ok(self.idling) Nov 01 12:55:11 volumiosalon volumio[2225]: error: The expression evaluated to a falsy value: Nov 01 12:55:11 volumiosalon volumio[2225]: assert.ok(self.idling) Nov 01 12:55:11 volumiosalon volumio[2225]: info: MPD running with PID2478 Nov 01 12:55:11 volumiosalon volumio[2225]: ,establishing connection Nov 01 12:55:11 volumiosalon volumio[2225]: error: updateQueue error: null Nov 01 12:55:11 volumiosalon volumio[2225]: error: updateQueue error: null Nov 01 12:55:11 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Nov 01 12:55:11 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:11 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:11 volumiosalon go-librespot[2572]: go-librespot daemon starting... Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=debug msg="app state loaded" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=info msg="zeroconf server listening on port 45555" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=debug msg="obtained new client token: AACHnCzGslXP6hdh05ecCBlcX8kmfu7XrEMyKFY+Q7bIbz4lxIbAnh2pfPljae/UUm+bessQ9LSwBdELWfQghjI6b0v0ezoV0bPdGqcD+d7zN7oL1LitSXOyg/x6dIZANw0UcS9NMqWaaUw6UoOEEzzNgiuXAdP6mewvvQxrvog77M90yIITAi5+O0zdoQcHSzQ5X1ZMPOOiiHpaOIH2hJITr/QEiiN7N0B73yGx2FO05m3RvtKj36DrT9s=" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=debug msg="completed challenge" Nov 01 12:55:11 volumiosalon go-librespot[2573]: time="2025-11-01T12:55:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:11 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:11 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:12 volumiosalon volumio[2225]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Nov 01 12:55:13 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:13 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:13 volumiosalon sudo[2581]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 01 12:55:13 volumiosalon sudo[2581]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:14 volumiosalon sudo[2583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 01 12:55:14 volumiosalon sudo[2583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:14 volumiosalon systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 01 12:55:14 volumiosalon systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 01 12:55:14 volumiosalon systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 01 12:55:14 volumiosalon systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 01 12:55:14 volumiosalon sudo[2581]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:14 volumiosalon sudo[2583]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:14 volumiosalon volumio[2225]: info: Successfully started MPD Monitor Nov 01 12:55:14 volumiosalon mpd_monitor.sh[2586]: MPD Monitor Service: Starting MPD Monitor Service Nov 01 12:55:14 volumiosalon volumio[2225]: info: Successfully started MPD Monitor Nov 01 12:55:15 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Nov 01 12:55:15 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:15 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:15 volumiosalon go-librespot[2590]: go-librespot daemon starting... Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=debug msg="app state loaded" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=info msg="zeroconf server listening on port 39805" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=debug msg="obtained new client token: AAArq1wKiVikIW4saZo381dZM8BkU28BhdUdN+IWdTRgTEtNAq0MlNQNHXBatab42v5G0hEf8zcLRM5RAScnE+x4I+NTR02KEH6o/pKmQwxNYBI+pmOrEHlHpCIPbgQS29BT1AXD6kkadMY2aBBr2VvYxQrj6e598/G5fDNMiLCpEw7WmcMsNeW9yg9PGAUTiaggQn/gIeh+PGsReOWUXuxDh8Po3blqybnQ0+FxGn85JD+6A4HHh5jdGzg=" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=debug msg="completed challenge" Nov 01 12:55:15 volumiosalon go-librespot[2591]: time="2025-11-01T12:55:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:15 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:15 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:16 volumiosalon volumio[2225]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 01 12:55:16 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:16 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:17 volumiosalon volumio[2225]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Nov 01 12:55:18 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Nov 01 12:55:18 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:18 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:18 volumiosalon go-librespot[2598]: go-librespot daemon starting... Nov 01 12:55:18 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:18+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:18 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:18+01:00" level=debug msg="app state loaded" Nov 01 12:55:18 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:18+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=info msg="zeroconf server listening on port 45579" Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=debug msg="obtained new client token: AAA5zaeSGE4hQINeJsSczvDOmk8M9DU0FwtNvthxYNG79IkraEFPaTE51ZiRJQw9eQXDqFn4YEnQ4V2TD/+LMLNlf0cVmATxjYT65udKGQF1KG2LA+srI1EnBmV/an/ZHq7GaGcYxUhpq/NiITefq8yQ/1sgBQ4apQ7uZHwNTS8BUP7HGelM0wO/tguam4AcibWn4YJ90kWtWQMTiG8l2WNQPV92uKGlpRAfazOnTSrsQecyXNHLuqqIgpk=" Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=debug msg="completed challenge" Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Nov 01 12:55:19 volumiosalon go-librespot[2599]: time="2025-11-01T12:55:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Nov 01 12:55:19 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Nov 01 12:55:19 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Nov 01 12:55:19 volumiosalon volumio[2225]: info: Adding plugin bluetooth to MyMusic Plugins Nov 01 12:55:19 volumiosalon volumio[2225]: info: Adding plugin multiroom to MyMusic Plugins Nov 01 12:55:19 volumiosalon volumio[2225]: info: Adding plugin metavolumio to MyMusic Plugins Nov 01 12:55:19 volumiosalon volumio[2225]: info: Adding plugin cd_controller to MyMusic Plugins Nov 01 12:55:19 volumiosalon volumio[2225]: info: Adding plugin qobuzconnect to MyMusic Plugins Nov 01 12:55:19 volumiosalon volumio[2225]: info: Adding plugin smart_inputs to MyMusic Plugins Nov 01 12:55:19 volumiosalon volumio[2225]: info: Adding plugin tidalconnect to MyMusic Plugins Nov 01 12:55:19 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Nov 01 12:55:21 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Nov 01 12:55:21 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Nov 01 12:55:21 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:21 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:21 volumiosalon volumio[2225]: info: Starting MyVolumio Remote Streaming Endpoints Nov 01 12:55:21 volumiosalon volumio[2225]: info: MyVolumio login type: Token Nov 01 12:55:21 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Nov 01 12:55:21 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Nov 01 12:55:22 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Nov 01 12:55:22 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:22 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:22 volumiosalon go-librespot[2620]: go-librespot daemon starting... Nov 01 12:55:22 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:22+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:22 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:22+01:00" level=debug msg="app state loaded" Nov 01 12:55:22 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=info msg="zeroconf server listening on port 44489" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=debug msg="obtained new client token: AACxMW0FUwuWxDG06T8oLQaPxnU6hJwKjbsYgOWscsb0YK+wvdaYuhBoXKiZC+1iQEJTQKDjjLmfzfJx6RDOoTdfCFWfrqslRuTWMgk3YHQDmLT8WPzkFX32t1Bcb0g+LXvIoYIHsnn/sEKTMjoKAjIes3rDNVXdb6qnQ1r8f/NN1S4nr3lPPuaSUrWctSCIkMux1SlH+HXaoUrnewhI3R0pKUzlyCCjjZPDhCWUFpTLZL09L6+0U5Zm" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=debug msg="completed challenge" Nov 01 12:55:23 volumiosalon go-librespot[2621]: time="2025-11-01T12:55:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:23 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:23 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:23 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Nov 01 12:55:23 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Nov 01 12:55:23 volumiosalon volumio[2225]: info: Streaming services startup Nov 01 12:55:23 volumiosalon volumio[2225]: info: Starting Streaming Daemon Nov 01 12:55:23 volumiosalon volumio[2225]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Nov 01 12:55:23 volumiosalon sudo[2631]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 01 12:55:23 volumiosalon sudo[2631]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:23 volumiosalon sudo[2631]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:23 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:23 volumiosalon volumio[2225]: error: Cannot start Volumio Streaming Daemon Nov 01 12:55:23 volumiosalon volumio[2225]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 01 12:55:23 volumiosalon volumio[2225]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 01 12:55:23 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:23 volumiosalon nmbd[905]: [2025/11/01 12:55:23.761854, 0] ../../source3/nmbd/nmbd_namequery.c:109(query_name_response) Nov 01 12:55:23 volumiosalon nmbd[905]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.3.151 for name WORKGROUP<1d>. Nov 01 12:55:23 volumiosalon nmbd[905]: This response was from IP 192.168.3.251, reporting an IP address of 192.168.3.251. Nov 01 12:55:24 volumiosalon volumio[2225]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Nov 01 12:55:24 volumiosalon volumio[2225]: info: MyVolumio token set successfully Nov 01 12:55:24 volumiosalon volumio[2225]: info: MYVOLUMIO: Adding device Nov 01 12:55:24 volumiosalon volumio[2225]: info: MYVOLUMIO: Evaluating Server Nov 01 12:55:25 volumiosalon volumio[2225]: info: MyVolumio status changed Nov 01 12:55:25 volumiosalon volumio[2225]: info: Streaming services startup Nov 01 12:55:25 volumiosalon volumio[2225]: info: Starting Streaming Daemon Nov 01 12:55:25 volumiosalon volumio[2225]: info: Removing browser output: myVolumio user plan is not superstar Nov 01 12:55:25 volumiosalon volumio[2225]: info: Removing audio output: Nov 01 12:55:25 volumiosalon volumio[2225]: info: Stoppping Tunnel 1 Nov 01 12:55:25 volumiosalon sudo[2658]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 01 12:55:25 volumiosalon sudo[2658]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:25 volumiosalon sudo[2660]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Nov 01 12:55:25 volumiosalon sudo[2660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:25 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Nov 01 12:55:25 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Nov 01 12:55:25 volumiosalon sudo[2658]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:25 volumiosalon volumio[2225]: error: Cannot start Volumio Streaming Daemon Nov 01 12:55:25 volumiosalon volumio[2225]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 01 12:55:25 volumiosalon volumio[2225]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 01 12:55:25 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Nov 01 12:55:25 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Nov 01 12:55:25 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Nov 01 12:55:25 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Nov 01 12:55:25 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Nov 01 12:55:25 volumiosalon systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Nov 01 12:55:25 volumiosalon sudo[2660]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:25 volumiosalon volumio[2225]: info: Remote SSH Stopped Nov 01 12:55:26 volumiosalon volumio[2225]: info: Setting Geolocation for MyVolumio to eu6 Nov 01 12:55:26 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:26 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:26 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:26 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Nov 01 12:55:26 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:26 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:26 volumiosalon go-librespot[2663]: go-librespot daemon starting... Nov 01 12:55:26 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:26 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:26 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:26+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:26 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:26+01:00" level=debug msg="app state loaded" Nov 01 12:55:26 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:26+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:26 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:26+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:26 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:26+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:26 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:26+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:26 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:26+01:00" level=info msg="zeroconf server listening on port 33035" Nov 01 12:55:27 volumiosalon volumio[2225]: info: Successfully Added MyVolumio device Nov 01 12:55:27 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:27+01:00" level=debug msg="obtained new client token: AAAoO6gtXnJiU0p1XLRHtc3RBFN5HiJCp0QIcgrqZXfnE3y9F3O50/cNz5hm4/2rsibIieaJ1TZ9VzW7XE36PMI4gPoI+8DDtuU+77rMYpyhQweg4A+paaFQgmgsbg3zks8z2/ROBHOm7eUxImiNsW1VBIJ8C1hySY/FrZvKAIQfkDhrebFTq9ApaKa26Zr9IUW+jUimi2V1sQsc7lqm9Ui0jNLszuNVuCaWAg05mlxrZTuWv0/nEAZL" Nov 01 12:55:27 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:27+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:27 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:27+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:27 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:27+01:00" level=debug msg="completed challenge" Nov 01 12:55:27 volumiosalon go-librespot[2664]: time="2025-11-01T12:55:27+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:27 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:27 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:27 volumiosalon volumio[2225]: info: Updating MyVolumio device info Nov 01 12:55:27 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:27 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:27 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:28 volumiosalon volumio[2225]: info: Successfully Updated MyVolumio device Nov 01 12:55:29 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:29 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:30 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Nov 01 12:55:30 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:30 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:30 volumiosalon go-librespot[2671]: go-librespot daemon starting... Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=debug msg="app state loaded" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=info msg="zeroconf server listening on port 46791" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=debug msg="obtained new client token: AAB/o3ddNVcj8R9GT1tUbS7ckuedv+n+89CtIvU7vmS/SxtBbssmpOeOVfhVzLyd0EdtG/Qb6a1mf70ScFGQ0YgMfti3bBqXWao8gPuWxp+VfFhwh6R27j23TggBysBzbtWw9taBIKB6Z0+KwPt5naU4f8pBhEINiAQiCd1kvD8hw0QmoNeyB/IoppUdYyt5Yt19lKkvfz0Fvg50V6dxiqILWDqPJyLQAMsBrgzAh6vhydU2BPkjAhkIA9o=" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:30 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:30+01:00" level=debug msg="completed challenge" Nov 01 12:55:31 volumiosalon go-librespot[2672]: time="2025-11-01T12:55:31+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:31 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:31 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:32 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:32 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:34 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Nov 01 12:55:34 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:34 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:34 volumiosalon go-librespot[2695]: go-librespot daemon starting... Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=debug msg="app state loaded" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=info msg="zeroconf server listening on port 34039" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=debug msg="obtained new client token: AAAtUCIS27SfochtvsE0rKzHxlMNgA1FBXyeKw3bSNJokr1yBDJSI5d33KgN8Z+iia/Ecu5e5xY3o8KLyTw4HROp80KEOF75ctuHE9vHzlL2AtCOJJQIPdfgBmLw9l3Ca9DaxJhtiKkfJLbwLqfOPAeDVpoCoYfB2IQmcIkBOUBu1W20qgPUbta32R0S3Pv394HWthwOmmhAcIvkF3s+xBYe5fDhAVvsaoaoUBzlLh7Qa8FLLYJUrZBET5E=" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=debug msg="completed challenge" Nov 01 12:55:34 volumiosalon go-librespot[2697]: time="2025-11-01T12:55:34+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:34 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:34 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:35 volumiosalon systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Nov 01 12:55:35 volumiosalon kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error! Nov 01 12:55:35 volumiosalon volumio[2225]: info: Airplay started streaming, receiving metadatas Nov 01 12:55:35 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioStop Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::stop Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:55:35 volumiosalon volumio[2225]: info: Airplay started streaming, receiving metadatas Nov 01 12:55:35 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioStop Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::stop Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:55:35 volumiosalon volumio[2225]: info: Airplay started streaming, receiving metadatas Nov 01 12:55:35 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioStop Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::stop Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:55:35 volumiosalon shairport-sync[2721]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:55:35 volumiosalon shairport-sync[2721]: Dload Upload Total Spent Left Speed Nov 01 12:55:35 volumiosalon shairport-sync[2721]: [79B blob data] Nov 01 12:55:35 volumiosalon shairport-sync[2722]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:55:35 volumiosalon shairport-sync[2722]: Dload Upload Total Spent Left Speed Nov 01 12:55:35 volumiosalon volumio[2225]: info: Updating volume from AirPlay: -20; 33% Nov 01 12:55:35 volumiosalon volumio[2225]: info: VolumeController::SetAlsaVolume33 Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:35 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:35 volumiosalon volumio[2225]: info: Nov 01 12:55:35 volumiosalon volumio[2225]: ---------------------------- Client requests AirplayActive Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayActive Nov 01 12:55:35 volumiosalon shairport-sync[2722]: [79B blob data] Nov 01 12:55:35 volumiosalon shairport-sync[2721]: [79B blob data] Nov 01 12:55:35 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:35 volumiosalon volumio[2225]: info: Nov 01 12:55:35 volumiosalon volumio[2225]: ---------------------------- Client requests Start Airplay PlaybackRoutine Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Nov 01 12:55:35 volumiosalon volumio[2225]: info: Airplay playback start Nov 01 12:55:35 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioStop Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::stop Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:55:35 volumiosalon volumio[2225]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:55:35 volumiosalon shairport-sync[2721]: {"time":1761998135591,"response":"airplayActive Success"} Nov 01 12:55:35 volumiosalon shairport-sync[2722]: [79B blob data] Nov 01 12:55:35 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 01 12:55:36 volumiosalon volumio-remote-updater[466]: Test mode enabled Nov 01 12:55:36 volumiosalon volumio-remote-updater[466]: Alpha mode disabled Nov 01 12:55:36 volumiosalon volumio-remote-updater[466]: Alpha legacy test mode disabled Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Nov 01 12:55:36 volumiosalon volumio[2225]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 01 12:55:36 volumiosalon volumio[2225]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioGetState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CorePlayQueue::getTrack 0 Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:36 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:36 volumiosalon systemd[1]: setdatetime-helper.service: Deactivated successfully. Nov 01 12:55:36 volumiosalon systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Nov 01 12:55:36 volumiosalon systemd[1]: setdatetime-helper.service: Consumed 1.884s CPU time. Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:37 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:38 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Nov 01 12:55:38 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:38 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:38 volumiosalon go-librespot[2743]: go-librespot daemon starting... Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=debug msg="app state loaded" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=info msg="zeroconf server listening on port 40989" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=debug msg="obtained new client token: AABvBvmvBB5loWzm1bMpAvzsQrNEU1liydcoOFaZ5xZJmzVCYFjGjkwsQmsjNHxcGWpXoy+/6dDFqchz4delvGnYIHTvw2N8kmncnN1c+yFDvzab8RDdBA/xyhokIqPImecZxs25pW9ZcvNSkniz1IKHx4siPfLIcXmndN64eJOoz9dXEP+1/Yk1VkxmxkJthbDwD5uZLRtIxAsOntXnqlnoLsISRTlh0dkhN0xU+AuGW9TRmjhjrkup9Ek=" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=debug msg="completed challenge" Nov 01 12:55:38 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:38 volumiosalon go-librespot[2744]: time="2025-11-01T12:55:38+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:38 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: read ECONNRESET Nov 01 12:55:38 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:38 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:41 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:41 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:41 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Nov 01 12:55:41 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Nov 01 12:55:41 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 01 12:55:41 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Nov 01 12:55:41 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioGetBrowseSources Nov 01 12:55:41 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:55:41 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:41 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:41 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Nov 01 12:55:41 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:41 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:41 volumiosalon go-librespot[2765]: go-librespot daemon starting... Nov 01 12:55:41 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:41+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:41 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:41+01:00" level=debug msg="app state loaded" Nov 01 12:55:41 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:41+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=info msg="zeroconf server listening on port 37493" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=debug msg="obtained new client token: AAAF8VkW/MjRzlPk6NnHRJ8A64jAA/Ot5njG78c7mhR94JLDlXauDSe5Fw+C7tHZgkspE8loCvvgd8NH5s953++ug5XxTnHNBCQkLdpkFd8qGSsNJ5w4b5jfdy3lDHzUu6FIwAnNXz+IYzkMAH8gJEtP0e5fVoEIiDPbDBrjPxmN1xfb+9KAlZL2p7uQD9C1xkvhQiSANrYQTVYQw2mHho/xuSqqyEJ4aIPcR9E7XlPzRVQTU6E9WPV9b9k=" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=debug msg="completed challenge" Nov 01 12:55:42 volumiosalon go-librespot[2766]: time="2025-11-01T12:55:42+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:42 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:42 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:43 volumiosalon volumio[2225]: error: MyVolumio Plugin failed to authenticate in a timely fashion Nov 01 12:55:43 volumiosalon volumio[2225]: info: Completed starting MyVolumio Plugin Nov 01 12:55:43 volumiosalon volumio[2225]: [Metrics] CommandRouter: 67s 366.37ms Nov 01 12:55:43 volumiosalon volumio[2225]: info: CoreCommandRouter::volumiosetStartupVolume Nov 01 12:55:43 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:55:43 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:55:43 volumiosalon volumio[2225]: info: CoreCommandRouter::Close All Modals sent Nov 01 12:55:43 volumiosalon volumio[2225]: info: CoreCommandRouter::Close All Modals sent Nov 01 12:55:43 volumiosalon volumio[2225]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Nov 01 12:55:43 volumiosalon volumio[2225]: aplay: main:831: audio open error: Device or resource busy Nov 01 12:55:44 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Nov 01 12:55:44 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 01 12:55:44 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Nov 01 12:55:44 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:44 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:45 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Nov 01 12:55:45 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:45 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:45 volumiosalon go-librespot[2776]: go-librespot daemon starting... Nov 01 12:55:45 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:45+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:45 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:45+01:00" level=debug msg="app state loaded" Nov 01 12:55:45 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:45+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:45 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:45+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:45 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:45+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:45 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:45+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:45 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:45+01:00" level=info msg="zeroconf server listening on port 33307" Nov 01 12:55:46 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:46+01:00" level=debug msg="obtained new client token: AADSn7nebCQgcgmMi3xtNVT76WIss8AoTDVDwEhlGPGQ/ptC5qETVrQ0sXTvoFAkYSlC+5An3VbGjrTkhx+sez/1yE/3+ifF2O9GzAOIYBok3IHn67G2Yq7Wo6R2pN6f9ML4Rc4s79L3KDeyZuZESHvp364sq1hVxi+lgCUI1Iu5xm4A+dgGSDx9olcqcNPfW+oZJEOwB/ntIasZnjGLmqbs4un8yK/L9NzIRVsZoWvf1HhY032KhopI" Nov 01 12:55:46 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:46+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:46 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:46+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:46 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:46+01:00" level=debug msg="completed challenge" Nov 01 12:55:46 volumiosalon go-librespot[2777]: time="2025-11-01T12:55:46+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:46 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:46 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:47 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:47 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:49 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Nov 01 12:55:49 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:49 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:49 volumiosalon go-librespot[2784]: go-librespot daemon starting... Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=debug msg="app state loaded" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=info msg="zeroconf server listening on port 46447" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=debug msg="obtained new client token: AACR7c911yV+yCczN2Jnyfw3XsrirvHmZdeR5e5qs4EswN0BegQHay4ptnhiXUG3yAsH+0jKd7eHjpMYVSu24m/A9CpPf/PhAg8W5FaUTebj4OH5Sv3NxJ7qVDrvCOwSmdciOVctKYn2FX5WSgWdMFWVT7jpEsvMg3bffG7S11dsGvGFNCHdL13jnQzL/rB/swmDpfJZuVh/f8QpnOkk+a9XkYenvQxd809H2Cpdqp0srHS6lLxCn4WefYo=" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=debug msg="completed challenge" Nov 01 12:55:49 volumiosalon go-librespot[2785]: time="2025-11-01T12:55:49+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:49 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:49 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:50 volumiosalon volumio[2225]: info: BOOT COMPLETED Nov 01 12:55:50 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:50 volumiosalon volumio[2225]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:53 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Nov 01 12:55:53 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:53 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:53 volumiosalon go-librespot[2807]: go-librespot daemon starting... Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="app state loaded" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=info msg="zeroconf server listening on port 45415" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="obtained new client token: AADn0sufVFevuhCHGlAuV+7RCTTp8D1eIDVOSfDVLpnBmKoESfTc/Os6M9B2VgsuvYnEY9n9KB/DFh0OpK0H+sbKq6HnvWPS2pxyryzVesHtGPDpRuCRluyvVAWWVEs15js0LlXaqnRs6FYgRcD+QEL3hjUaILOBMzejcYgrUbPQlGLIiSrit6NcxaDyp5X08uajwpAk67nkFRL9XDBka5SZ4qz+ciBfAzXKIsAQLoGQ2jVoPmV+kYWmdvo=" Nov 01 12:55:53 volumiosalon volumio[2225]: info: Initializing connection to go-librespot Websocket Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="new websocket client" Nov 01 12:55:53 volumiosalon volumio[2225]: info: Connection to go-librespot Websocket established Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=debug msg="completed challenge" Nov 01 12:55:53 volumiosalon go-librespot[2808]: time="2025-11-01T12:55:53+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:53 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:53 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:53 volumiosalon volumio[2225]: info: Connection to go-librespot Websocket closed Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:54 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::servicePushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:56 volumiosalon shairport-sync[2722]: {"time":1761998135667,"response":"startAirplayPlayback Success"} Nov 01 12:55:56 volumiosalon shairport-sync[2819]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:55:56 volumiosalon shairport-sync[2819]: Dload Upload Total Spent Left Speed Nov 01 12:55:56 volumiosalon volumio[2225]: info: Nov 01 12:55:56 volumiosalon volumio[2225]: ---------------------------- Client requests Stop Airplay Playback Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , stopAirplayPlayback Nov 01 12:55:56 volumiosalon volumio[2225]: info: Airplay playback stop Nov 01 12:55:56 volumiosalon volumio[2225]: info: Airplay Playback Stopped, clearing state Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreStateMachine::resetVolumioState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreStateMachine::getcurrentVolume Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioRetrievevolume Nov 01 12:55:56 volumiosalon shairport-sync[2819]: [158B blob data] Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreStateMachine::pushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: CoreCommandRouter::volumioPushState Nov 01 12:55:56 volumiosalon volumio[2225]: info: Getting Spotify volume Nov 01 12:55:56 volumiosalon volumio[2225]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 01 12:55:56 volumiosalon volumio[2225]: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:55:56 volumiosalon volumio[2225]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Nov 01 12:55:56 volumiosalon volumio[2225]: errno: -111, Nov 01 12:55:56 volumiosalon volumio[2225]: code: 'ECONNREFUSED', Nov 01 12:55:56 volumiosalon volumio[2225]: syscall: 'connect', Nov 01 12:55:56 volumiosalon volumio[2225]: address: '127.0.0.1', Nov 01 12:55:56 volumiosalon volumio[2225]: port: 9879, Nov 01 12:55:56 volumiosalon volumio[2225]: response: undefined Nov 01 12:55:56 volumiosalon volumio[2225]: } Nov 01 12:55:56 volumiosalon volumio[2225]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 01 12:55:57 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Nov 01 12:55:57 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:57 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:55:57 volumiosalon go-librespot[2831]: go-librespot daemon starting... Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=debug msg="app state loaded" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=info msg="zeroconf server listening on port 41347" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=debug msg="obtained new client token: AACIxiw/yVXWQg/ew3lv0BBYFXL9pxBrNK292Uf99KNoBqz3GLY8mxrgUdItEiHkNp5yLKCklyAoIg3/fKnXWSnF55W3KvYcbwcdNu5Y1xZoXNWsaIjaM/EH7Y07OIGVq6CD8TQpYSt4RS8FE9y/4as6ImWWBSY8x1+lNwikT1AiGLMDqQ4QdeUBPxXWPWDTKSgc3soiqbOPZmNt8OOMCboy9LIUFMRWi0dJvrh1hbJ4X7M0Np2L3UfsP3E=" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=debug msg="completed keyexchange" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=debug msg="completed challenge" Nov 01 12:55:57 volumiosalon go-librespot[2832]: time="2025-11-01T12:55:57+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:55:57 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:57 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:55:58 volumiosalon sudo[2842]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-11-01 12:54' Nov 01 12:55:58 volumiosalon sudo[2842]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:55:58 volumiosalon sudo[2842]: pam_unix(sudo:session): session closed for user root Nov 01 12:55:58 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:55:58] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Nov 01 12:55:58 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:55:58] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Nov 01 12:55:58 volumiosalon systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:55:58 volumiosalon systemd[1]: volumio.service: Failed with result 'exit-code'. Nov 01 12:55:58 volumiosalon systemd[1]: volumio.service: Consumed 1min 17.885s CPU time. Nov 01 12:55:58 volumiosalon systemd[1]: Started dynamicswap.service - dynamicswap service. Nov 01 12:55:59 volumiosalon systemd[1]: dynamicswap.service: Deactivated successfully. Nov 01 12:55:59 volumiosalon systemd[1]: volumio.service: Scheduled restart job, restart counter is at 68. Nov 01 12:55:59 volumiosalon systemd[1]: Started dynamicswap.service - dynamicswap service. Nov 01 12:55:59 volumiosalon systemd[1]: Stopped volumio.service - Volumio Backend Module. Nov 01 12:55:59 volumiosalon systemd[1]: volumio.service: Consumed 1min 17.885s CPU time. Nov 01 12:55:59 volumiosalon systemd[1]: Started volumio.service - Volumio Backend Module. Nov 01 12:55:59 volumiosalon systemd[1]: dynamicswap.service: Deactivated successfully. Nov 01 12:56:01 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Nov 01 12:56:01 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:01 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:01 volumiosalon go-librespot[2873]: go-librespot daemon starting... Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=debug msg="app state loaded" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=info msg="zeroconf server listening on port 46255" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=debug msg="obtained new client token: AADMKC/iJb8PScqO+AqNdfBCEc28AJEe05Uubtn4kNBWJx9ktOwn2yuasZByYzr4lei8F0Hw7Irw4lppUfzQd59hRKVpApnLTOsuR3LHXQOzV1CXoeETdyh7c7aRFv9mOQmV3j37XAN1gXm2b+tA8losAY/QwnZZ1D7kfXbnYX9iujfL3b9SItzfsg1lw1XKlMc2hZylEhasTGm3R+SgmLGl+n1hfjNAIG7UzEJbOsJEv9IOZyjGmg3a0ws=" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=debug msg="completed challenge" Nov 01 12:56:01 volumiosalon go-librespot[2874]: time="2025-11-01T12:56:01+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:01 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:01 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:02 volumiosalon volumio[2858]: info: ------------------------------------------- Nov 01 12:56:02 volumiosalon volumio[2858]: info: ----- Volumio3 ---- Nov 01 12:56:02 volumiosalon volumio[2858]: info: ------------------------------------------- Nov 01 12:56:02 volumiosalon volumio[2858]: info: ----- System startup ---- Nov 01 12:56:02 volumiosalon volumio[2858]: info: ------------------------------------------- Nov 01 12:56:03 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:56:03] [connect] Successful connection Nov 01 12:56:04 volumiosalon volumio[2858]: info: MYVOLUMIO Environment detected Nov 01 12:56:04 volumiosalon volumio[2858]: info: Plugin folders cleanup Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning into folder /volumio/app/plugins/ Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning category audio_interface Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning category miscellanea Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning category music_service Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning category plugins.json Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning category system_controller Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning category user_interface Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning into folder /data/plugins/ Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning category music_service Nov 01 12:56:04 volumiosalon volumio[2858]: info: Scanning category user_interface Nov 01 12:56:04 volumiosalon volumio[2858]: info: Plugin folders cleanup completed Nov 01 12:56:04 volumiosalon volumio[2858]: info: ------------------------------------------- Nov 01 12:56:04 volumiosalon volumio[2858]: info: ----- Core plugins startup ---- Nov 01 12:56:04 volumiosalon volumio[2858]: info: ------------------------------------------- Nov 01 12:56:04 volumiosalon volumio[2858]: info: Loading plugins from folder /volumio/app/plugins/ Nov 01 12:56:04 volumiosalon volumio[2858]: info: Adding plugin upnp to MyMusic Plugins Nov 01 12:56:04 volumiosalon volumio[2858]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 01 12:56:04 volumiosalon volumio[2858]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 01 12:56:04 volumiosalon volumio[2858]: info: Loading plugins from folder /data/plugins/ Nov 01 12:56:04 volumiosalon volumio[2858]: info: Loading plugin "system"... Nov 01 12:56:04 volumiosalon volumio[2858]: info: Loading plugin "appearance"... Nov 01 12:56:05 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Nov 01 12:56:05 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:05 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:05 volumiosalon go-librespot[2893]: go-librespot daemon starting... Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=debug msg="app state loaded" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=info msg="zeroconf server listening on port 36825" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=debug msg="obtained new client token: AAC4Gj5XoRDKKtU0c7MVzWXCTHSE+f8wyGJAiOR1zfhNO6MBJ16qOXi1l1hZ2UxdLtLR9m+ixoXeTWQ80qmhEASqyUJAxOsJPnhGBbwPRBDc4aVqg+bUOMjkQe7nJP0440NjH5E9rExtGC0vs9juKmS5X8VrhTLtLEpi7Zaq3xd1/DRV2Qe2yg47Y37FP28UcWnYTXCrg3C6JYuJhTephP9vFVr76jUH5Y+xRQWl/uKEvzFozBJH6t7+j4s=" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=debug msg="completed challenge" Nov 01 12:56:05 volumiosalon go-librespot[2894]: time="2025-11-01T12:56:05+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:05 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:05 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:06 volumiosalon shairport-sync[2819]: {"time":1761998156151,"response":"stopAirplayPlayback Success"} Nov 01 12:56:06 volumiosalon shairport-sync[2902]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:56:06 volumiosalon shairport-sync[2902]: Dload Upload Total Spent Left Speed Nov 01 12:56:06 volumiosalon volumio[2858]: info: Loading plugin "network"... Nov 01 12:56:06 volumiosalon volumio[2858]: info: Refreshing Cached IP Addresses Nov 01 12:56:06 volumiosalon volumio[2858]: info: Loading plugin "services"... Nov 01 12:56:06 volumiosalon sudo[2904]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 01 12:56:06 volumiosalon sudo[2904]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:06 volumiosalon volumio[2858]: info: Loading plugin "alsa_controller"... Nov 01 12:56:06 volumiosalon sudo[2904]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:06 volumiosalon sudo[2906]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 01 12:56:06 volumiosalon sudo[2906]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:06 volumiosalon sudo[2906]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:06 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:56:06 volumiosalon volumio[2858]: info: Loading plugin "wizard"... Nov 01 12:56:06 volumiosalon volumio[2858]: info: Loading plugin "networkfs"... Nov 01 12:56:06 volumiosalon volumio[2858]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Nov 01 12:56:06 volumiosalon volumio[2858]: info: Starting Udev Watcher for removable devices Nov 01 12:56:06 volumiosalon volumio[2858]: info: Ignoring mount for partition: boot Nov 01 12:56:06 volumiosalon volumio[2858]: info: Ignoring mount for partition: volumio Nov 01 12:56:06 volumiosalon volumio[2858]: info: Ignoring mount for partition: volumio_data Nov 01 12:56:06 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 01 12:56:06 volumiosalon volumio[2858]: info: Loading plugin "volumio_command_line_client"... Nov 01 12:56:06 volumiosalon volumio[2858]: info: Plugin upnp is not enabled Nov 01 12:56:06 volumiosalon volumio[2858]: info: Loading plugin "my_music"... Nov 01 12:56:06 volumiosalon volumio[2858]: info: Loading plugin "mpd"... Nov 01 12:56:07 volumiosalon volumio[2858]: info: Plugin upnp_browser is not enabled Nov 01 12:56:07 volumiosalon volumio[2858]: info: Loading plugin "alarm-clock"... Nov 01 12:56:07 volumiosalon volumio[2858]: info: Loading plugin "airplay_emulation"... Nov 01 12:56:07 volumiosalon volumio[2858]: info: Starting Shairport Sync Nov 01 12:56:07 volumiosalon volumio[2858]: info: Loading plugin "last_100"... Nov 01 12:56:07 volumiosalon volumio[2858]: info: Loading plugin "webradio"... Nov 01 12:56:09 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Nov 01 12:56:09 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:09 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:09 volumiosalon go-librespot[2933]: go-librespot daemon starting... Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=debug msg="app state loaded" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=info msg="zeroconf server listening on port 42225" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=debug msg="obtained new client token: AAA6mG5sdykZYKseU6qGjqmdghPus5uiwqANl4lYi2n4OlmhFbrOJsAskgxI87KA8fD+IzJyUwZeIuYCNT1iwAb5NSKZ8pq0+Nsvi79B5NRYaJe/geyg+lD12dddzuweaD/NULAcR0keFajkWWtEvUQw6tiepiZmzD99dDLsZyS4NF8UPPb+1l5P2DeMj/xJqgpvUvxWSX3TF5wIWdFXT/oCVMJapMPgaE01vsjJB4Kys0CkOfd+SPHDr/Y=" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=debug msg="completed challenge" Nov 01 12:56:09 volumiosalon go-librespot[2934]: time="2025-11-01T12:56:09+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:09 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:09 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:10 volumiosalon volumio[2858]: info: Loading plugin "i2s_dacs"... Nov 01 12:56:10 volumiosalon volumio[2858]: info: Loading plugin "volumiodiscovery"... Nov 01 12:56:10 volumiosalon volumio[2858]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 01 12:56:10 volumiosalon volumio[2858]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 01 12:56:10 volumiosalon volumio[2858]: *** WARNING *** For more information see Nov 01 12:56:10 volumiosalon volumio[2858]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 01 12:56:10 volumiosalon volumio[2858]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 01 12:56:10 volumiosalon volumio[2858]: *** WARNING *** For more information see Nov 01 12:56:10 volumiosalon node[2858]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 01 12:56:10 volumiosalon node[2858]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 01 12:56:10 volumiosalon node[2858]: *** WARNING *** For more information see Nov 01 12:56:10 volumiosalon node[2858]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 01 12:56:10 volumiosalon node[2858]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 01 12:56:10 volumiosalon node[2858]: *** WARNING *** For more information see Nov 01 12:56:10 volumiosalon volumio[2858]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 01 12:56:10 volumiosalon volumio[2858]: info: Discovery: Started advertising with name: VolumioSalon Nov 01 12:56:10 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 01 12:56:10 volumiosalon volumio[2858]: info: Loading plugin "mixcloud"... Nov 01 12:56:11 volumiosalon volumio[2858]: info: Loading plugin "soundcloud"... Nov 01 12:56:11 volumiosalon volumio[2858]: info: Loading plugin "spop"... Nov 01 12:56:13 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Nov 01 12:56:13 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:13 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:13 volumiosalon go-librespot[2943]: go-librespot daemon starting... Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=debug msg="app state loaded" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=info msg="zeroconf server listening on port 34707" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=debug msg="obtained new client token: AAB0uLrevWnzWyKFUgNoScqTVtMbKRsR7lYhNFd2HsHJuAnbwgRJucX/N/T/zVAtbq6J1QHSbAjtTizsW9Zc/uxZIZQNQbhehmAasaP2p0R8qFpgf58iBMMGq5AF4Dor8KMiJ+ZiYabTj+dsVWSYj/RwKt3S4CzmE/QZkwa93g7T33ownf73t6VbP0sFYckI47JguHH+Yezu9Nj4F9vxneSbQgMfu6oXcgZj9g5VjDYqRCiAocbAAiJLt/Y=" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=debug msg="completed challenge" Nov 01 12:56:13 volumiosalon go-librespot[2944]: time="2025-11-01T12:56:13+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:13 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:13 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:13 volumiosalon volumio[2858]: info: Loading plugin "youtube2"... Nov 01 12:56:16 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:56:16] [connect] Successful connection Nov 01 12:56:16 volumiosalon kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error! Nov 01 12:56:16 volumiosalon shairport-sync[2902]: [869B blob data] Nov 01 12:56:16 volumiosalon shairport-sync[2978]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:56:16 volumiosalon shairport-sync[2978]: Dload Upload Total Spent Left Speed Nov 01 12:56:16 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:16 volumiosalon shairport-sync[2979]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:56:16 volumiosalon shairport-sync[2979]: Dload Upload Total Spent Left Speed Nov 01 12:56:17 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Nov 01 12:56:17 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:17 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:17 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:17 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:17 volumiosalon go-librespot[2981]: go-librespot daemon starting... Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=debug msg="app state loaded" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:17 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=info msg="zeroconf server listening on port 35081" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=debug msg="obtained new client token: AAB3MRvuk9lfKZ2zVjBzMTTC3satl9DlTqXUvvvc3mtTONrNbBVxFVBRa53C52M07rpSY9kbOVCq/KpwtPsLbwRQIdYeoMjOzgNnLgU73SXzBHrBjECzMv3t1RAkqrW7Z0jyroxZCFZBd408aZWrnqc56SKnfg2WaMk3pdFxkpa8rC2JPn6rUWeK5GiwLEwoXE3HX7HdIxv37qZsV7EYoOjZgR9qxCIEDBd2Wq914hQlty4PwrC569L33nc=" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=debug msg="completed challenge" Nov 01 12:56:17 volumiosalon go-librespot[2982]: time="2025-11-01T12:56:17+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:17 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:17 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:18 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:18 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:18 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:19 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:19 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:19 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:19 volumiosalon volumio[2858]: info: Loading plugin "ytmusic"... Nov 01 12:56:20 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:20 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:20 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:21 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Nov 01 12:56:21 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:21 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:21 volumiosalon go-librespot[2989]: go-librespot daemon starting... Nov 01 12:56:21 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:21 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=debug msg="app state loaded" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:21 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=info msg="zeroconf server listening on port 35749" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=debug msg="obtained new client token: AABg4QlTT4irittamLC9V+zoR64dgXyHI8RsScOiXEm/1nvgObR+RwgMGbtaPs9mqdyRKTSrkjWbF5R5w30VkFLGaEGftvEcb4YHnPhP/KhOHiD8zqq/FaY0e4D4ukOZEhFlah5qsN6CszF005AxqgjFTIzCSkcltz8Ijia6qJEU0/tjo1L2a9xjzr3ocPncqH5xARhYn1EfqRnnvU3t15zgKADNlDI9WmcsEbRBQdm46NM7X+mfbRLfVw8=" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=debug msg="completed challenge" Nov 01 12:56:21 volumiosalon go-librespot[2990]: time="2025-11-01T12:56:21+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:21 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:21 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:22 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:22 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:22 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:23 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:23 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:23 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:24 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:24 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:24 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:25 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Nov 01 12:56:25 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:25 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:25 volumiosalon go-librespot[2998]: go-librespot daemon starting... Nov 01 12:56:25 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:25 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=debug msg="app state loaded" Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:25 volumiosalon volumio[2858]: info: Loading plugin "outputs"... Nov 01 12:56:25 volumiosalon volumio[2858]: info: Loading plugin "albumart"... Nov 01 12:56:25 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:25 volumiosalon volumio[2858]: info: Plugin example_plugin is not enabled Nov 01 12:56:25 volumiosalon volumio[2858]: info: Loading plugin "inputs"... Nov 01 12:56:25 volumiosalon volumio[2858]: info: Loading plugin "updater_comm"... Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:25 volumiosalon volumio[2858]: info: Plugin mpdemulation is not enabled Nov 01 12:56:25 volumiosalon volumio[2858]: info: Loading plugin "rest_api"... Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=info msg="zeroconf server listening on port 39535" Nov 01 12:56:25 volumiosalon volumio[2858]: info: Loading plugin "websocket"... Nov 01 12:56:25 volumiosalon volumio[2858]: info: Starting Socket.io Server version 1.7.4 Nov 01 12:56:25 volumiosalon volumio[2858]: info: Loading plugin "80s80s"... Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=debug msg="obtained new client token: AADuSBpSqqHnqVws0XIZfKDF6AUDuoeyrvML/YAfdlVSSnlzNGwVmy2F/+RRwZTwcEUmMU/X5XGR8FdsjFJfQkgJ3lmRIsOoGOBseQMMACgVhgBvei+B97TYOL6dXxmUmuPuj+DS696Fq/ljA9voT7krEQLnQor3NRYC4t7mOyoeadFoYG3i6LZHIM9FAhuJo+vRsE9zc5E1XZyD4VDSR/WqIwSwKqqF7y9IrH6MQdDvO/slW/Bokaf7HUM=" Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=debug msg="completed challenge" Nov 01 12:56:25 volumiosalon go-librespot[2999]: time="2025-11-01T12:56:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:25 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:25 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:26 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:26 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:26 volumiosalon volumio[2858]: info: Applying required configuration parameters for plugin 80s80s Nov 01 12:56:26 volumiosalon volumio[2858]: info: [1761998186199] [80s80s] API delay: 30 Nov 01 12:56:26 volumiosalon volumio[2858]: info: Loading plugin "podcast"... Nov 01 12:56:26 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:26 volumiosalon volumio[3005]: Forking 3 albumart workers Nov 01 12:56:26 volumiosalon volumio[2858]: info: ControllerPodcast::constructor Nov 01 12:56:26 volumiosalon volumio[2858]: info: Loading plugin "Systeminfo"... Nov 01 12:56:27 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:27 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:27 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:27 volumiosalon volumio[2858]: info: Loading i18n strings for locale fr Nov 01 12:56:27 volumiosalon volumio[2858]: Updating browse sources language Nov 01 12:56:27 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:28 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:28 volumiosalon shairport-sync[3062]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:56:28 volumiosalon shairport-sync[3062]: Dload Upload Total Spent Left Speed Nov 01 12:56:28 volumiosalon shairport-sync[3062]: [79B blob data] Nov 01 12:56:28 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::initPlayerControls Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 01 12:56:28 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:28 volumiosalon volumio[2858]: Express server listening on port 3000 Nov 01 12:56:28 volumiosalon volumio[2858]: [Metrics] WebUI: 26s 522.68ms Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreStateMachine::resetVolumioState Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreStateMachine::getcurrentVolume Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioRetrievevolume Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:28 volumiosalon volumio[2858]: info: CorePlayQueue::getTrack 0 Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:28 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:28 volumiosalon volumio[2858]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Nov 01 12:56:28 volumiosalon volumio[2858]: info: Volumio Network Manager: Network status updated: 1 Nov 01 12:56:29 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Nov 01 12:56:29 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:29 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:29 volumiosalon shairport-sync[2902]: [79B blob data] Nov 01 12:56:29 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:29 volumiosalon go-librespot[3067]: go-librespot daemon starting... Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:29 volumiosalon volumio[2858]: info: Reloading queue from file Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=debug msg="app state loaded" Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:29 volumiosalon volumio[2858]: info: Nov 01 12:56:29 volumiosalon volumio[2858]: ---------------------------- Client requests AirplayInactive Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayInctive Nov 01 12:56:29 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:29 volumiosalon shairport-sync[3062]: [79B blob data] Nov 01 12:56:29 volumiosalon shairport-sync[2902]: [158B blob data] Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreStateMachine::setRepeat null single undefined Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:29 volumiosalon volumio[2858]: info: CorePlayQueue::getTrack 0 Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreStateMachine::setRandom true Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:29 volumiosalon volumio[2858]: info: CorePlayQueue::getTrack 0 Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:29 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:29 volumiosalon volumio[2858]: info: Setting Device type: Raspberry PI Nov 01 12:56:29 volumiosalon volumio[3019]: Starting albumart workers Nov 01 12:56:29 volumiosalon volumio[3018]: Starting albumart workers Nov 01 12:56:29 volumiosalon volumio[2858]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.105 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Nov 01 12:56:29 volumiosalon volumio[3017]: Starting albumart workers Nov 01 12:56:29 volumiosalon volumio[2858]: info: Completed loading Core Plugins Nov 01 12:56:29 volumiosalon volumio[2858]: info: Preparing to generate the ALSA configuration file Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=info msg="zeroconf server listening on port 42847" Nov 01 12:56:29 volumiosalon volumio[2858]: info: Discovery: adding 9080a7df-a081-4c2d-afb5-c9e324a7ab93 Nov 01 12:56:29 volumiosalon volumio[2858]: info: Discovery: Found device VolumioComble Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=debug msg="obtained new client token: AAASt4Y6B2K8SZCH4LCkjwdrCPUCEiB67y5Kdv1dP4jUGLNZ5MpMpq1eZBkJYA352oq9sQ/XkxJbnLRLrxurPK4Pb0jWNp0Gk8AVsL5tzWydreQ9Q5bmvUJ5EXMfZmxZdWyp5IUDkSHr9qppa1nLBK00VADuDoqSXF9DF73fJVlyOnjstudv4zzksblsO47fMgHiT8iZq82QapXR+TXZzTgZKmY94y1PpCTMHdq7obxB6gYIAZKhPzMPwas=" Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:29 volumiosalon volumio[2858]: info: Discovery: Connecting to remote: 192.168.3.105 Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:29 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:29+01:00" level=debug msg="completed challenge" Nov 01 12:56:30 volumiosalon go-librespot[3070]: time="2025-11-01T12:56:30+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:30 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:30 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:30 volumiosalon shairport-sync[2902]: {"time":1761998189231,"response":"airplayInactive Success"} Nov 01 12:56:30 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:30 volumiosalon volumio[2858]: info: Asound.conf file unchanged, so no further update is needed Nov 01 12:56:30 volumiosalon volumio[2858]: info: Output device has changed, restarting MPD Nov 01 12:56:30 volumiosalon volumio[2858]: info: Output device has changed, restarting Shairport Sync Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:30 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:30 volumiosalon sudo[3083]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 01 12:56:30 volumiosalon sudo[3083]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:30 volumiosalon volumio[2858]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:56:30 volumiosalon sudo[3085]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 01 12:56:30 volumiosalon volumio[2858]: info: ___________ START PLUGINS ___________ Nov 01 12:56:30 volumiosalon sudo[3085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:30 volumiosalon sudo[3083]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:30 volumiosalon volumio[2858]: info: ControllerMpd::onStart: Initializing MPD Nov 01 12:56:30 volumiosalon volumio[2858]: info: Creating MPD Configuration file Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:30 volumiosalon systemd[1]: Stopping mpd.service - Music Player Daemon... Nov 01 12:56:30 volumiosalon volumio[2858]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:30 volumiosalon systemd[1]: mpd.service: Deactivated successfully. Nov 01 12:56:30 volumiosalon sudo[3094]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 01 12:56:30 volumiosalon systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 01 12:56:30 volumiosalon systemd[1]: mpd.service: Consumed 6.585s CPU time. Nov 01 12:56:30 volumiosalon systemd[1]: mpd.socket: Deactivated successfully. Nov 01 12:56:30 volumiosalon systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 01 12:56:30 volumiosalon systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 01 12:56:30 volumiosalon sudo[3095]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 01 12:56:30 volumiosalon sudo[3094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:30 volumiosalon sudo[3095]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:30 volumiosalon sudo[3094]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:30 volumiosalon systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 01 12:56:30 volumiosalon systemd[1]: Starting mpd.service - Music Player Daemon... Nov 01 12:56:30 volumiosalon volumio[2858]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:56:30 volumiosalon volumio[2858]: info: [1761998190760] CoreMusicLibrary::Adding element Last_100 Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:56:30 volumiosalon volumio[2858]: info: [1761998190768] CoreMusicLibrary::Adding element Webradio Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:30 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:56:30 volumiosalon volumio[2858]: info: Initializing BBC Radios Nov 01 12:56:30 volumiosalon systemd[1]: mpd.service: Deactivated successfully. Nov 01 12:56:30 volumiosalon systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 01 12:56:30 volumiosalon systemd[1]: mpd.socket: Deactivated successfully. Nov 01 12:56:30 volumiosalon systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 01 12:56:30 volumiosalon systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 01 12:56:30 volumiosalon systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 01 12:56:30 volumiosalon systemd[1]: Starting mpd.service - Music Player Daemon... Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:31 volumiosalon shairport-sync[3062]: [79B blob data] Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:56:31 volumiosalon volumio[2858]: info: [1761998191111] CoreMusicLibrary::Adding element Mixcloud Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:31 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source Mixcloud Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:56:31 volumiosalon volumio[2858]: info: [1761998191162] CoreMusicLibrary::Adding element SoundCloud Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source Mixcloud Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source SoundCloud Nov 01 12:56:31 volumiosalon volumio[2858]: info: Creating Spotify config file Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:31 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:31 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:56:31] [connect] Successful connection Nov 01 12:56:31 volumiosalon sudo[3117]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 01 12:56:31 volumiosalon sudo[3117]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Nov 01 12:56:31 volumiosalon sudo[3117]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:56:31 volumiosalon volumio[2858]: info: [1761998191967] CoreMusicLibrary::Adding element YouTube2 Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source Mixcloud Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source SoundCloud Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source YouTube2 Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:56:31 volumiosalon volumio[2858]: info: [1761998191984] CoreMusicLibrary::Adding element YouTube Music Nov 01 12:56:31 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source Mixcloud Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source SoundCloud Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source YouTube2 Nov 01 12:56:31 volumiosalon volumio[2858]: Cannot find translation for source YouTube Music Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:56:32 volumiosalon volumio[2858]: info: [1761998192003] CoreMusicLibrary::Adding element 80s80s Radio Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source Mixcloud Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source SoundCloud Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source YouTube2 Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source YouTube Music Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source 80s80s Radio Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:56:32 volumiosalon volumio[2858]: info: [1761998192022] CoreMusicLibrary::Adding element Podcast Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source Mixcloud Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source SoundCloud Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source YouTube2 Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source YouTube Music Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source 80s80s Radio Nov 01 12:56:32 volumiosalon volumio[2858]: Cannot find translation for source Podcast Nov 01 12:56:32 volumiosalon volumio[2858]: info: Volumio Calling Home Nov 01 12:56:32 volumiosalon shairport-sync[3062]: [79B blob data] Nov 01 12:56:32 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:32 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:32 volumiosalon volumio[2858]: info: Nov 01 12:56:32 volumiosalon volumio[2858]: ---------------------------- Client requests AirplayActive Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayActive Nov 01 12:56:32 volumiosalon shairport-sync[3062]: [79B blob data] Nov 01 12:56:32 volumiosalon shairport-sync[2978]: [79B blob data] Nov 01 12:56:32 volumiosalon volumio[2858]: info: Nov 01 12:56:32 volumiosalon volumio[2858]: ---------------------------- Client requests Start Airplay PlaybackRoutine Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Nov 01 12:56:32 volumiosalon volumio[2858]: info: Airplay playback start Nov 01 12:56:32 volumiosalon volumio[2858]: info: CorePlayQueue::getTrack 0 Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioStop Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreStateMachine::stop Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 01 12:56:32 volumiosalon shairport-sync[2978]: {"time":1761998192387,"response":"airplayActive Success"} Nov 01 12:56:32 volumiosalon shairport-sync[2979]: [79B blob data] Nov 01 12:56:32 volumiosalon volumio[2858]: info: Discovery: adding 8e36d70c-1812-4fc0-9282-89074ef539a8 Nov 01 12:56:32 volumiosalon volumio[2858]: info: Discovery: Found device VolumioSalon Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:32 volumiosalon volumio[2858]: info: CorePlayQueue::getTrack 0 Nov 01 12:56:32 volumiosalon volumio[2858]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.105 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 01 12:56:32 volumiosalon volumio[2858]: info: MPD Permissions set Nov 01 12:56:32 volumiosalon volumio[2858]: info: MPD Permissions set Nov 01 12:56:32 volumiosalon volumio[2858]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.105 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 01 12:56:32 volumiosalon volumio[2858]: info: Discovery: Connected to remote: 192.168.3.105 Nov 01 12:56:32 volumiosalon volumio[2858]: info: Volumio called home Nov 01 12:56:32 volumiosalon volumio[2858]: info: Spotify config file written Nov 01 12:56:32 volumiosalon volumio[2858]: info: Discovery: this is already registered, 8e36d70c-1812-4fc0-9282-89074ef539a8 Nov 01 12:56:32 volumiosalon volumio[2858]: info: Discovery: Found device VolumioSalon Nov 01 12:56:32 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:32 volumiosalon volumio[2858]: info: CorePlayQueue::getTrack 0 Nov 01 12:56:32 volumiosalon sudo[3148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 01 12:56:32 volumiosalon sudo[3148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:32 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:33 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:33 volumiosalon sudo[3148]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:33 volumiosalon go-librespot[3150]: go-librespot daemon starting... Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=debug msg="app state loaded" Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:56:33 volumiosalon volumio[2858]: info: No need to fix Spotify hosts Nov 01 12:56:33 volumiosalon volumio[2858]: info: Nov 01 12:56:33 volumiosalon volumio[2858]: ---------------------------- Client requests Stop Airplay Playback Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , stopAirplayPlayback Nov 01 12:56:33 volumiosalon volumio[2858]: info: Airplay playback stop Nov 01 12:56:33 volumiosalon volumio[2858]: info: CorePlayQueue::getTrack 0 Nov 01 12:56:33 volumiosalon shairport-sync[2979]: {"time":1761998192562,"response":"startAirplayPlayback Success"} Nov 01 12:56:33 volumiosalon shairport-sync[3062]: [158B blob data] Nov 01 12:56:33 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:56:33] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761998191 101 Nov 01 12:56:33 volumiosalon volumio[2858]: 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: 4 Nov 01 12:56:33 volumiosalon volumio[2858]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 01 12:56:33 volumiosalon volumio[2858]: info: An error occurred while refreshing Spotify Token Error: Bad Request Nov 01 12:56:33 volumiosalon volumio[2858]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.105 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 01 12:56:33 volumiosalon volumio[2858]: info: Starting Shairport Sync Nov 01 12:56:33 volumiosalon volumio[2858]: info: Starting Shairport Sync Nov 01 12:56:33 volumiosalon volumio[2858]: info: Starting Shairport Sync Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:33 volumiosalon sudo[3170]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=info msg="zeroconf server listening on port 36495" Nov 01 12:56:33 volumiosalon sudo[3170]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:33 volumiosalon volumio[2858]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Nov 01 12:56:33 volumiosalon sudo[3172]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:56:33 volumiosalon sudo[3172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:33 volumiosalon sudo[3174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:56:33 volumiosalon sudo[3174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=debug msg="obtained new client token: AACNY0xBhVajdRJDyDnqmPlFxjqsw9yv4gEuI/au0X6t2d4ohCvCVxm2EXYfNL8uLAz+I7s2fegI/2nJS8g+9bjCws6ILCLNKnqoOFmWTmZozKmx13gMl04Kxi2MOyuMwDgpCf2HSYG/rVGIRNy+yJBYjIWLtK2iLZd6RmgiW1FbIUBeR6BurOfc88wur0lgbsvzlMloK2rBzrpFqrYqs97yqSBzYso2t7qH/bCGTSmNMpt6OyVKAYrVobU=" Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=debug msg="completed challenge" Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Nov 01 12:56:33 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:33 volumiosalon shairport-sync[3062]: {"time":1761998193192,"response":"stopAirplayPlayback Success"} Nov 01 12:56:33 volumiosalon systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Nov 01 12:56:33 volumiosalon go-librespot[3151]: time="2025-11-01T12:56:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:33 volumiosalon systemd[1]: shairport-sync.service: Deactivated successfully. Nov 01 12:56:33 volumiosalon systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 01 12:56:33 volumiosalon systemd[1]: shairport-sync.service: Consumed 7.234s CPU time. Nov 01 12:56:33 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:33 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:34 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:34 volumiosalon systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 01 12:56:34 volumiosalon sudo[3170]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:34 volumiosalon sudo[3172]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:34 volumiosalon sudo[3174]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:34 volumiosalon volumio[2858]: info: Shairport-Sync Started Nov 01 12:56:34 volumiosalon volumio[2858]: Error adding Membership: Error: addMembership EINVAL Nov 01 12:56:34 volumiosalon volumio[2858]: info: Shairport-Sync Started Nov 01 12:56:34 volumiosalon volumio[2858]: info: Shairport-Sync Started Nov 01 12:56:36 volumiosalon volumio[2858]: info: go-librespot daemon successfully initialized Nov 01 12:56:37 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Nov 01 12:56:37 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:37 volumiosalon mpd[3130]: 2025-11-01T12:56:37 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 01 12:56:37 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:37 volumiosalon go-librespot[3201]: go-librespot daemon starting... Nov 01 12:56:37 volumiosalon systemd[1]: Started mpd.service - Music Player Daemon. Nov 01 12:56:37 volumiosalon sudo[3095]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:37 volumiosalon sudo[3085]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=debug msg="app state loaded" Nov 01 12:56:37 volumiosalon volumio[2858]: info: Completed starting Core Plugins Nov 01 12:56:37 volumiosalon volumio[2858]: info: ------------------------------------------- Nov 01 12:56:37 volumiosalon volumio[2858]: info: ----- MyVolumio plugins startup ---- Nov 01 12:56:37 volumiosalon volumio[2858]: info: ------------------------------------------- Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:37 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 01 12:56:37 volumiosalon volumio[2858]: error: MPD error: The expression evaluated to a falsy value: Nov 01 12:56:37 volumiosalon volumio[2858]: assert.ok(self.idling) Nov 01 12:56:37 volumiosalon volumio[2858]: error: The expression evaluated to a falsy value: Nov 01 12:56:37 volumiosalon volumio[2858]: assert.ok(self.idling) Nov 01 12:56:37 volumiosalon volumio[2858]: info: MPD running with PID3130 Nov 01 12:56:37 volumiosalon volumio[2858]: ,establishing connection Nov 01 12:56:37 volumiosalon volumio[2858]: error: updateQueue error: null Nov 01 12:56:37 volumiosalon volumio[2858]: error: updateQueue error: null Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=info msg="zeroconf server listening on port 37739" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=debug msg="obtained new client token: AAD2+bzbTsfLy71J4zWqhR/fluaKWIma3KTewFPpns5DImXUMZpsFbYIneI2z6vXwqTeteB7LmR0nzPFBRyA4GEpMdwV9j+iWnKSpwkO5igskiaK2hKQGR00+c7XxPy4T/xQvhVrcEQT4gCA40EK/oWsTx7/SXHElkjndgwrcg/J2mqfbo1WMVmnOTofJ45RaBPt3v0EBey0Hk0bGYKQ2w0ks7frd0YRNWKOx9OhlJ+BRDRZo+3DMp2m78I=" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=debug msg="completed challenge" Nov 01 12:56:37 volumiosalon go-librespot[3215]: time="2025-11-01T12:56:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:37 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:37 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:37 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:56:37 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:56:37 volumiosalon volumio[2858]: info: Discovery: Getting this device information Nov 01 12:56:37 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:37 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:56:37 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:56:37 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:56:37 volumiosalon volumio[2858]: info: Discovery: Getting this device information Nov 01 12:56:37 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:37 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:56:38 volumiosalon volumio[2858]: verbose: New Socket.io Connection to 192.168.3.151:3000 from 192.168.3.217 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Nov 01 12:56:38 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:38 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Nov 01 12:56:38 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Nov 01 12:56:38 volumiosalon volumio[2858]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Nov 01 12:56:39 volumiosalon volumio[2858]: info: Initializing connection to go-librespot Websocket Nov 01 12:56:39 volumiosalon volumio[2858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:56:39 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:40 volumiosalon sudo[3227]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 01 12:56:40 volumiosalon sudo[3227]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:40 volumiosalon sudo[3230]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 01 12:56:40 volumiosalon sudo[3230]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:40 volumiosalon systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 01 12:56:40 volumiosalon systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 01 12:56:40 volumiosalon systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 01 12:56:40 volumiosalon kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error! Nov 01 12:56:40 volumiosalon volumio[2858]: info: Airplay started streaming, receiving metadatas Nov 01 12:56:40 volumiosalon volumio[2858]: info: Airplay started streaming, receiving metadatas Nov 01 12:56:40 volumiosalon volumio[2858]: info: Airplay started streaming, receiving metadatas Nov 01 12:56:40 volumiosalon systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 01 12:56:40 volumiosalon sudo[3227]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:40 volumiosalon volumio[2858]: info: Successfully started MPD Monitor Nov 01 12:56:40 volumiosalon mpd_monitor.sh[3233]: MPD Monitor Service: Starting MPD Monitor Service Nov 01 12:56:40 volumiosalon volumio[2858]: info: Updating volume from AirPlay: -18; 40% Nov 01 12:56:40 volumiosalon systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 01 12:56:40 volumiosalon shairport-sync[3235]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:56:40 volumiosalon shairport-sync[3235]: Dload Upload Total Spent Left Speed Nov 01 12:56:40 volumiosalon systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 01 12:56:40 volumiosalon volumio[2858]: info: VolumeController::SetAlsaVolume40 Nov 01 12:56:40 volumiosalon systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 01 12:56:40 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:40 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:40 volumiosalon systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 01 12:56:40 volumiosalon shairport-sync[3235]: [79B blob data] Nov 01 12:56:40 volumiosalon shairport-sync[3236]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 01 12:56:40 volumiosalon shairport-sync[3236]: Dload Upload Total Spent Left Speed Nov 01 12:56:40 volumiosalon sudo[3230]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:40 volumiosalon mpd_monitor.sh[3244]: MPD Monitor Service: Starting MPD Monitor Service Nov 01 12:56:40 volumiosalon volumio[2858]: info: Successfully started MPD Monitor Nov 01 12:56:40 volumiosalon volumio[2858]: info: Nov 01 12:56:40 volumiosalon volumio[2858]: ---------------------------- Client requests AirplayActive Nov 01 12:56:40 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayActive Nov 01 12:56:40 volumiosalon shairport-sync[3236]: [79B blob data] Nov 01 12:56:40 volumiosalon shairport-sync[3235]: [79B blob data] Nov 01 12:56:40 volumiosalon volumio[2858]: info: Nov 01 12:56:40 volumiosalon volumio[2858]: ---------------------------- Client requests Start Airplay PlaybackRoutine Nov 01 12:56:40 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Nov 01 12:56:40 volumiosalon volumio[2858]: info: Airplay playback start Nov 01 12:56:40 volumiosalon shairport-sync[3235]: {"time":1761998200573,"response":"airplayActive Success"} Nov 01 12:56:40 volumiosalon shairport-sync[3236]: [79B blob data] Nov 01 12:56:41 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Nov 01 12:56:41 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:41 volumiosalon sudo[3249]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 01 12:56:41 volumiosalon sudo[3249]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:41 volumiosalon sudo[3249]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:41 volumiosalon sudo[3251]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 01 12:56:41 volumiosalon sudo[3251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:41 volumiosalon sudo[3251]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:41 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:41 volumiosalon go-librespot[3252]: go-librespot daemon starting... Nov 01 12:56:41 volumiosalon volumio[2858]: verbose: New Socket.io Connection to 192.168.3.151 from 192.168.3.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=debug msg="app state loaded" Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:41 volumiosalon sudo[3265]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 01 12:56:41 volumiosalon sudo[3265]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:41 volumiosalon sudo[3265]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:41 volumiosalon sudo[3267]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 01 12:56:41 volumiosalon sudo[3267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:41 volumiosalon sudo[3267]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:41 volumiosalon volumio[2858]: verbose: New Socket.io Connection to 192.168.3.151 from 192.168.3.217 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=info msg="zeroconf server listening on port 44935" Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=debug msg="obtained new client token: AAAfS8FHDAB7OuV7BzOW1146JK6VrsSVEJ/LfHksnahuIESaBgXvJmoT3Kqz0CD0AU7PR5+YKGiH6IkjRjm8SZCSoOc2enn3SOPaFfG4oHzN7vK1yUVCDNSlwi/n9KCrwQJeF/0o8NOMmWPJC1ro8wkpNYFhcqMtdhSdrcUzJeB8g7Nvngl9zYXaWrB3hrFh8YktCorM/Yy+8M7OJzDj9J1C5jJqRckvalO4s/EEPTFr9qeQ18Zc9pgcUIE=" Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetVisibleSources Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 01 12:56:41 volumiosalon volumio[2858]: info: Received Get System Info Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:56:41 volumiosalon volumio[2858]: info: Discovery: Getting this device information Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=debug msg="completed challenge" Nov 01 12:56:41 volumiosalon volumio[2858]: info: Listing playlists Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Nov 01 12:56:41 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 01 12:56:41 volumiosalon go-librespot[3257]: time="2025-11-01T12:56:41+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:41 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:41 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 01 12:56:42 volumiosalon volumio[2858]: info: Initializing connection to go-librespot Websocket Nov 01 12:56:42 volumiosalon volumio[2858]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:42 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 01 12:56:43 volumiosalon volumio[2858]: info: Received Get System Info Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:56:43 volumiosalon volumio[2858]: info: Discovery: Getting this device information Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Nov 01 12:56:43 volumiosalon volumio[2858]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:43 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:44 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 01 12:56:44 volumiosalon volumio[2858]: info: Received Get System Info Nov 01 12:56:44 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:56:44 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:56:44 volumiosalon volumio[2858]: info: Discovery: Getting this device information Nov 01 12:56:44 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetState Nov 01 12:56:44 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:56:44 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Nov 01 12:56:45 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Nov 01 12:56:45 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:45 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:45 volumiosalon go-librespot[3274]: go-librespot daemon starting... Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="app state loaded" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=info msg="zeroconf server listening on port 42507" Nov 01 12:56:45 volumiosalon volumio[2858]: info: Initializing connection to go-librespot Websocket Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="new websocket client" Nov 01 12:56:45 volumiosalon volumio[2858]: info: Connection to go-librespot Websocket established Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="obtained new client token: AAAPQH7/afpPF92cBo98igEyRQPasBaxxkmCweFu0HFy7iw46hsIoW5hVLFPt59/NGz+bHn3TR/QLHygtcm3abPqejrQ6l6Z+9HESZGJMfm5WXSo+ef7bgwAAnY9s/LPnuoaqJFhYjTcTmK2hSN5gwjfM2X0e7wZ7AFc0ex3X+aFdULA70uR9AyzqWj8ktCG61y0ApNk1nTEqpuFWuuu4a93FvsfOACT9hkGc2dKSK8mCcdXUnmP7QCNkSM=" Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Nov 01 12:56:45 volumiosalon volumio[2858]: info: Adding plugin bluetooth to MyMusic Plugins Nov 01 12:56:45 volumiosalon volumio[2858]: info: Adding plugin multiroom to MyMusic Plugins Nov 01 12:56:45 volumiosalon volumio[2858]: info: Adding plugin metavolumio to MyMusic Plugins Nov 01 12:56:45 volumiosalon volumio[2858]: info: Adding plugin cd_controller to MyMusic Plugins Nov 01 12:56:45 volumiosalon volumio[2858]: info: Adding plugin qobuzconnect to MyMusic Plugins Nov 01 12:56:45 volumiosalon volumio[2858]: info: Adding plugin smart_inputs to MyMusic Plugins Nov 01 12:56:45 volumiosalon volumio[2858]: info: Adding plugin tidalconnect to MyMusic Plugins Nov 01 12:56:45 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=debug msg="completed challenge" Nov 01 12:56:45 volumiosalon go-librespot[3275]: time="2025-11-01T12:56:45+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:45 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:45 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:47 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Nov 01 12:56:47 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Nov 01 12:56:47 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:47 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:56:47 volumiosalon volumio[2858]: info: Starting MyVolumio Remote Streaming Endpoints Nov 01 12:56:47 volumiosalon volumio[2858]: info: MyVolumio login type: Token Nov 01 12:56:47 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Nov 01 12:56:47 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Nov 01 12:56:49 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Nov 01 12:56:49 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:49 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:49 volumiosalon go-librespot[3296]: go-librespot daemon starting... Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=debug msg="app state loaded" Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:49 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Nov 01 12:56:49 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Nov 01 12:56:49 volumiosalon volumio[2858]: info: Streaming services startup Nov 01 12:56:49 volumiosalon volumio[2858]: info: Starting Streaming Daemon Nov 01 12:56:49 volumiosalon sudo[3304]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 01 12:56:49 volumiosalon sudo[3304]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:49 volumiosalon volumio[2858]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Nov 01 12:56:49 volumiosalon sudo[3304]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:49 volumiosalon volumio[2858]: info: Getting Spotify volume Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioGetQueue Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::getQueue Nov 01 12:56:49 volumiosalon volumio[2858]: info: CorePlayQueue::getQueue Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioClearQueue Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::ClearQueue Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::stop Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::serviceStop Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::serviceStop Nov 01 12:56:49 volumiosalon volumio[2858]: info: Airplay Stop Nov 01 12:56:49 volumiosalon volumio[2858]: info: Stopping Airplay Playback and sending pause command to client via USR2 Nov 01 12:56:49 volumiosalon volumio[2858]: info: CorePlayQueue::clearPlayQueue Nov 01 12:56:49 volumiosalon volumio[2858]: info: CorePlayQueue::saveQueue Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushQueue Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=info msg="zeroconf server listening on port 32873" Nov 01 12:56:49 volumiosalon sudo[3313]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 3179 Nov 01 12:56:49 volumiosalon volumio[2858]: info: Connection to go-librespot Websocket closed Nov 01 12:56:49 volumiosalon sudo[3313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:49 volumiosalon volumio[2858]: error: Cannot start Volumio Streaming Daemon Nov 01 12:56:49 volumiosalon volumio[2858]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 01 12:56:49 volumiosalon volumio[2858]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 01 12:56:49 volumiosalon shairport-sync[3236]: {"time":1761998200616,"response":"startAirplayPlayback Success"} Nov 01 12:56:49 volumiosalon sudo[3313]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:49 volumiosalon systemd[1]: shairport-sync.service: Main process exited, code=killed, status=12/USR2 Nov 01 12:56:49 volumiosalon systemd[1]: shairport-sync.service: Failed with result 'signal'. Nov 01 12:56:49 volumiosalon systemd[1]: shairport-sync.service: Consumed 3.180s CPU time. Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=debug msg="obtained new client token: AADToTdL4HK/4XE7+9QqepZD6p8QAqQ89V4dYyO8STSTpV5G39e0Ps7GK+hwBWW3VV6CAyZapmKWhdAeSFExBgZBy1AbqJSplq+4ys8WaFeSWySE69YScKSbTCYNC0W/tvnCBthQpT0iVdlZjFhm3EVpugPdHGAtfb4MCxoEWGhu6UviFKwoQiSH7qFe/CVkx014oh05dr4ICADJwYyBK5X+AJTW9t3rhDYVbJVOSgiOgDfyzw7XcOujKb8=" Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=debug msg="completed challenge" Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::servicePushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreStateMachine::pushState Nov 01 12:56:49 volumiosalon volumio[2858]: info: CoreCommandRouter::volumioPushState Nov 01 12:56:49 volumiosalon go-librespot[3297]: time="2025-11-01T12:56:49+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Nov 01 12:56:49 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:49 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:49 volumiosalon volumio[2858]: info: Shairport-Sync paused with USR2 Nov 01 12:56:49 volumiosalon volumio[2858]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 01 12:56:50 volumiosalon volumio[2858]: Error: socket hang up Nov 01 12:56:50 volumiosalon volumio[2858]: at connResetException (node:internal/errors:720:14) Nov 01 12:56:50 volumiosalon volumio[2858]: at Socket.socketOnEnd (node:_http_client:519:23) Nov 01 12:56:50 volumiosalon volumio[2858]: at Socket.emit (node:events:526:35) Nov 01 12:56:50 volumiosalon volumio[2858]: at endReadableNT (node:internal/streams/readable:1376:12) Nov 01 12:56:50 volumiosalon volumio[2858]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Nov 01 12:56:50 volumiosalon volumio[2858]: code: 'ECONNRESET', Nov 01 12:56:50 volumiosalon volumio[2858]: response: undefined Nov 01 12:56:50 volumiosalon volumio[2858]: } Nov 01 12:56:50 volumiosalon volumio[2858]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 01 12:56:51 volumiosalon sudo[3329]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-11-01 12:55' Nov 01 12:56:51 volumiosalon sudo[3329]: 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="5ef3d56f987d109f3e21bfa246dbbb723cf6a917" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="c7bff9654d2984a81c5720476c2c8ac531869c54" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Oct 9 18:08:11 UTC 2025" VOLUMIO_VERSION="4.062" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="00524295c246b7d72f125e4c54b86a88"