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) Nov 01 12:56:51 volumiosalon sudo[3329]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:52 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:56:52] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Nov 01 12:56:52 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:56:52] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Nov 01 12:56:52 volumiosalon systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:52 volumiosalon systemd[1]: volumio.service: Failed with result 'exit-code'. Nov 01 12:56:52 volumiosalon systemd[1]: volumio.service: Consumed 1min 12.046s CPU time. Nov 01 12:56:52 volumiosalon systemd[1]: Started dynamicswap.service - dynamicswap service. Nov 01 12:56:52 volumiosalon systemd[1]: dynamicswap.service: Deactivated successfully. Nov 01 12:56:52 volumiosalon systemd[1]: volumio.service: Scheduled restart job, restart counter is at 69. Nov 01 12:56:52 volumiosalon systemd[1]: Started dynamicswap.service - dynamicswap service. Nov 01 12:56:52 volumiosalon systemd[1]: Stopped volumio.service - Volumio Backend Module. Nov 01 12:56:52 volumiosalon systemd[1]: volumio.service: Consumed 1min 12.046s CPU time. Nov 01 12:56:52 volumiosalon systemd[1]: Started volumio.service - Volumio Backend Module. Nov 01 12:56:52 volumiosalon systemd[1]: dynamicswap.service: Deactivated successfully. Nov 01 12:56:53 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Nov 01 12:56:53 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:53 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:53 volumiosalon go-librespot[3361]: go-librespot daemon starting... Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56:53+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56:53+01:00" level=debug msg="app state loaded" Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56: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:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56: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:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56: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:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56:53+01:00" level=info msg="zeroconf server listening on port 44991" Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56:53+01:00" level=debug msg="obtained new client token: AACMWtCuxLbvM5zPeSa7Zm+u7Y6sg0BwZ91ayxmwaLCGWVWcP2iyHxKEDM0Qs0kgarprdcvfRkhqDsIuYYQVt+cnDjvzls0NML+nuUdieEklRIQCDESbCig+IFCbH39Im6Sl6Qi/KXfc7r0jJus3XHUYWegyoHf9CKEkYP1FCwemEmbE1LAvUbkNayvzDrDQkD6xUipD4lb3anV7XdMwQPp3yu21O4kan6vlLEVjFLVwe3Z6KCIylUzD2JA=" Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56:53+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56:53+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56:53+01:00" level=debug msg="completed challenge" Nov 01 12:56:53 volumiosalon go-librespot[3362]: time="2025-11-01T12:56: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:56:53 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:53 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:56 volumiosalon volumio[3346]: info: ------------------------------------------- Nov 01 12:56:56 volumiosalon volumio[3346]: info: ----- Volumio3 ---- Nov 01 12:56:56 volumiosalon volumio[3346]: info: ------------------------------------------- Nov 01 12:56:56 volumiosalon volumio[3346]: info: ----- System startup ---- Nov 01 12:56:56 volumiosalon volumio[3346]: info: ------------------------------------------- Nov 01 12:56:57 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Nov 01 12:56:57 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:57 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:56:57 volumiosalon go-librespot[3376]: go-librespot daemon starting... Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+01:00" level=debug msg="app state loaded" Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:56:57 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:56:57] [connect] Successful connection Nov 01 12:56:57 volumiosalon volumio[3346]: info: MYVOLUMIO Environment detected Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56: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-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+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:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+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:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+01:00" level=info msg="zeroconf server listening on port 41349" Nov 01 12:56:57 volumiosalon volumio[3346]: info: Plugin folders cleanup Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning into folder /volumio/app/plugins/ Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning category audio_interface Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning category miscellanea Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning category music_service Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning category plugins.json Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning category system_controller Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning category user_interface Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning into folder /data/plugins/ Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning category music_service Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+01:00" level=debug msg="obtained new client token: AACG39cNDLT3KRnfBkrz4EY1ZnX+M+tc+Ny1Ag4LFeFFwvw7tcIVcb5P58c64kmWaH2tAv+xIutoih3Qv0aLmfFxquvkQ56kDOqe5jQG1C17mYiJhn1qQeEh3ClF7uTmfZkf9F6FrSrd22SngmPSoCy4os1BIplcViE4iqtP9//oK6+FQS3ff1r6e658AZjRRghmxukNNSb1tJSIpXAqRxyCu9XA5YFij+/a7uWP6dm4nS927lvHtpHXf9s=" Nov 01 12:56:57 volumiosalon volumio[3346]: info: Scanning category user_interface Nov 01 12:56:57 volumiosalon volumio[3346]: info: Plugin folders cleanup completed Nov 01 12:56:57 volumiosalon volumio[3346]: info: ------------------------------------------- Nov 01 12:56:57 volumiosalon volumio[3346]: info: ----- Core plugins startup ---- Nov 01 12:56:57 volumiosalon volumio[3346]: info: ------------------------------------------- Nov 01 12:56:57 volumiosalon volumio[3346]: info: Loading plugins from folder /volumio/app/plugins/ Nov 01 12:56:57 volumiosalon volumio[3346]: info: Adding plugin upnp to MyMusic Plugins Nov 01 12:56:57 volumiosalon volumio[3346]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 01 12:56:57 volumiosalon volumio[3346]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 01 12:56:57 volumiosalon volumio[3346]: info: Loading plugins from folder /data/plugins/ Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:56:57 volumiosalon volumio[3346]: info: Loading plugin "system"... Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+01:00" level=debug msg="completed keyexchange" Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56:57+01:00" level=debug msg="completed challenge" Nov 01 12:56:57 volumiosalon go-librespot[3377]: time="2025-11-01T12:56: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:56:57 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:56:57 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:56:57 volumiosalon volumio[3346]: info: Loading plugin "appearance"... Nov 01 12:56:59 volumiosalon volumio[3346]: info: Loading plugin "network"... Nov 01 12:56:59 volumiosalon volumio[3346]: info: Refreshing Cached IP Addresses Nov 01 12:56:59 volumiosalon volumio[3346]: info: Loading plugin "services"... Nov 01 12:56:59 volumiosalon sudo[3392]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 01 12:56:59 volumiosalon sudo[3392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:59 volumiosalon sudo[3394]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 01 12:56:59 volumiosalon volumio[3346]: info: Loading plugin "alsa_controller"... Nov 01 12:56:59 volumiosalon sudo[3394]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:56:59 volumiosalon sudo[3392]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:59 volumiosalon sudo[3394]: pam_unix(sudo:session): session closed for user root Nov 01 12:56:59 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:56:59 volumiosalon volumio[3346]: info: Loading plugin "wizard"... Nov 01 12:56:59 volumiosalon volumio[3346]: info: Loading plugin "networkfs"... Nov 01 12:56:59 volumiosalon volumio[3346]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Nov 01 12:56:59 volumiosalon volumio[3346]: info: Starting Udev Watcher for removable devices Nov 01 12:57:00 volumiosalon volumio[3346]: info: Ignoring mount for partition: boot Nov 01 12:57:00 volumiosalon volumio[3346]: info: Ignoring mount for partition: volumio Nov 01 12:57:00 volumiosalon volumio[3346]: info: Ignoring mount for partition: volumio_data Nov 01 12:57:00 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 01 12:57:00 volumiosalon volumio[3346]: info: Loading plugin "volumio_command_line_client"... Nov 01 12:57:00 volumiosalon volumio[3346]: info: Plugin upnp is not enabled Nov 01 12:57:00 volumiosalon volumio[3346]: info: Loading plugin "my_music"... Nov 01 12:57:00 volumiosalon volumio[3346]: info: Loading plugin "mpd"... Nov 01 12:57:00 volumiosalon volumio[3346]: info: Plugin upnp_browser is not enabled Nov 01 12:57:00 volumiosalon volumio[3346]: info: Loading plugin "alarm-clock"... Nov 01 12:57:01 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Nov 01 12:57:01 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:01 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:01 volumiosalon go-librespot[3424]: go-librespot daemon starting... Nov 01 12:57:01 volumiosalon volumio[3346]: info: Loading plugin "airplay_emulation"... Nov 01 12:57:01 volumiosalon volumio[3346]: info: Starting Shairport Sync Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57:01+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57:01+01:00" level=debug msg="app state loaded" Nov 01 12:57:01 volumiosalon volumio[3346]: info: Loading plugin "last_100"... Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:01 volumiosalon volumio[3346]: info: Loading plugin "webradio"... Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57: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:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57: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:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57: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:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57:01+01:00" level=info msg="zeroconf server listening on port 37189" Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57:01+01:00" level=debug msg="obtained new client token: AADxU1NguNUqi5QDGVl7MClm5KAHiAT6Znrxtk2D7dVwrsr19aDMxOe9FpWyUNgQbpjGCYk6P9JFf/7JtgDLLdjlDbHiMY1j5B65p7dlWxWbLkwWJBDY0g+/Wpq2owQib8fY9tkeOfud45f5H/CY0QWJkTTOsgOenHKMIOwYxrQRz+7KGfraYBKLORh8cmZ2c+RalzdvdHEmD0q6RvLw8Vef8ATq4zKHCuuqSZh0u9Y95LwmIP+2UPJgZ3U=" Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57:01+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57:01+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57:01+01:00" level=debug msg="completed challenge" Nov 01 12:57:01 volumiosalon go-librespot[3425]: time="2025-11-01T12:57: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:57:01 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:01 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:03 volumiosalon volumio[3346]: info: Loading plugin "i2s_dacs"... Nov 01 12:57:03 volumiosalon volumio[3346]: info: Loading plugin "volumiodiscovery"... Nov 01 12:57:03 volumiosalon volumio[3346]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 01 12:57:03 volumiosalon volumio[3346]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 01 12:57:03 volumiosalon volumio[3346]: *** WARNING *** For more information see Nov 01 12:57:03 volumiosalon volumio[3346]: *** 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:57:03 volumiosalon volumio[3346]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 01 12:57:03 volumiosalon volumio[3346]: *** WARNING *** For more information see Nov 01 12:57:03 volumiosalon node[3346]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 01 12:57:03 volumiosalon node[3346]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 01 12:57:03 volumiosalon node[3346]: *** WARNING *** For more information see Nov 01 12:57:03 volumiosalon node[3346]: *** 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:57:03 volumiosalon node[3346]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 01 12:57:03 volumiosalon node[3346]: *** WARNING *** For more information see Nov 01 12:57:03 volumiosalon volumio[3346]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 01 12:57:03 volumiosalon volumio[3346]: info: Discovery: Started advertising with name: VolumioSalon Nov 01 12:57:03 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 01 12:57:03 volumiosalon volumio[3346]: info: Loading plugin "mixcloud"... Nov 01 12:57:04 volumiosalon volumio[3346]: info: Loading plugin "soundcloud"... Nov 01 12:57:05 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Nov 01 12:57:05 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:05 volumiosalon volumio[3346]: info: Loading plugin "spop"... Nov 01 12:57:05 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:05 volumiosalon go-librespot[3435]: go-librespot daemon starting... Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+01:00" level=debug msg="app state loaded" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+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:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+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:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+01:00" level=info msg="zeroconf server listening on port 36261" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+01:00" level=debug msg="obtained new client token: AABJlqhRmpOP2iXL/n6aAv+r5oaYAAfn1gVmO62AJILOCk8qGegP5W4jhrX7w43Eqj9qjHgZc+2U7EYmMyMe91hUjdRsYadM+HBiNv9VWL7geqkjQaNkRI4hywkcEXAfiPy9ztgfwIQM+Efs+zsiCgPAvZMXylf5SbzC8y5u7qxhXDjqS8ORyqTOj7g1hflj2qIJohJC5ePPBYDkE5wLsADyOPsVslULZ/BTOcKo1n9TWGGi+jj0P7ne7/k=" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57:05+01:00" level=debug msg="completed challenge" Nov 01 12:57:05 volumiosalon go-librespot[3436]: time="2025-11-01T12:57: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:57:05 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:05 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:06 volumiosalon volumio[3346]: info: Loading plugin "youtube2"... Nov 01 12:57:09 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Nov 01 12:57:09 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:09 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:09 volumiosalon go-librespot[3443]: go-librespot daemon starting... Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57:09+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57:09+01:00" level=debug msg="app state loaded" Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57:09+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57: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:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57: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:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57: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:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57:09+01:00" level=info msg="zeroconf server listening on port 42393" Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57:09+01:00" level=debug msg="obtained new client token: AADK0/91dxnDqzxmVeXClvhLzAGNLlPMUlY9739ks9JAJl5354EoRX03tAidd6/Wix5nCwRxesnc+CNiDeQd1Dw3KUH8DRCeuGCq0XShKlzHuu/ImEtCJGsG6C2X6hPcsSI1ieIcEx4XVakBg1emLJlEMXDjPm50l/22GDX1RaUGzoniiEx15s0zbTlejgrPjYrmDU6fEJ+vX4LmI7Zsa+Nf9WUlhOSiVOvQW1q51StIc/eKzCRqInKustk=" Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57:09+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:09 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:57:09] [connect] Successful connection Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57:09+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57:09+01:00" level=debug msg="completed challenge" Nov 01 12:57:09 volumiosalon go-librespot[3444]: time="2025-11-01T12:57: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:57:09 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:09 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:12 volumiosalon volumio[3346]: info: Loading plugin "ytmusic"... Nov 01 12:57:13 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. Nov 01 12:57:13 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:13 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:13 volumiosalon go-librespot[3466]: go-librespot daemon starting... Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57:13+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57:13+01:00" level=debug msg="app state loaded" Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57: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:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57: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:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57: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:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57:13+01:00" level=info msg="zeroconf server listening on port 43469" Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57:13+01:00" level=debug msg="obtained new client token: AAADESvCVH6XDQ676wE6UUXfsSOr6q03Hl+3j346Q46wZJB35AcpclfuRYRdm48JRP6xONmTxFJE2N3abCCnKYTUO1bpq3dchaX5OB4sWmRjintTC+ZvB5UdhfTidWaxoRHZCwAP24aDpcxt3mK06cmMO8I0bCdMIJtQ64QlTRxlO7DGbLv96rkpxP5bs6gxQ4lXLlpsIO9tcYtSUnUdn6gDNb27eDmCXaermK1Z35/0IVWysCaKBFtheuc=" Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57:13+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57:13+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57:13+01:00" level=debug msg="completed challenge" Nov 01 12:57:13 volumiosalon go-librespot[3467]: time="2025-11-01T12:57: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:57:13 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:13 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:17 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. Nov 01 12:57:17 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:17 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:17 volumiosalon go-librespot[3476]: go-librespot daemon starting... Nov 01 12:57:17 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:17+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:17 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:17+01:00" level=debug msg="app state loaded" Nov 01 12:57:17 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:17 volumiosalon go-librespot[3477]: time="2025-11-01T12:57: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 01 12:57:17 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:17+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:57:17 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:17+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:57:17 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:17+01:00" level=info msg="zeroconf server listening on port 41231" Nov 01 12:57:17 volumiosalon volumio[3346]: info: Loading plugin "outputs"... Nov 01 12:57:17 volumiosalon volumio[3346]: info: Loading plugin "albumart"... Nov 01 12:57:18 volumiosalon volumio[3346]: info: Plugin example_plugin is not enabled Nov 01 12:57:18 volumiosalon volumio[3346]: info: Loading plugin "inputs"... Nov 01 12:57:18 volumiosalon volumio[3346]: info: Loading plugin "updater_comm"... Nov 01 12:57:18 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:18+01:00" level=debug msg="obtained new client token: AADDGGSm/J7aSTxQI9atzd4CF9TEjP+XFs7iIkxQCKWHIzxIdu5iMCAYErm8wiP4pZguD3t6Bs6L3AwaV8g5KfPT53wHjavXR3iVr9YXqOFl1+x9X5dJeAzLZCzng/i7AnrH9IpkohZqS3LwE80IV0iiwoinKnT60hCoBk04pbMnDPSFQJJyODX4j5BJECOwgPa6+5uSkPfLCm3GsUPGNOTw0GihGkijwd5JemJyPi9gE0L4j4r+rTi/" Nov 01 12:57:18 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:18+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:18 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:18+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:18 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:18+01:00" level=debug msg="completed challenge" Nov 01 12:57:18 volumiosalon go-librespot[3477]: time="2025-11-01T12:57:18+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:57:18 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:18 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:18 volumiosalon volumio[3346]: info: Plugin mpdemulation is not enabled Nov 01 12:57:18 volumiosalon volumio[3346]: info: Loading plugin "rest_api"... Nov 01 12:57:18 volumiosalon volumio[3346]: info: Loading plugin "websocket"... Nov 01 12:57:18 volumiosalon volumio[3346]: info: Starting Socket.io Server version 1.7.4 Nov 01 12:57:18 volumiosalon volumio[3346]: info: Loading plugin "80s80s"... Nov 01 12:57:18 volumiosalon volumio[3346]: info: Applying required configuration parameters for plugin 80s80s Nov 01 12:57:18 volumiosalon volumio[3346]: info: [1761998238798] [80s80s] API delay: 30 Nov 01 12:57:18 volumiosalon volumio[3346]: info: Loading plugin "podcast"... Nov 01 12:57:19 volumiosalon volumio[3484]: Forking 3 albumart workers Nov 01 12:57:19 volumiosalon volumio[3346]: info: ControllerPodcast::constructor Nov 01 12:57:19 volumiosalon volumio[3346]: info: Loading plugin "Systeminfo"... Nov 01 12:57:20 volumiosalon volumio[3346]: info: Loading i18n strings for locale fr Nov 01 12:57:20 volumiosalon volumio[3346]: Updating browse sources language Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::initPlayerControls Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 01 12:57:20 volumiosalon volumio[3346]: Express server listening on port 3000 Nov 01 12:57:20 volumiosalon volumio[3346]: [Metrics] WebUI: 25s 566.47ms Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreStateMachine::resetVolumioState Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreStateMachine::getcurrentVolume Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioRetrievevolume Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreStateMachine::pushState Nov 01 12:57:20 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:57:20 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioPushState Nov 01 12:57:20 volumiosalon volumio[3346]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Nov 01 12:57:21 volumiosalon volumio[3346]: info: Volumio Network Manager: Network status updated: 1 Nov 01 12:57:21 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33. Nov 01 12:57:21 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:21 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:21 volumiosalon go-librespot[3546]: go-librespot daemon starting... Nov 01 12:57:21 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:21+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:21 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:21+01:00" level=debug msg="app state loaded" Nov 01 12:57:21 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:21 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:21 volumiosalon volumio[3346]: info: Reloading queue from file Nov 01 12:57:21 volumiosalon volumio[3346]: info: CoreStateMachine::setRepeat null single undefined Nov 01 12:57:21 volumiosalon volumio[3346]: info: CoreStateMachine::pushState Nov 01 12:57:21 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:21 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioPushState Nov 01 12:57:21 volumiosalon volumio[3346]: info: CoreStateMachine::setRandom true Nov 01 12:57:21 volumiosalon volumio[3346]: info: CoreStateMachine::pushState Nov 01 12:57:21 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:21 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 01 12:57:21 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioPushState Nov 01 12:57:21 volumiosalon volumio[3346]: info: Setting Device type: Raspberry PI Nov 01 12:57:21 volumiosalon volumio[3346]: info: Completed loading Core Plugins Nov 01 12:57:21 volumiosalon volumio[3346]: info: Preparing to generate the ALSA configuration file Nov 01 12:57:21 volumiosalon volumio[3495]: Starting albumart workers Nov 01 12:57:21 volumiosalon volumio[3494]: Starting albumart workers Nov 01 12:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+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:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+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:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+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:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+01:00" level=info msg="zeroconf server listening on port 40067" Nov 01 12:57:22 volumiosalon volumio[3496]: Starting albumart workers Nov 01 12:57:22 volumiosalon volumio[3346]: 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:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+01:00" level=debug msg="obtained new client token: AADkegYllSfo0IE83NKi/WlnzPVbI6KR3P6YwKyCRn9TjJRrYhhcY3q4qQvpgQ6Vwhn3srULLwevJY0lEzXZSxW1Z6hlCvsmP5v109zkYhJy9JCg9myrSzfYFhQz50LRtcwxQsl/tBozsaXtexWcZJGCHrNBQY6m9Nx3PKSQWse2jLV47kKyW4lLslXO8RT1VUU/mDzoRJ5DZaUvSiJakxsBY271wdWoqngLW4tk35P/pBPNLBI7k3pO" Nov 01 12:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:22 volumiosalon volumio[3346]: info: Discovery: adding 9080a7df-a081-4c2d-afb5-c9e324a7ab93 Nov 01 12:57:22 volumiosalon volumio[3346]: info: Discovery: Found device VolumioComble Nov 01 12:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+01:00" level=debug msg="completed challenge" Nov 01 12:57:22 volumiosalon go-librespot[3548]: time="2025-11-01T12:57:22+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:57:22 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:22 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:22 volumiosalon volumio[3346]: info: Discovery: Connecting to remote: 192.168.3.105 Nov 01 12:57:22 volumiosalon volumio[3346]: info: Asound.conf file unchanged, so no further update is needed Nov 01 12:57:22 volumiosalon volumio[3346]: info: Output device has changed, restarting MPD Nov 01 12:57:22 volumiosalon volumio[3346]: info: Output device has changed, restarting Shairport Sync Nov 01 12:57:22 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:22 volumiosalon sudo[3563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 01 12:57:22 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:22 volumiosalon sudo[3563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:22 volumiosalon sudo[3563]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:22 volumiosalon volumio[3346]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:57:22 volumiosalon volumio[3346]: info: ___________ START PLUGINS ___________ Nov 01 12:57:22 volumiosalon sudo[3565]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 01 12:57:22 volumiosalon sudo[3565]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:22 volumiosalon volumio[3346]: info: ControllerMpd::onStart: Initializing MPD Nov 01 12:57:22 volumiosalon volumio[3346]: info: Creating MPD Configuration file Nov 01 12:57:22 volumiosalon systemd[1]: Stopping mpd.service - Music Player Daemon... Nov 01 12:57:22 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:22 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:22 volumiosalon sudo[3573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 01 12:57:22 volumiosalon systemd[1]: mpd.service: Deactivated successfully. Nov 01 12:57:22 volumiosalon systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 01 12:57:22 volumiosalon systemd[1]: mpd.service: Consumed 6.106s CPU time. Nov 01 12:57:22 volumiosalon systemd[1]: mpd.socket: Deactivated successfully. Nov 01 12:57:23 volumiosalon systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 01 12:57:23 volumiosalon systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 01 12:57:23 volumiosalon sudo[3573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:23 volumiosalon sudo[3575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 01 12:57:23 volumiosalon sudo[3575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:23 volumiosalon volumio[3346]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:23 volumiosalon sudo[3573]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:23 volumiosalon systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 01 12:57:23 volumiosalon systemd[1]: Starting mpd.service - Music Player Daemon... Nov 01 12:57:23 volumiosalon volumio[3346]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:57:23 volumiosalon volumio[3346]: info: [1761998243150] CoreMusicLibrary::Adding element Last_100 Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:57:23 volumiosalon volumio[3346]: info: [1761998243159] CoreMusicLibrary::Adding element Webradio Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:23 volumiosalon systemd[1]: mpd.service: Deactivated successfully. Nov 01 12:57:23 volumiosalon systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 01 12:57:23 volumiosalon systemd[1]: mpd.socket: Deactivated successfully. Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:57:23 volumiosalon systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 01 12:57:23 volumiosalon systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 01 12:57:23 volumiosalon volumio[3346]: info: Initializing BBC Radios Nov 01 12:57:23 volumiosalon systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 01 12:57:23 volumiosalon systemd[1]: Starting mpd.service - Music Player Daemon... Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:57:23 volumiosalon volumio[3346]: info: [1761998243453] CoreMusicLibrary::Adding element Mixcloud Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:23 volumiosalon volumio[3346]: Cannot find translation for source Mixcloud Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:57:23 volumiosalon volumio[3346]: info: [1761998243481] CoreMusicLibrary::Adding element SoundCloud Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:23 volumiosalon volumio[3346]: Cannot find translation for source Mixcloud Nov 01 12:57:23 volumiosalon volumio[3346]: Cannot find translation for source SoundCloud Nov 01 12:57:23 volumiosalon volumio[3346]: info: Creating Spotify config file Nov 01 12:57:23 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:23 volumiosalon sudo[3594]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 01 12:57:23 volumiosalon sudo[3594]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Nov 01 12:57:23 volumiosalon sudo[3594]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:57:24 volumiosalon volumio[3346]: info: [1761998244327] CoreMusicLibrary::Adding element YouTube2 Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source Mixcloud Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source SoundCloud Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source YouTube2 Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:57:24 volumiosalon volumio[3346]: info: [1761998244344] CoreMusicLibrary::Adding element YouTube Music Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source Mixcloud Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source SoundCloud Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source YouTube2 Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source YouTube Music Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:57:24 volumiosalon volumio[3346]: info: [1761998244375] CoreMusicLibrary::Adding element 80s80s Radio Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source Mixcloud Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source SoundCloud Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source YouTube2 Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source YouTube Music Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source 80s80s Radio Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 01 12:57:24 volumiosalon volumio[3346]: info: [1761998244396] CoreMusicLibrary::Adding element Podcast Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source Mixcloud Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source SoundCloud Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source YouTube2 Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source YouTube Music Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source 80s80s Radio Nov 01 12:57:24 volumiosalon volumio[3346]: Cannot find translation for source Podcast Nov 01 12:57:24 volumiosalon volumio[3346]: info: Volumio Calling Home Nov 01 12:57:24 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:57:24] [connect] Successful connection Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:57:24 volumiosalon volumio[3346]: info: Discovery: Getting this device information Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:24 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:57:24 volumiosalon volumio[3346]: info: Discovery: adding 8e36d70c-1812-4fc0-9282-89074ef539a8 Nov 01 12:57:24 volumiosalon volumio[3346]: info: Discovery: Found device VolumioSalon Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:24 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:24 volumiosalon volumio[3346]: info: Discovery: this is already registered, 8e36d70c-1812-4fc0-9282-89074ef539a8 Nov 01 12:57:24 volumiosalon volumio[3346]: info: Discovery: Found device VolumioSalon Nov 01 12:57:24 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:24 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:25 volumiosalon volumio[3346]: 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:57:25 volumiosalon volumio[3346]: info: MPD Permissions set Nov 01 12:57:25 volumiosalon volumio[3346]: info: MPD Permissions set Nov 01 12:57:25 volumiosalon volumio[3346]: 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: 7 Nov 01 12:57:25 volumiosalon volumio[3346]: info: Volumio called home Nov 01 12:57:25 volumiosalon volumio[3346]: info: Spotify config file written Nov 01 12:57:25 volumiosalon sudo[3628]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 01 12:57:25 volumiosalon sudo[3628]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:25 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:25 volumiosalon volumio[3346]: info: Discovery: Connected to remote: 192.168.3.105 Nov 01 12:57:25 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:25 volumiosalon go-librespot[3630]: go-librespot daemon starting... Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon sudo[3628]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:25+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:25 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:25+01:00" level=debug msg="app state loaded" Nov 01 12:57:25 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 01 12:57:25 volumiosalon volumio[3346]: info: No need to fix Spotify hosts Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:57:25 volumiosalon volumio[3346]: info: Discovery: Getting this device information Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:25 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:25 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:57:25 volumiosalon volumio[3346]: info: An error occurred while refreshing Spotify Token Error: Bad Request Nov 01 12:57:25 volumiosalon volumio-remote-updater[466]: [2025-11-01 12:57:25] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761998244 101 Nov 01 12:57:25 volumiosalon volumio[3346]: 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: 8 Nov 01 12:57:25 volumiosalon volumio[3346]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Nov 01 12:57:25 volumiosalon volumio[3346]: info: Starting Shairport Sync Nov 01 12:57:25 volumiosalon volumio[3346]: info: Starting Shairport Sync Nov 01 12:57:25 volumiosalon volumio[3346]: info: Starting Shairport Sync Nov 01 12:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57: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:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57: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:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57: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:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:26+01:00" level=info msg="zeroconf server listening on port 44365" Nov 01 12:57:26 volumiosalon volumio[3346]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Nov 01 12:57:26 volumiosalon sudo[3649]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:57:26 volumiosalon sudo[3649]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:57:26 volumiosalon volumio[3346]: info: Discovery: Getting this device information Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:26 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:57:26 volumiosalon sudo[3651]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:57:26 volumiosalon sudo[3651]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:26 volumiosalon sudo[3653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 01 12:57:26 volumiosalon sudo[3653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:26+01:00" level=debug msg="obtained new client token: AAAt2EZ/wugmuQBDVsGUTW0H7RtPl7m2pOD9gbLhupYTMsC9fE3A2Hp3G0MsVm5kbjs67qZw4cYntK8OEIAkMn0Q/qA5YdtCHBy1TAVjOrgqpL5SwyYePkLMjfFgLDQLYX/OhpXsxEirUYQq4ERLnqfeqzaE81AG/qfvbrGGMQWXvA5HIawDpzPk7d9jsBrGLOdaYF62IAhNmPug2K7rkjM7alOgWnl10Y96O8dOCY1LQeCYdstBVrMx" Nov 01 12:57:26 volumiosalon volumio[3346]: 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: 10 Nov 01 12:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:26+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:26+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:26+01:00" level=debug msg="completed challenge" Nov 01 12:57:26 volumiosalon go-librespot[3631]: time="2025-11-01T12:57:26+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:57:26 volumiosalon volumio[3346]: 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: 11 Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:26 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Nov 01 12:57:26 volumiosalon systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 01 12:57:26 volumiosalon sudo[3653]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:26 volumiosalon sudo[3649]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:26 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:26 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:26 volumiosalon sudo[3651]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:26 volumiosalon volumio[3346]: info: Shairport-Sync Started Nov 01 12:57:26 volumiosalon volumio[3346]: Error adding Membership: Error: addMembership EINVAL Nov 01 12:57:26 volumiosalon volumio[3346]: info: Shairport-Sync Started Nov 01 12:57:26 volumiosalon volumio[3346]: info: Shairport-Sync Started Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:26 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:26 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:26 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:28 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:28 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:28 volumiosalon volumio[3346]: info: go-librespot daemon successfully initialized Nov 01 12:57:29 volumiosalon sudo[3674]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 01 12:57:29 volumiosalon sudo[3674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:29 volumiosalon sudo[3676]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 01 12:57:29 volumiosalon sudo[3676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:29 volumiosalon sudo[3674]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:29 volumiosalon sudo[3676]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:29 volumiosalon volumio[3346]: 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: 12 Nov 01 12:57:29 volumiosalon sudo[3682]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 01 12:57:29 volumiosalon sudo[3682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:29 volumiosalon sudo[3682]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:29 volumiosalon sudo[3684]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 01 12:57:29 volumiosalon sudo[3684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:29 volumiosalon sudo[3684]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:29 volumiosalon volumio[3346]: 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: 13 Nov 01 12:57:29 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34. Nov 01 12:57:29 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 01 12:57:29 volumiosalon mpd[3611]: 2025-11-01T12:57:29 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 01 12:57:29 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:29 volumiosalon go-librespot[3689]: go-librespot daemon starting... Nov 01 12:57:29 volumiosalon systemd[1]: Started mpd.service - Music Player Daemon. Nov 01 12:57:29 volumiosalon sudo[3565]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:29 volumiosalon sudo[3575]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:29 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:29+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:29 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:29+01:00" level=debug msg="app state loaded" Nov 01 12:57:29 volumiosalon volumio[3346]: info: Completed starting Core Plugins Nov 01 12:57:29 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:29 volumiosalon volumio[3346]: info: ------------------------------------------- Nov 01 12:57:29 volumiosalon volumio[3346]: info: ----- MyVolumio plugins startup ---- Nov 01 12:57:29 volumiosalon volumio[3346]: info: ------------------------------------------- Nov 01 12:57:29 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetVisibleSources Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:29 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 01 12:57:29 volumiosalon volumio[3346]: info: Received Get System Info Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:57:29 volumiosalon volumio[3346]: info: Discovery: Getting this device information Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:29 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:29 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:29 volumiosalon volumio[3346]: info: Listing playlists Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Nov 01 12:57:29 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 01 12:57:30 volumiosalon volumio[3346]: error: MPD error: The expression evaluated to a falsy value: Nov 01 12:57:30 volumiosalon volumio[3346]: assert.ok(self.idling) Nov 01 12:57:30 volumiosalon volumio[3346]: error: The expression evaluated to a falsy value: Nov 01 12:57:30 volumiosalon volumio[3346]: assert.ok(self.idling) Nov 01 12:57:30 volumiosalon volumio[3346]: info: MPD running with PID3611 Nov 01 12:57:30 volumiosalon volumio[3346]: ,establishing connection Nov 01 12:57:30 volumiosalon volumio[3346]: error: MPD error: The expression evaluated to a falsy value: Nov 01 12:57:30 volumiosalon volumio[3346]: assert.ok(self.idling) Nov 01 12:57:30 volumiosalon volumio[3346]: error: The expression evaluated to a falsy value: Nov 01 12:57:30 volumiosalon volumio[3346]: assert.ok(self.idling) Nov 01 12:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 01 12:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:30+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:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:30+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:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:30+01:00" level=info msg="zeroconf server listening on port 32937" Nov 01 12:57:30 volumiosalon volumio[3346]: error: updateQueue error: null Nov 01 12:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:30+01:00" level=debug msg="obtained new client token: AADBvxvi3HSKqMjDcbNrfYgJCy4GzFCiL7ZlcH/um3+LIawzHbytKBHYAMHJiiF7VhEuxvY/bfQGpCqtlUJAzh3pBu7/WEkRwzaK0vCsYfFsXfw75THmZRVrZdQ7YodsXX9birUiTaDvjP3kNbU2ps2QLmVbry6J3Xhk7zvAb9y4n3Xd9ofKMopE/daNAiBPar2o9MMDRb81clEn7d6r/P9q64nByJhvkZ78GFOByPMm+E8M7W7M09WN" Nov 01 12:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:30+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:30+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57:30+01:00" level=debug msg="completed challenge" Nov 01 12:57:30 volumiosalon go-librespot[3690]: time="2025-11-01T12:57: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:57:30 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:30 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:30 volumiosalon volumio[3346]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Nov 01 12:57:31 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 01 12:57:31 volumiosalon volumio[3346]: info: Received Get System Info Nov 01 12:57:31 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:57:31 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:57:31 volumiosalon volumio[3346]: info: Discovery: Getting this device information Nov 01 12:57:31 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:31 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:31 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:57:31 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Nov 01 12:57:31 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Nov 01 12:57:31 volumiosalon volumio[3346]: info: Initializing connection to go-librespot Websocket Nov 01 12:57:31 volumiosalon volumio[3346]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:57:32 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 01 12:57:32 volumiosalon volumio[3346]: info: Received Get System Info Nov 01 12:57:32 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 01 12:57:32 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 01 12:57:32 volumiosalon volumio[3346]: info: Discovery: Getting this device information Nov 01 12:57:32 volumiosalon volumio[3346]: info: CoreCommandRouter::volumioGetState Nov 01 12:57:32 volumiosalon volumio[3346]: info: CorePlayQueue::getTrack 0 Nov 01 12:57:32 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 01 12:57:32 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Nov 01 12:57:32 volumiosalon sudo[3716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 01 12:57:32 volumiosalon sudo[3716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:32 volumiosalon systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 01 12:57:32 volumiosalon systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 01 12:57:32 volumiosalon systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 01 12:57:32 volumiosalon systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 01 12:57:32 volumiosalon sudo[3716]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:32 volumiosalon mpd_monitor.sh[3718]: MPD Monitor Service: Starting MPD Monitor Service Nov 01 12:57:32 volumiosalon volumio[3346]: info: Successfully started MPD Monitor Nov 01 12:57:32 volumiosalon sudo[3722]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 01 12:57:32 volumiosalon sudo[3722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:32 volumiosalon systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 01 12:57:32 volumiosalon systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 01 12:57:32 volumiosalon systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 01 12:57:33 volumiosalon systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 01 12:57:33 volumiosalon sudo[3722]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:33 volumiosalon mpd_monitor.sh[3725]: MPD Monitor Service: Starting MPD Monitor Service Nov 01 12:57:33 volumiosalon volumio[3346]: info: Successfully started MPD Monitor Nov 01 12:57:33 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. Nov 01 12:57:33 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:33 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:33 volumiosalon go-librespot[3729]: go-librespot daemon starting... Nov 01 12:57:33 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:33+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:33 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:33+01:00" level=debug msg="app state loaded" Nov 01 12:57:33 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:33 volumiosalon go-librespot[3730]: time="2025-11-01T12:57: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 01 12:57:33 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:33+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:57:33 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:33+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:57:33 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:33+01:00" level=info msg="zeroconf server listening on port 41339" Nov 01 12:57:34 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:34+01:00" level=debug msg="obtained new client token: AACekCTfVTp9yDIGUvezzdmYNHba+M6z/JsxaoORVgieHOMUKmka7cyMowKt/IfK98OwKqjLgPZDJ6Zr/fw0hHFLMlTeX4cFsxV2mBtJZ3PE//8ZKGqtMq4DOEIPrxlWbJqO00jORBPjMi4IBzDwnKXUXFzkgWa36RU56x5YWTPAssLwK8a3eO3Yt7htiPsiSLJe64td9wFj3hGqNPXXgkZNd/RZJ9X/BUUERKGXGQpmzABqO4XEyii7" Nov 01 12:57:34 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:34+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:34 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:34+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:34 volumiosalon go-librespot[3730]: time="2025-11-01T12:57:34+01:00" level=debug msg="completed challenge" Nov 01 12:57:34 volumiosalon go-librespot[3730]: time="2025-11-01T12:57: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:57:34 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:34 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:34 volumiosalon volumio[3346]: info: Initializing connection to go-librespot Websocket Nov 01 12:57:34 volumiosalon volumio[3346]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:57:34 volumiosalon volumio[3346]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 01 12:57:35 volumiosalon volumio[3346]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Nov 01 12:57:36 volumiosalon volumio[3346]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 01 12:57:36 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 01 12:57:36 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 01 12:57:36 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 01 12:57:36 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Nov 01 12:57:36 volumiosalon volumio[3346]: info: Received Get System Version Nov 01 12:57:36 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 01 12:57:37 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. Nov 01 12:57:37 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:37 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:37 volumiosalon go-librespot[3757]: go-librespot daemon starting... Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=debug msg="app state loaded" Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57: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-gae2.spotify.com:80]" Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+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:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+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:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=info msg="zeroconf server listening on port 43165" Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=debug msg="obtained new client token: AAAzSh3xn1pqKDeGVv97voXLo+EnnQP7BfVrp3Q6z7CaDV1D81rBFS3JC5YWzYbdX0Hw0XCQlgFsrKn3vNZ+zEJRJA7pab20H+jWDotB88XjcjoDEj8cD+TMd+iqaVkQNHIn4Zs7vRTPL7yObJMfblMeN5AagASMMh+4J0T78OtUOmLCaZnBY2K5lxZDB78vRV5SqN+TFLMsGvUfa6OfOH3xa4s7JyQYKYHHxh2mh0OWzdyN0zbMtNOxmy4=" Nov 01 12:57:37 volumiosalon volumio[3346]: info: Initializing connection to go-librespot Websocket Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=debug msg="new websocket client" Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:37 volumiosalon volumio[3346]: info: Connection to go-librespot Websocket established Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57:37+01:00" level=debug msg="completed challenge" Nov 01 12:57:37 volumiosalon go-librespot[3758]: time="2025-11-01T12:57: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:57:37 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:37 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:37 volumiosalon volumio[3346]: info: Connection to go-librespot Websocket closed Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Nov 01 12:57:37 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Nov 01 12:57:37 volumiosalon volumio[3346]: info: Adding plugin bluetooth to MyMusic Plugins Nov 01 12:57:37 volumiosalon volumio[3346]: info: Adding plugin multiroom to MyMusic Plugins Nov 01 12:57:37 volumiosalon volumio[3346]: info: Adding plugin metavolumio to MyMusic Plugins Nov 01 12:57:37 volumiosalon volumio[3346]: info: Adding plugin cd_controller to MyMusic Plugins Nov 01 12:57:38 volumiosalon volumio[3346]: info: Adding plugin qobuzconnect to MyMusic Plugins Nov 01 12:57:38 volumiosalon volumio[3346]: info: Adding plugin smart_inputs to MyMusic Plugins Nov 01 12:57:38 volumiosalon volumio[3346]: info: Adding plugin tidalconnect to MyMusic Plugins Nov 01 12:57:38 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Nov 01 12:57:39 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Nov 01 12:57:39 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Nov 01 12:57:39 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:39 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 01 12:57:39 volumiosalon volumio[3346]: info: Starting MyVolumio Remote Streaming Endpoints Nov 01 12:57:39 volumiosalon volumio[3346]: info: MyVolumio login type: Token Nov 01 12:57:40 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Nov 01 12:57:40 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Nov 01 12:57:41 volumiosalon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37. Nov 01 12:57:41 volumiosalon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:41 volumiosalon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 01 12:57:41 volumiosalon go-librespot[3779]: go-librespot daemon starting... Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+01:00" level=info msg="running go-librespot 0.4.0" Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+01:00" level=debug msg="app state loaded" Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+01:00" level=info msg="api server listening on 127.0.0.1:9879" Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57: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-gew4.spotify.com:80]" Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+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:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+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:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+01:00" level=info msg="zeroconf server listening on port 44705" Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+01:00" level=debug msg="obtained new client token: AAClFXT1ICS5ydaSjj8ElITw2sUMZscIKHo5laSdSAjtu7/LKUVnTdCYV6q7bIHnR+++vyhtgsM/I+Qf3angai/gIJWI2tXg42x4Bx03hj4vMbNjANQGBAs/zNVeg4hfdNssuN3P+TkPznoyEHOWJ8xGDNq0z/wa4dsckEAYcMiio1f7VrbGwtm5zEm1CLBknpYAoknUtTuC2tnnvU47RJRxQHTQybdR3y4Cn99lIdQdyaHnCCeQz6cDZFc=" Nov 01 12:57:41 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Nov 01 12:57:41 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Nov 01 12:57:41 volumiosalon volumio[3346]: info: Streaming services startup Nov 01 12:57:41 volumiosalon volumio[3346]: info: Starting Streaming Daemon Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 01 12:57:41 volumiosalon sudo[3790]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 01 12:57:41 volumiosalon sudo[3790]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 01 12:57:41 volumiosalon volumio[3346]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+01:00" level=debug msg="completed keyexchange" Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57:41+01:00" level=debug msg="completed challenge" Nov 01 12:57:41 volumiosalon go-librespot[3780]: time="2025-11-01T12:57: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:57:41 volumiosalon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 01 12:57:41 volumiosalon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 01 12:57:41 volumiosalon sudo[3790]: pam_unix(sudo:session): session closed for user root Nov 01 12:57:41 volumiosalon volumio[3346]: info: Getting Spotify volume Nov 01 12:57:41 volumiosalon volumio[3346]: info: Initializing connection to go-librespot Websocket Nov 01 12:57:41 volumiosalon volumio[3346]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 01 12:57:42 volumiosalon volumio-remote-updater[466]: Test mode enabled Nov 01 12:57:42 volumiosalon volumio-remote-updater[466]: Alpha mode disabled Nov 01 12:57:42 volumiosalon volumio-remote-updater[466]: Alpha legacy test mode disabled Nov 01 12:57:42 volumiosalon volumio[3346]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 01 12:57:42 volumiosalon volumio[3346]: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 01 12:57:42 volumiosalon volumio[3346]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Nov 01 12:57:42 volumiosalon volumio[3346]: errno: -111, Nov 01 12:57:42 volumiosalon volumio[3346]: code: 'ECONNREFUSED', Nov 01 12:57:42 volumiosalon volumio[3346]: syscall: 'connect', Nov 01 12:57:42 volumiosalon volumio[3346]: address: '127.0.0.1', Nov 01 12:57:42 volumiosalon volumio[3346]: port: 9879, Nov 01 12:57:42 volumiosalon volumio[3346]: response: undefined Nov 01 12:57:42 volumiosalon volumio[3346]: } Nov 01 12:57:42 volumiosalon volumio[3346]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 01 12:57:43 volumiosalon sudo[3811]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-11-01 12:56' Nov 01 12:57:43 volumiosalon sudo[3811]: 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"