Dec 06 16:26:00 volumio volumio[2812]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 06 16:26:00 volumio volumio[2812]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 06 16:26:00 volumio volumio[2812]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:00 volumio volumio[2812]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:00 volumio volumio[2812]: info: Starting MyVolumio Remote Streaming Endpoints Dec 06 16:26:00 volumio volumio[2812]: info: MyVolumio login type: Token Dec 06 16:26:00 volumio volumio[2812]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 06 16:26:00 volumio volumio[2812]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 06 16:26:01 volumio volumio[2812]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 06 16:26:01 volumio volumio[2812]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 06 16:26:01 volumio volumio[2812]: info: Streaming services startup Dec 06 16:26:01 volumio volumio[2812]: info: Starting Streaming Daemon Dec 06 16:26:01 volumio sudo[3303]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:26:01 volumio sudo[3303]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:01 volumio volumio[2812]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 06 16:26:01 volumio sudo[3303]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:01 volumio volumio[2812]: error: Cannot start Volumio Streaming Daemon Dec 06 16:26:01 volumio volumio[2812]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 16:26:01 volumio volumio[2812]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 16:26:01 volumio volumio[2812]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 06 16:26:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 98. Dec 06 16:26:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:01 volumio go-librespot[3309]: go-librespot daemon starting... Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="app state loaded" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=info msg="zeroconf server listening on port 38841" Dec 06 16:26:02 volumio volumio[2812]: info: Initializing connection to go-librespot Websocket Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="new websocket client" Dec 06 16:26:02 volumio volumio[2812]: info: Connection to go-librespot Websocket established Dec 06 16:26:02 volumio volumio[2812]: info: MyVolumio token set successfully Dec 06 16:26:02 volumio volumio[2812]: info: MYVOLUMIO: Adding device Dec 06 16:26:02 volumio volumio[2812]: info: MYVOLUMIO: Evaluating Server Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="obtained new client token: AADGn687uBNYnf4HjsHfgcQcUBTJHu+9RBfoN3HjGA012ynsLRwEM5WdzOh/ZCtTWVjsYjAAtLqU67iG5SvUtHg6hCZvzCbFVnZAcROmjgM+Esx7H9hoR7eIznPvn6ted3flIGmZ9iAaytsdSYkY8gXOXfcTEGq8zj41CcGaypraI8h9m3UdZHZro+5mXpr6/oeNQ/SVIcV03ZebR0/A+2fiYMOJ+uDP19GDrqUC6pVg4Fx2vo0gH4CGOQ==" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:443, retrying with a different AP" error="dial tcp 104.154.127.247:443: connect: connection refused" Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="connected to ap-guc3.spotify.com:80" Dec 06 16:26:02 volumio volumio[2812]: info: MyVolumio status changed Dec 06 16:26:02 volumio volumio[2812]: info: Streaming services startup Dec 06 16:26:02 volumio volumio[2812]: info: Starting Streaming Daemon Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:02 volumio volumio[2812]: info: Removing browser output: myVolumio user plan is not superstar Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=debug msg="completed challenge" Dec 06 16:26:02 volumio volumio[2812]: info: Removing audio output: Dec 06 16:26:02 volumio volumio[2812]: info: Stoppping Tunnel 1 Dec 06 16:26:02 volumio sudo[3338]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:26:02 volumio sudo[3338]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:02 volumio sudo[3340]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 06 16:26:02 volumio sudo[3340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:02 volumio go-librespot[3310]: time="2025-12-06T16:26:02-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:02 volumio volumio[2812]: info: Connection to go-librespot Websocket closed Dec 06 16:26:02 volumio sudo[3338]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:02 volumio volumio[2812]: error: Cannot start Volumio Streaming Daemon Dec 06 16:26:02 volumio volumio[2812]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 16:26:02 volumio volumio[2812]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 16:26:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:02 volumio sudo[3340]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:02 volumio volumio[2812]: info: Remote SSH Stopped Dec 06 16:26:02 volumio volumio[2812]: info: Setting Geolocation for MyVolumio to us1 Dec 06 16:26:02 volumio volumio[2812]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:02 volumio volumio[2812]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:02 volumio volumio[2812]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:03 volumio volumio[2812]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 06 16:26:03 volumio volumio[2812]: info: Updating MyVolumio device info Dec 06 16:26:03 volumio volumio[2812]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:03 volumio volumio[2812]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:03 volumio volumio[2812]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:05 volumio volumio[2812]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 06 16:26:05 volumio volumio[2812]: info: Getting Spotify volume Dec 06 16:26:05 volumio volumio[2812]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:26:05 volumio volumio[2812]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:26:05 volumio volumio[2812]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 06 16:26:05 volumio volumio[2812]: errno: -111, Dec 06 16:26:05 volumio volumio[2812]: code: 'ECONNREFUSED', Dec 06 16:26:05 volumio volumio[2812]: syscall: 'connect', Dec 06 16:26:05 volumio volumio[2812]: address: '127.0.0.1', Dec 06 16:26:05 volumio volumio[2812]: port: 9879, Dec 06 16:26:05 volumio volumio[2812]: response: undefined Dec 06 16:26:05 volumio volumio[2812]: } Dec 06 16:26:05 volumio volumio[2812]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:26:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 99. Dec 06 16:26:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:05 volumio go-librespot[3355]: go-librespot daemon starting... Dec 06 16:26:05 volumio go-librespot[3356]: time="2025-12-06T16:26:05-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:05 volumio go-librespot[3356]: time="2025-12-06T16:26:05-06:00" level=debug msg="app state loaded" Dec 06 16:26:05 volumio go-librespot[3356]: time="2025-12-06T16:26:05-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:05 volumio go-librespot[3356]: time="2025-12-06T16:26:05-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=info msg="zeroconf server listening on port 46577" Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=debug msg="obtained new client token: AAAjKdjG1x72glaG7nL+GQwLtnrKoTXvHqNuEArhOKpdfNoSSyLTo0MvK8VPeYK89tFrc95/RkEmeijyrx5RB1lvrP7x5mCoZVQGNSabpnYRM9SouL8GZogoT1PajZ95pBz8eA41SiJDcc4D2Siy3MSsITPSzRU4eL/35e4zNLT1T2ceH4Pyl9xKIty61GIbOtgtRD9Yc4euXiV+5iizQO492bN0jBcs69B++P5AZSH2uMcmliurYlA=" Dec 06 16:26:06 volumio sudo[3366]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 16:25' Dec 06 16:26:06 volumio sudo[3366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=debug msg="completed challenge" Dec 06 16:26:06 volumio go-librespot[3356]: time="2025-12-06T16:26:06-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:06 volumio sudo[3366]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:06 volumio volumio-remote-updater[2353]: [2025-12-06 16:26:06] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 06 16:26:06 volumio volumio-remote-updater[2353]: [2025-12-06 16:26:06] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 06 16:26:06 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:06 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 06 16:26:06 volumio systemd[1]: volumio.service: Consumed 45.848s CPU time. Dec 06 16:26:06 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 06 16:26:06 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 06 16:26:06 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 21165. Dec 06 16:26:06 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 06 16:26:06 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 06 16:26:06 volumio systemd[1]: volumio.service: Consumed 45.848s CPU time. Dec 06 16:26:06 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 06 16:26:06 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 06 16:26:08 volumio volumio[3379]: info: ------------------------------------------- Dec 06 16:26:08 volumio volumio[3379]: info: ----- Volumio3 ---- Dec 06 16:26:08 volumio volumio[3379]: info: ------------------------------------------- Dec 06 16:26:08 volumio volumio[3379]: info: ----- System startup ---- Dec 06 16:26:08 volumio volumio[3379]: info: ------------------------------------------- Dec 06 16:26:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Dec 06 16:26:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:09 volumio volumio[3379]: info: MYVOLUMIO Environment detected Dec 06 16:26:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:09 volumio go-librespot[3400]: go-librespot daemon starting... Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=debug msg="app state loaded" Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:09 volumio volumio[3379]: info: Plugin folders cleanup Dec 06 16:26:09 volumio volumio[3379]: info: Scanning into folder /volumio/app/plugins/ Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category audio_interface Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category miscellanea Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category music_service Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category plugins.json Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category system_controller Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category user_interface Dec 06 16:26:09 volumio volumio[3379]: info: Scanning into folder /data/plugins/ Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category audio_interface Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category music_service Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category system_controller Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category system_hardware Dec 06 16:26:09 volumio volumio[3379]: info: Scanning category user_interface Dec 06 16:26:09 volumio volumio[3379]: info: Plugin folders cleanup completed Dec 06 16:26:09 volumio volumio[3379]: info: ------------------------------------------- Dec 06 16:26:09 volumio volumio[3379]: info: ----- Core plugins startup ---- Dec 06 16:26:09 volumio volumio[3379]: info: ------------------------------------------- Dec 06 16:26:09 volumio volumio[3379]: info: Loading plugins from folder /volumio/app/plugins/ Dec 06 16:26:09 volumio volumio[3379]: info: Adding plugin upnp to MyMusic Plugins Dec 06 16:26:09 volumio volumio[3379]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 06 16:26:09 volumio volumio[3379]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 06 16:26:09 volumio volumio[3379]: info: Loading plugins from folder /data/plugins/ Dec 06 16:26:09 volumio volumio[3379]: info: Loading plugin "system"... Dec 06 16:26:09 volumio volumio[3379]: info: Loading plugin "appearance"... Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=info msg="zeroconf server listening on port 32859" Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=debug msg="obtained new client token: AADvIXT6B8CfRPAkwow4+YiBQJp23u3Udy1l2i/FbjJGuFbXu3NfHV5MY4u3wqqPi5fkLl3kSqh43JXb1n+XKP6+d+0f70LfhuBOk9lz4u8gTlHxpp/v/lapoQYRWl1V6/Hr1B1kzxoEo6s+NbGxn+6dfhN1jnwozgdJZQrRIHyOJNSN4oaaN5KR3EiycMr9x/azztxtygikW0f05mJOw0tUR1DDPt6zd5oCGNlowvtAd5FSzPEyGo0mtA==" Dec 06 16:26:09 volumio go-librespot[3404]: time="2025-12-06T16:26:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:10 volumio go-librespot[3404]: time="2025-12-06T16:26:10-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:10 volumio go-librespot[3404]: time="2025-12-06T16:26:10-06:00" level=debug msg="completed challenge" Dec 06 16:26:10 volumio go-librespot[3404]: time="2025-12-06T16:26:10-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:10 volumio volumio[3379]: info: Loading plugin "network"... Dec 06 16:26:10 volumio volumio[3379]: info: Refreshing Cached IP Addresses Dec 06 16:26:10 volumio sudo[3415]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 16:26:10 volumio sudo[3415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:10 volumio sudo[3417]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 16:26:10 volumio sudo[3417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:10 volumio sudo[3415]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:10 volumio volumio[3379]: info: Loading plugin "services"... Dec 06 16:26:10 volumio sudo[3417]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:10 volumio volumio[3379]: info: Loading plugin "alsa_controller"... Dec 06 16:26:10 volumio sudo[3429]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 06 16:26:10 volumio sudo[3429]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:10 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:26:10 volumio volumio[3379]: info: Loading plugin "wizard"... Dec 06 16:26:10 volumio volumio[3379]: info: Loading plugin "networkfs"... Dec 06 16:26:10 volumio volumio[3379]: info: Starting Udev Watcher for removable devices Dec 06 16:26:10 volumio volumio[3379]: info: Ignoring mount for partition: boot Dec 06 16:26:10 volumio volumio[3379]: info: Ignoring mount for partition: volumio Dec 06 16:26:10 volumio volumio[3379]: info: Ignoring mount for partition: volumio_data Dec 06 16:26:11 volumio volumio[3379]: info: Mounting Device Wikipedia Dec 06 16:26:11 volumio sudo[3454]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 06 16:26:11 volumio sudo[3454]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:11 volumio sudo[3454]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:11 volumio volumio[3379]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 06 16:26:11 volumio volumio[3379]: dmesg(1) may have more information after failed mount system call. Dec 06 16:26:11 volumio volumio[3379]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 06 16:26:11 volumio volumio[3379]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 06 16:26:11 volumio volumio[3379]: dmesg(1) may have more information after failed mount system call. Dec 06 16:26:11 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:26:11 volumio volumio[3379]: info: Loading plugin "volumio_command_line_client"... Dec 06 16:26:11 volumio volumio[3379]: info: Loading plugin "upnp"... Dec 06 16:26:11 volumio volumio[3379]: info: [1765059971074] Starting Upmpd Daemon Dec 06 16:26:11 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:26:11 volumio volumio[3379]: info: Loading plugin "my_music"... Dec 06 16:26:11 volumio volumio[3379]: info: Loading plugin "mpd"... Dec 06 16:26:11 volumio volumio[3379]: info: Loading plugin "upnp_browser"... Dec 06 16:26:11 volumio sudo[3429]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:11 volumio volumio-remote-updater[2353]: [2025-12-06 16:26:11] [connect] Successful connection Dec 06 16:26:12 volumio volumio[3379]: info: Loading plugin "alarm-clock"... Dec 06 16:26:13 volumio volumio[3379]: info: Loading plugin "airplay_emulation"... Dec 06 16:26:13 volumio volumio[3379]: info: Starting Shairport Sync Dec 06 16:26:13 volumio volumio[3379]: info: Loading plugin "last_100"... Dec 06 16:26:13 volumio volumio[3379]: info: Loading plugin "webradio"... Dec 06 16:26:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Dec 06 16:26:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:13 volumio volumio[3379]: info: Loading plugin "i2s_dacs"... Dec 06 16:26:13 volumio volumio[3379]: info: I2S DAC not set, start Auto-detection Dec 06 16:26:13 volumio volumio[3379]: info: Loading plugin "volumiodiscovery"... Dec 06 16:26:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:13 volumio go-librespot[3460]: go-librespot daemon starting... Dec 06 16:26:13 volumio volumio[3379]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 06 16:26:13 volumio volumio[3379]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:26:13 volumio volumio[3379]: *** WARNING *** For more information see Dec 06 16:26:13 volumio volumio[3379]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 06 16:26:13 volumio volumio[3379]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:26:13 volumio volumio[3379]: *** WARNING *** For more information see Dec 06 16:26:13 volumio node[3379]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 06 16:26:13 volumio node[3379]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:26:13 volumio node[3379]: *** WARNING *** For more information see Dec 06 16:26:13 volumio node[3379]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 06 16:26:13 volumio node[3379]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:26:13 volumio node[3379]: *** WARNING *** For more information see Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="app state loaded" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:13 volumio volumio[3379]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:13 volumio volumio[3379]: info: Discovery: Started advertising with name: Volumio Dec 06 16:26:13 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:26:13 volumio volumio[3379]: info: Loading plugin "bandcamp"... Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=info msg="zeroconf server listening on port 43441" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="obtained new client token: AAA6bi4ifHBLcCbzSgC5iuug/AHIg4lAdTkkbNMFslnSywfEYDHZcI9+bCtd6KqDF/dm2fJdQAHqtjpZIqInK6AT6og8Qfo958ppfo0zZG+Jjbp7y4/2ZGbjPMNXX1n0zuzWk4zs190MzsX85Ikm5Ahhl2s58mawDWM1+OcliaGTtsr2uML7IqaNEnpkQaPlmEM3xCqj5rQ/oEduCScqQOikwje9EyEuutuwNna0HtDnTyAbnQNBHfThlw==" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=debug msg="completed challenge" Dec 06 16:26:13 volumio go-librespot[3461]: time="2025-12-06T16:26:13-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:14 volumio volumio[3379]: info: Plugin calmradio is not enabled Dec 06 16:26:14 volumio volumio[3379]: info: Loading plugin "soundcloud"... Dec 06 16:26:14 volumio volumio[3379]: info: Loading plugin "spop"... Dec 06 16:26:15 volumio volumio[3379]: info: Loading plugin "squeezelite_mc"... Dec 06 16:26:16 volumio volumio[3379]: info: Loading plugin "youtube2"... Dec 06 16:26:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Dec 06 16:26:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:17 volumio go-librespot[3470]: go-librespot daemon starting... Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="app state loaded" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=info msg="zeroconf server listening on port 43161" Dec 06 16:26:17 volumio volumio[3379]: info: Loading plugin "ytcr"... Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="obtained new client token: AAAnLaPfLYaUCdkesreFkNQwanjm+ewuyR3kxpcanZcl0JrZ0Rrizi6X7E+Y7Sq7e6J6+PfDJj/+Y0KqzJRCAtF11m6352dBeSM4pYh/Ky5mao2Ft0mLzoNw6286NBZoV1o7qTONY/mMJXu3wNtVSK7uzXTUrgEdFtng+N3tOzDBdi8AW+xzdh4hzlFQ2AhbJfv16nSXKi8c4iEHnvDNCx3HC6WrbpS+/evpTBb+dboTMbcTkRGIzddBNw==" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=debug msg="completed challenge" Dec 06 16:26:17 volumio go-librespot[3471]: time="2025-12-06T16:26:17-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:18 volumio volumio[3379]: info: Loading plugin "ytmusic"... Dec 06 16:26:19 volumio volumio[3379]: info: Plugin now_playing is not enabled Dec 06 16:26:19 volumio volumio[3379]: info: Loading plugin "outputs"... Dec 06 16:26:19 volumio volumio[3379]: info: Loading plugin "albumart"... Dec 06 16:26:19 volumio volumio[3379]: info: Plugin example_plugin is not enabled Dec 06 16:26:19 volumio volumio[3379]: info: Loading plugin "inputs"... Dec 06 16:26:19 volumio volumio[3379]: info: Loading plugin "updater_comm"... Dec 06 16:26:19 volumio volumio[3379]: info: Plugin mpdemulation is not enabled Dec 06 16:26:19 volumio volumio[3379]: info: Loading plugin "rest_api"... Dec 06 16:26:19 volumio volumio[3379]: info: Loading plugin "websocket"... Dec 06 16:26:19 volumio volumio[3379]: info: Starting Socket.io Server version 1.7.4 Dec 06 16:26:19 volumio volumio[3379]: info: Plugin fusiondsp is not enabled Dec 06 16:26:19 volumio volumio[3379]: info: Plugin mpdoutput is not enabled Dec 06 16:26:19 volumio volumio[3379]: info: Plugin RoonBridge is not enabled Dec 06 16:26:19 volumio volumio[3379]: info: Loading plugin "podcast"... Dec 06 16:26:19 volumio volumio[3379]: info: ControllerPodcast::constructor Dec 06 16:26:19 volumio volumio[3379]: info: Loading plugin "volusonic"... Dec 06 16:26:19 volumio volumio[3478]: Forking 3 albumart workers Dec 06 16:26:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Dec 06 16:26:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:20 volumio go-librespot[3518]: go-librespot daemon starting... Dec 06 16:26:20 volumio go-librespot[3519]: time="2025-12-06T16:26:20-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:20 volumio go-librespot[3519]: time="2025-12-06T16:26:20-06:00" level=debug msg="app state loaded" Dec 06 16:26:20 volumio go-librespot[3519]: time="2025-12-06T16:26:20-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:20 volumio go-librespot[3519]: time="2025-12-06T16:26:20-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=info msg="zeroconf server listening on port 46045" Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=debug msg="obtained new client token: AACUeKm1zku0C9WtJzwNurUcj+HcTLRLVIM3M+RAI2o/Vj24MoBKVdg34DwuGNYfDExucHIu0BtX4UwLpvuiyCRD0yIcbCgG5hcG2lgG4THXWGURhkLklTfeSLc1LnFRsgx3xI+UfugdaKkZgUtaqvWIfi82NZ349YzmY7gA+/h01z7gTbbwOUO228KEkE8dxdeN4Vd751MBNsdeB/JjoWRsUIGQlQyu6ufj7hYXu9hl4CbFnoNRkLB2vA==" Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=debug msg="completed challenge" Dec 06 16:26:21 volumio volumio[3379]: info: Applying required configuration parameters for plugin volusonic Dec 06 16:26:21 volumio volumio[3379]: info: Loading plugin "backup_restore"... Dec 06 16:26:21 volumio go-librespot[3519]: time="2025-12-06T16:26:21-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:21 volumio volumio[3490]: Starting albumart workers Dec 06 16:26:21 volumio volumio[3488]: Starting albumart workers Dec 06 16:26:21 volumio volumio[3489]: Starting albumart workers Dec 06 16:26:21 volumio volumio[3379]: info: Applying required configuration parameters for plugin backup_restore Dec 06 16:26:21 volumio volumio[3379]: info: Plugin rpi_eeprom_config is not enabled Dec 06 16:26:21 volumio volumio[3379]: info: Plugin rpi_eeprom_updater is not enabled Dec 06 16:26:21 volumio volumio[3379]: info: Loading plugin "scheduledrestart"... Dec 06 16:26:22 volumio volumio[3379]: info: Applying required configuration parameters for plugin scheduledrestart Dec 06 16:26:22 volumio volumio[3379]: info: Plugin Bluetoothremote is not enabled Dec 06 16:26:22 volumio volumio[3379]: info: Plugin music_services_shield is not enabled Dec 06 16:26:22 volumio volumio[3379]: info: Loading plugin "Systeminfo"... Dec 06 16:26:22 volumio volumio[3379]: info: Plugin peppymeterbasic is not enabled Dec 06 16:26:22 volumio volumio[3379]: info: Loading plugin "peppyspectrum"... Dec 06 16:26:22 volumio volumio[3379]: info: Loading i18n strings for locale en Dec 06 16:26:22 volumio volumio[3379]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 06 16:26:22 volumio volumio[3379]: Updating browse sources language Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::initPlayerControls Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:26:22 volumio volumio[3379]: Express server listening on port 3000 Dec 06 16:26:22 volumio volumio[3379]: [Metrics] WebUI: 14s 771.39ms Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::resetVolumioState Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::getcurrentVolume Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:23 volumio sudo[3564]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 16:26:23 volumio sudo[3564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:23 volumio sudo[3564]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:23 volumio sudo[3566]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 16:26:23 volumio sudo[3566]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:23 volumio sudo[3566]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:23 volumio volumio[3379]: info: Volumio Network Manager: Network status updated: 1 Dec 06 16:26:23 volumio volumio[3379]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::pushState Dec 06 16:26:23 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioPushState Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::updateTrackBlock Dec 06 16:26:23 volumio volumio[3379]: info: CorePlayQueue::getTrackBlock Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:26:23 volumio volumio[3379]: info: Reloading queue from file Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::setRepeat null single undefined Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::pushState Dec 06 16:26:23 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioPushState Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::setRandom null Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::pushState Dec 06 16:26:23 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioPushState Dec 06 16:26:23 volumio volumio[3379]: info: Setting Device type: Raspberry PI Dec 06 16:26:23 volumio volumio[3379]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:26:23 volumio volumio[3379]: info: CoreStateMachine::pushState Dec 06 16:26:23 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioPushState Dec 06 16:26:23 volumio volumio[3379]: info: Completed loading Core Plugins Dec 06 16:26:23 volumio volumio[3379]: info: Preparing to generate the ALSA configuration file Dec 06 16:26:23 volumio sudo[3579]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 06 16:26:23 volumio sudo[3579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:23 volumio volumio[3379]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 06 16:26:23 volumio volumio[3379]: info: Discovery: Found device Volumio Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioGetState Dec 06 16:26:23 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:23 volumio volumio[3379]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 06 16:26:23 volumio volumio[3379]: info: Discovery: Found device Volumio Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioGetState Dec 06 16:26:23 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:23 volumio volumio[3379]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 06 16:26:23 volumio sudo[3579]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:23 volumio volumio[3379]: info: Reading ALSA contributions from plugins. Dec 06 16:26:23 volumio volumio[3379]: info: Upmpdcli Daemon Started Dec 06 16:26:23 volumio volumio[3379]: info: Asound.conf file unchanged, so no further update is needed Dec 06 16:26:23 volumio volumio[3379]: info: Output device has changed, restarting MPD Dec 06 16:26:23 volumio volumio[3379]: info: Output device has changed, restarting Shairport Sync Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:23 volumio sudo[3582]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:26:23 volumio sudo[3582]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:23 volumio sudo[3584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:26:23 volumio sudo[3584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:23 volumio sudo[3582]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:23 volumio volumio[3379]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:26:23 volumio volumio[3379]: info: ___________ START PLUGINS ___________ Dec 06 16:26:23 volumio volumio[3379]: info: ControllerMpd::onStart: Initializing MPD Dec 06 16:26:23 volumio volumio[3379]: info: Creating MPD Configuration file Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:23 volumio volumio[3379]: info: [1765059983532] CoreMusicLibrary::Adding element Media Servers Dec 06 16:26:23 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:23 volumio sudo[3592]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:26:23 volumio sudo[3592]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:23 volumio sudo[3592]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:23 volumio sudo[3594]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:26:23 volumio sudo[3594]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:23 volumio volumio[3379]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:23 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 06 16:26:23 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 16:26:23 volumio systemd[1]: mpd.service: Consumed 4.589s CPU time. Dec 06 16:26:23 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 06 16:26:23 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 16:26:23 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 16:26:23 volumio volumio[3379]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:23 volumio volumio[3379]: info: [1765059983665] CoreMusicLibrary::Adding element Last_100 Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:23 volumio volumio[3379]: info: [1765059983669] CoreMusicLibrary::Adding element Webradio Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:26:23 volumio volumio[3379]: info: Initializing BBC Radios Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:23 volumio volumio[3379]: info: [1765059983740] CoreMusicLibrary::Adding element Bandcamp Discover Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:23 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:23 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:23 volumio volumio[3379]: info: [1765059983752] CoreMusicLibrary::Adding element SoundCloud Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:23 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:23 volumio volumio[3379]: Cannot find translation for source SoundCloud Dec 06 16:26:23 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 16:26:23 volumio volumio[3379]: info: Creating Spotify config file Dec 06 16:26:23 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:23 volumio sudo[3619]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 16:26:23 volumio sudo[3619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 16:26:23 volumio sudo[3619]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:24 volumio volumio-remote-updater[2353]: [2025-12-06 16:26:23] [connect] Successful connection Dec 06 16:26:24 volumio volumio[3379]: info: [squeezelite_mc] Starting proxy server... Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:24 volumio volumio[3379]: info: [1765059984114] CoreMusicLibrary::Adding element YouTube2 Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source SoundCloud Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube2 Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:24 volumio volumio[3379]: info: [1765059984141] CoreMusicLibrary::Adding element YouTube Music Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source SoundCloud Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube2 Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube Music Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:24 volumio volumio[3379]: info: [1765059984153] CoreMusicLibrary::Adding element Podcast Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source SoundCloud Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube2 Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube Music Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Podcast Dec 06 16:26:24 volumio volumio[3379]: info: Loading i18n strings for locale en Dec 06 16:26:24 volumio volumio[3379]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 06 16:26:24 volumio volumio[3379]: Updating browse sources language Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source SoundCloud Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube2 Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube Music Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Podcast Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source SoundCloud Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube2 Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube Music Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Podcast Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:24 volumio volumio[3379]: info: [1765059984201] CoreMusicLibrary::Adding element Volusonic Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source SoundCloud Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube2 Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source YouTube Music Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Podcast Dec 06 16:26:24 volumio volumio[3379]: Cannot find translation for source Volusonic Dec 06 16:26:24 volumio volumio[3379]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 06 16:26:24 volumio volumio[3379]: info: Volumio Calling Home Dec 06 16:26:24 volumio volumio[3379]: info: [squeezelite_mc] Proxy server started on port 43453 Dec 06 16:26:24 volumio volumio[3379]: info: Preparing to generate the ALSA configuration file Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:26:24 volumio volumio[3379]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 06 16:26:24 volumio volumio[3379]: info: Reading ALSA contributions from plugins. Dec 06 16:26:24 volumio volumio[3379]: info: MPD Permissions set Dec 06 16:26:24 volumio volumio[3379]: info: MPD Permissions set Dec 06 16:26:24 volumio volumio-remote-updater[2353]: [2025-12-06 16:26:24] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765059983 101 Dec 06 16:26:24 volumio volumio[3379]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 06 16:26:24 volumio volumio[3379]: info: Spotify config file written Dec 06 16:26:24 volumio sudo[3628]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 06 16:26:24 volumio sudo[3628]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Dec 06 16:26:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:24 volumio volumio[3379]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 06 16:26:24 volumio volumio[3379]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:26:24 volumio volumio[3379]: info: CoreStateMachine::pushState Dec 06 16:26:24 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::volumioPushState Dec 06 16:26:24 volumio volumio[3379]: info: [squeezelite_mc] Server discovery started Dec 06 16:26:24 volumio volumio[3379]: info: [squeezelite_mc] Player finder started Dec 06 16:26:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:26:24 volumio go-librespot[3630]: go-librespot daemon starting... Dec 06 16:26:24 volumio volumio[3379]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 06 16:26:24 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:24 volumio go-librespot[3641]: go-librespot daemon starting... Dec 06 16:26:24 volumio sudo[3628]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio go-librespot[3645]: time="2025-12-06T16:26:24-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:24 volumio go-librespot[3645]: time="2025-12-06T16:26:24-06:00" level=debug msg="app state loaded" Dec 06 16:26:24 volumio go-librespot[3645]: time="2025-12-06T16:26:24-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:24 volumio go-librespot[3645]: time="2025-12-06T16:26:24-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:24 volumio volumio[3379]: info: No need to fix Spotify hosts Dec 06 16:26:24 volumio volumio[3379]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 06 16:26:24 volumio volumio[3379]: info: Volumio called home Dec 06 16:26:25 volumio volumio[3379]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"} Dec 06 16:26:25 volumio volumio[3379]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 06 16:26:25 volumio volumio[3379]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:25 volumio volumio[3379]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=info msg="zeroconf server listening on port 40319" Dec 06 16:26:25 volumio volumio[3379]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 06 16:26:25 volumio volumio[3379]: SPOTIFY: BQCxoxN7dkRWGxxH1FNE_N1Wb28o3sjZ5fJFa1Ev5ZiHShjoTITaFkyjs_vy4K84Sg5DMew3Qzcc2gCMOSwB8sgKbSs2u9PFMDFfpfAT7-92GdrIFLy8MB1fwQl4i81ICdTD6-I8tDbVyyO1DDh7ViDbmFb1f0zlEPqt-hThxRyyZ0KB0h0e1dSfKy7FMaPqYvmWLracQwp4UMG4Ms0wuEd4Kpwucv0-hZdPC44 Dec 06 16:26:25 volumio volumio[3379]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 06 16:26:25 volumio volumio[3379]: info: New Spotify access token = BQCxoxN7dkRWGxxH1FNE_N1Wb28o3sjZ5fJFa1Ev5ZiHShjoTITaFkyjs_vy4K84Sg5DMew3Qzcc2gCMOSwB8sgKbSs2u9PFMDFfpfAT7-92GdrIFLy8MB1fwQl4i81ICdTD6-I8tDbVyyO1DDh7ViDbmFb1f0zlEPqt-hThxRyyZ0KB0h0e1dSfKy7FMaPqYvmWLracQwp4UMG4Ms0wuEd4Kpwucv0-hZdPC44 Dec 06 16:26:25 volumio volumio[3379]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 06 16:26:25 volumio volumio[3379]: info: Starting Shairport Sync Dec 06 16:26:25 volumio volumio[3379]: info: Starting Shairport Sync Dec 06 16:26:25 volumio volumio[3379]: info: Starting Shairport Sync Dec 06 16:26:25 volumio sudo[3662]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:26:25 volumio sudo[3662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=debug msg="obtained new client token: AAB7Qvz5UXLrYlSbAQbeOQmhifSm9gIT9rciR13n0CHt5ekiJO13oVzQTMtnrALyH+Okpy/P1RRx5SAPgqidNZ5g0Y550Hj5PZdaRqHLZ//Ar9CaxrbehyiQpr9NEWLmJS+/xJl3pdUisX+OX6nVppR4kjt0NdcScrDxHknXoDmbuuu7yQm8bifWtisSp8QlBY2/dacL/kBDC2lVS3p6jWcpP10tmtQdJpv0e17Ny4fZtIOKypWJC0c=" Dec 06 16:26:25 volumio sudo[3664]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:26:25 volumio sudo[3664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:26:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:26:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:26:25 volumio sudo[3667]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:26:25 volumio systemd[1]: shairport-sync.service: Consumed 1.847s CPU time. Dec 06 16:26:25 volumio sudo[3659]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 06 16:26:25 volumio sudo[3659]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio sudo[3667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio sudo[3659]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=debug msg="completed challenge" Dec 06 16:26:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:26:25 volumio sudo[3662]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:25 volumio go-librespot[3645]: time="2025-12-06T16:26:25-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:25 volumio volumio[3379]: info: Asound.conf file unchanged, so no further update is needed Dec 06 16:26:25 volumio volumio[3379]: info: Output device has changed, restarting MPD Dec 06 16:26:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:26:25 volumio volumio[3379]: info: Output device has changed, restarting Shairport Sync Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:26:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:26:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:26:25 volumio sudo[3664]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:25 volumio sudo[3667]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:25 volumio volumio[3379]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:26:25 volumio sudo[3673]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:26:25 volumio sudo[3673]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio sudo[3673]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:25 volumio sudo[3675]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:26:25 volumio sudo[3675]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 06 16:26:25 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 16:26:25 volumio systemd[1]: mpd.service: Consumed 1.636s CPU time. Dec 06 16:26:25 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 06 16:26:25 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 16:26:25 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 16:26:25 volumio volumio[3379]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 06 16:26:25 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 16:26:25 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 16:26:25 volumio sudo[3704]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 06 16:26:25 volumio sudo[3704]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio sudo[3704]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:25 volumio volumio[3379]: info: MPD Permissions set Dec 06 16:26:25 volumio volumio[3379]: info: Shairport-Sync Started Dec 06 16:26:25 volumio volumio[3379]: Error adding Membership: Error: addMembership EINVAL Dec 06 16:26:25 volumio volumio[3379]: info: Shairport-Sync Started Dec 06 16:26:25 volumio volumio[3379]: info: Shairport-Sync Started Dec 06 16:26:25 volumio volumio[3379]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::volumioGetState Dec 06 16:26:25 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:25 volumio volumio[3379]: info: Starting Shairport Sync Dec 06 16:26:25 volumio sudo[3705]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 16:26:25 volumio sudo[3705]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 16:26:25 volumio sudo[3709]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 06 16:26:25 volumio sudo[3709]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio volumio[3379]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Dec 06 16:26:25 volumio sudo[3716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:26:25 volumio sudo[3716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:25 volumio volumio[3379]: info: Spotify Successfully logged in Dec 06 16:26:25 volumio sudo[3709]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:25 volumio sudo[3705]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:26:25 volumio volumio[3379]: info: [1765059985977] CoreMusicLibrary::Adding element Spotify Dec 06 16:26:25 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:26:25 volumio volumio[3379]: Cannot find translation for source Bandcamp Discover Dec 06 16:26:25 volumio volumio[3379]: Cannot find translation for source SoundCloud Dec 06 16:26:25 volumio volumio[3379]: Cannot find translation for source YouTube2 Dec 06 16:26:25 volumio volumio[3379]: Cannot find translation for source YouTube Music Dec 06 16:26:25 volumio volumio[3379]: Cannot find translation for source Podcast Dec 06 16:26:25 volumio volumio[3379]: Cannot find translation for source Volusonic Dec 06 16:26:25 volumio volumio[3379]: Cannot find translation for source Spotify Dec 06 16:26:26 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 06 16:26:26 volumio sudo[3722]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 06 16:26:26 volumio sudo[3722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:26 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:26:26 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:26:26 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:26:26 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:26:26 volumio sudo[3716]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:26 volumio systemd[1]: Reloading. Dec 06 16:26:26 volumio volumio[3379]: info: Shairport-Sync Started Dec 06 16:26:26 volumio volumio[3379]: info: [squeezelite_mc] Notification listener started Dec 06 16:26:26 volumio volumio[3379]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 06 16:26:26 volumio volumio[3379]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 06 16:26:26 volumio volumio[3379]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 06 16:26:27 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:27 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:27 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:26:27 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:26:27 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:27 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:26:28 volumio volumio[3379]: info: go-librespot daemon successfully initialized Dec 06 16:26:28 volumio sudo[3722]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:28 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:26:28 volumio sudo[3757]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:26:28 volumio sudo[3757]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:28 volumio sudo[3757]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:28 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 06 16:26:28 volumio volumio[3379]: info: CoreCommandRouter::volumioGetState Dec 06 16:26:28 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:28 volumio sudo[3760]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 06 16:26:28 volumio sudo[3760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:28 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 06 16:26:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 06 16:26:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:28 volumio volumio[3379]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect' Dec 06 16:26:28 volumio volumio[3379]: info: CoreCommandRouter::volumioGetState Dec 06 16:26:28 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:28 volumio go-librespot[3762]: go-librespot daemon starting... Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=debug msg="app state loaded" Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:28 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 06 16:26:28 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 06 16:26:28 volumio sudo[3760]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=info msg="zeroconf server listening on port 43957" Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=debug msg="obtained new client token: AABzD6RXrHh+BQbmCNsIwH9hnulJ6avDfbDFeYvqkSgEoMts+OiaE/YAbHACpbcYqFfdhL3BoogPjv/r9gEgO22XkqB0udv36GbMLHnL0FWsBfu6036ZvjqqzEvV8oBZ/WReGLkJsQ3zE+bSfjuE1h+6nqHCuKaPKMq17XGTqIu7reOIVe7nd/P7p2q18vSPC5WkVKU/YBa8C//t3ePOGXIxTVJXe6Miesq1YkHg9hC0+avXL2+HdiC7IQ==" Dec 06 16:26:28 volumio go-librespot[3763]: time="2025-12-06T16:26:28-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:29 volumio go-librespot[3763]: time="2025-12-06T16:26:29-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:29 volumio go-librespot[3763]: time="2025-12-06T16:26:29-06:00" level=debug msg="completed challenge" Dec 06 16:26:29 volumio go-librespot[3763]: time="2025-12-06T16:26:29-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:29 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:26:29 volumio sudo[3771]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:26:29 volumio sudo[3771]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:29 volumio sudo[3771]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:29 volumio volumio[3379]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 06 16:26:29 volumio sudo[3775]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 06 16:26:29 volumio sudo[3775]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:29 volumio sudo[3775]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:29 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 06 16:26:29 volumio sudo[3778]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 06 16:26:29 volumio sudo[3778]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:29 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 06 16:26:29 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 06 16:26:29 volumio sudo[3778]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:29 volumio volumio[3379]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect' Dec 06 16:26:29 volumio volumio[3379]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 06 16:26:29 volumio volumio[3379]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 06 16:26:29 volumio volumio[3379]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 06 16:26:29 volumio mpd[3720]: 2025-12-06T16:26:29 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 06 16:26:29 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 06 16:26:29 volumio sudo[3594]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:29 volumio sudo[3675]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:29 volumio sudo[3584]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:30 volumio volumio[3379]: error: MPD error: The expression evaluated to a falsy value: Dec 06 16:26:30 volumio volumio[3379]: assert.ok(self.idling) Dec 06 16:26:30 volumio volumio[3379]: error: The expression evaluated to a falsy value: Dec 06 16:26:30 volumio volumio[3379]: assert.ok(self.idling) Dec 06 16:26:30 volumio volumio[3379]: error: MPD error: The expression evaluated to a falsy value: Dec 06 16:26:30 volumio volumio[3379]: assert.ok(self.idling) Dec 06 16:26:30 volumio volumio[3379]: error: The expression evaluated to a falsy value: Dec 06 16:26:30 volumio volumio[3379]: assert.ok(self.idling) Dec 06 16:26:30 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:26:30 volumio volumio[3379]: error: updateQueue error: null Dec 06 16:26:30 volumio volumio[3379]: info: MPD running with PID3720 Dec 06 16:26:30 volumio volumio[3379]: ,establishing connection Dec 06 16:26:30 volumio volumio[3379]: error: updateQueue error: null Dec 06 16:26:30 volumio sudo[3789]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:26:30 volumio sudo[3789]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:30 volumio sudo[3789]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:30 volumio volumio[3379]: info: CoreCommandRouter::volumioGetState Dec 06 16:26:30 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:30 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:26:30 volumio sudo[3792]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:26:30 volumio sudo[3792]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:30 volumio sudo[3792]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:31 volumio volumio[3379]: info: Initializing connection to go-librespot Websocket Dec 06 16:26:31 volumio volumio[3379]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:26:31 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:26:31 volumio sudo[3809]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:26:31 volumio sudo[3809]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:31 volumio sudo[3809]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:31 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:26:31 volumio sudo[3815]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:26:31 volumio sudo[3815]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:31 volumio sudo[3815]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 06 16:26:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:32 volumio go-librespot[3817]: go-librespot daemon starting... Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="app state loaded" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:32 volumio volumio[3379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:26:32 volumio sudo[3827]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:26:32 volumio sudo[3827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=info msg="zeroconf server listening on port 38265" Dec 06 16:26:32 volumio sudo[3827]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:32 volumio volumio[3379]: info: Completed starting Core Plugins Dec 06 16:26:32 volumio volumio[3379]: info: ------------------------------------------- Dec 06 16:26:32 volumio volumio[3379]: info: ----- MyVolumio plugins startup ---- Dec 06 16:26:32 volumio volumio[3379]: info: ------------------------------------------- Dec 06 16:26:32 volumio volumio[3379]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="obtained new client token: AACHDHNoSu4R5BZOSZbgXUE+NwKJpDsgWqMrko3pt9DqiPpc0gWddlhzvncZ2gZGNlXOVeEqtKlqNNLY6VnKvyHQeRfZDrkBqxfRAmnhmp1N42qIDvXUVSNily6eXIFG01ziy1IZr8baWqRERn4jNV7xPHUXdwTi0n2IlSSxNwRkUyig8E8eLiqhHAa8X285Td1XwYffDVXjbkHEypv9T4tHsAXv6B5KFEQNmsKnTT6aInCjDcjhUfNamA==" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=debug msg="completed challenge" Dec 06 16:26:32 volumio go-librespot[3818]: time="2025-12-06T16:26:32-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:32 volumio sudo[3830]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:26:32 volumio sudo[3830]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:32 volumio sudo[3832]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:26:32 volumio sudo[3832]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:33 volumio sudo[3834]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:26:33 volumio sudo[3834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:33 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 06 16:26:33 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 06 16:26:33 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 06 16:26:33 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 06 16:26:33 volumio sudo[3832]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:33 volumio sudo[3834]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:33 volumio mpd_monitor.sh[3838]: MPD Monitor Service: Starting MPD Monitor Service Dec 06 16:26:33 volumio sudo[3830]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:33 volumio volumio[3379]: info: Successfully started MPD Monitor Dec 06 16:26:33 volumio volumio[3379]: info: Successfully started MPD Monitor Dec 06 16:26:33 volumio volumio[3379]: info: Successfully started MPD Monitor Dec 06 16:26:34 volumio volumio[3379]: info: Initializing connection to go-librespot Websocket Dec 06 16:26:34 volumio volumio[3379]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:26:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 06 16:26:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:36 volumio go-librespot[3842]: go-librespot daemon starting... Dec 06 16:26:36 volumio go-librespot[3843]: time="2025-12-06T16:26:36-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:36 volumio go-librespot[3843]: time="2025-12-06T16:26:36-06:00" level=debug msg="app state loaded" Dec 06 16:26:36 volumio go-librespot[3843]: time="2025-12-06T16:26:36-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:36 volumio go-librespot[3843]: time="2025-12-06T16:26:36-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:37 volumio volumio[3379]: info: Initializing connection to go-librespot Websocket Dec 06 16:26:37 volumio go-librespot[3843]: time="2025-12-06T16:26:37-06:00" level=debug msg="new websocket client" Dec 06 16:26:37 volumio volumio[3379]: info: Connection to go-librespot Websocket established Dec 06 16:26:40 volumio volumio[3379]: info: Getting Spotify volume Dec 06 16:26:40 volumio volumio[3379]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 06 16:26:40 volumio volumio[3379]: info: CoreCommandRouter::volumioGetState Dec 06 16:26:40 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:40 volumio volumio[3379]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 06 16:26:40 volumio volumio[3379]: SPOTIFY: SPOTIFY VOLUME undefined Dec 06 16:26:40 volumio volumio[3379]: SPOTIFY: VOLUMIO VOLUME 86 Dec 06 16:26:40 volumio volumio[3379]: info: Aligning Spotify Volume to Volumio Volume Dec 06 16:26:40 volumio volumio[3379]: info: CoreCommandRouter::volumioGetState Dec 06 16:26:40 volumio volumio[3379]: info: CorePlayQueue::getTrack 0 Dec 06 16:26:40 volumio volumio[3379]: info: Setting Spotify Volume from Volumio: 86 Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 06 16:26:42 volumio volumio[3379]: info: Adding plugin bluetooth to MyMusic Plugins Dec 06 16:26:42 volumio volumio[3379]: info: Adding plugin multiroom to MyMusic Plugins Dec 06 16:26:42 volumio volumio[3379]: info: Adding plugin metavolumio to MyMusic Plugins Dec 06 16:26:42 volumio volumio[3379]: info: Adding plugin cd_controller to MyMusic Plugins Dec 06 16:26:42 volumio volumio[3379]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 06 16:26:42 volumio volumio[3379]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 06 16:26:42 volumio volumio[3379]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 06 16:26:42 volumio volumio[3379]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=info msg="zeroconf server listening on port 36889" Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=debug msg="obtained new client token: AABJF/zS9FA27bpuFD1YhG6Fo0MwBT75VcMIj8+25B6zd9+70A0br0OrRLSHAYRQv1swnfefyYCQKH8SxkKzqu19zgOMg/enVpUN6gs3VBUIdO/QsLB4Z6AHyN9W8Fsq4vmHGmCFjFCN97hLznGph5SHb48Dl8OsUFYT4NGPg9esbNS4wYgA+dljj7HgLgb/s3c1TBQzUZDCzUlID5PW0Ms2AYs0jjDH3LffShJBsjrXse9iYu/+06fZeg==" Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=debug msg="completed challenge" Dec 06 16:26:42 volumio go-librespot[3843]: time="2025-12-06T16:26:42-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:43 volumio volumio[3379]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 06 16:26:43 volumio volumio[3379]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 06 16:26:43 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:43 volumio volumio[3379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:26:43 volumio volumio[3379]: info: Starting MyVolumio Remote Streaming Endpoints Dec 06 16:26:43 volumio volumio[3379]: info: MyVolumio login type: Token Dec 06 16:26:43 volumio volumio[3379]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 06 16:26:43 volumio volumio[3379]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 06 16:26:43 volumio volumio[3379]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 06 16:26:43 volumio volumio[3379]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 06 16:26:43 volumio volumio[3379]: info: Streaming services startup Dec 06 16:26:43 volumio volumio[3379]: info: Starting Streaming Daemon Dec 06 16:26:43 volumio sudo[3865]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:26:44 volumio sudo[3865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:44 volumio volumio[3379]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 06 16:26:44 volumio sudo[3865]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:44 volumio volumio[3379]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Dec 06 16:26:44 volumio volumio[3379]: info: Sending Spotify command with payload to local API: /player/volume Dec 06 16:26:44 volumio volumio[3379]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:26:44 volumio volumio[3379]: Error: socket hang up Dec 06 16:26:44 volumio volumio[3379]: at connResetException (node:internal/errors:720:14) Dec 06 16:26:44 volumio volumio[3379]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 06 16:26:44 volumio volumio[3379]: at Socket.emit (node:events:526:35) Dec 06 16:26:44 volumio volumio[3379]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 06 16:26:44 volumio volumio[3379]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 06 16:26:44 volumio volumio[3379]: code: 'ECONNRESET', Dec 06 16:26:44 volumio volumio[3379]: response: undefined Dec 06 16:26:44 volumio volumio[3379]: } Dec 06 16:26:44 volumio volumio[3379]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:26:44 volumio sudo[3885]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 16:25' Dec 06 16:26:44 volumio sudo[3885]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:45 volumio sudo[3885]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 06 16:26:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:45 volumio go-librespot[3893]: go-librespot daemon starting... Dec 06 16:26:45 volumio go-librespot[3894]: time="2025-12-06T16:26:45-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:45 volumio go-librespot[3894]: time="2025-12-06T16:26:45-06:00" level=debug msg="app state loaded" Dec 06 16:26:45 volumio go-librespot[3894]: time="2025-12-06T16:26:45-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:45 volumio go-librespot[3894]: time="2025-12-06T16:26:45-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:46 volumio go-librespot[3894]: time="2025-12-06T16:26:46-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:46 volumio go-librespot[3894]: time="2025-12-06T16:26:46-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:46 volumio go-librespot[3894]: time="2025-12-06T16:26:46-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:46 volumio go-librespot[3894]: time="2025-12-06T16:26:46-06:00" level=info msg="zeroconf server listening on port 38343" Dec 06 16:26:46 volumio volumio-remote-updater[2353]: [2025-12-06 16:26:46] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 06 16:26:46 volumio volumio-remote-updater[2353]: [2025-12-06 16:26:46] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 06 16:26:46 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:46 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 06 16:26:46 volumio systemd[1]: volumio.service: Consumed 44.875s CPU time. Dec 06 16:26:46 volumio go-librespot[3894]: time="2025-12-06T16:26:46-06:00" level=debug msg="obtained new client token: AADbuNY+NkLTZsmUZqeTU/LoTwisy8gLg7xSipjrWnFc5Wc+ScLOmM2MzW/IQWqb3QyKuNhv0zjfM7nlIyi4dpXW2c4VFqoGMMIWxQDg6hWW1uUgqmH/pgbRVyBoPGDQnjXShEx9SVEKcPyqt2i/pmZebM3cJmuWPXEs4FNjBFB6OcWeUy5jPySV55VWfo5Id7vzZd/WeDEflJBvbq8YwJQFD3vaWseKxyPz5LCA00tM6X/zCimNU3o=" Dec 06 16:26:46 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 06 16:26:46 volumio go-librespot[3894]: time="2025-12-06T16:26:46-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:46 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 06 16:26:46 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 21166. Dec 06 16:26:46 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 06 16:26:46 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 06 16:26:46 volumio systemd[1]: volumio.service: Consumed 44.875s CPU time. Dec 06 16:26:46 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 06 16:26:46 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 06 16:26:47 volumio go-librespot[3894]: time="2025-12-06T16:26:47-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:47 volumio go-librespot[3894]: time="2025-12-06T16:26:47-06:00" level=debug msg="completed challenge" Dec 06 16:26:47 volumio go-librespot[3894]: time="2025-12-06T16:26:47-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:48 volumio volumio[3908]: info: ------------------------------------------- Dec 06 16:26:48 volumio volumio[3908]: info: ----- Volumio3 ---- Dec 06 16:26:48 volumio volumio[3908]: info: ------------------------------------------- Dec 06 16:26:48 volumio volumio[3908]: info: ----- System startup ---- Dec 06 16:26:48 volumio volumio[3908]: info: ------------------------------------------- Dec 06 16:26:49 volumio volumio[3908]: info: MYVOLUMIO Environment detected Dec 06 16:26:49 volumio volumio[3908]: info: Plugin folders cleanup Dec 06 16:26:49 volumio volumio[3908]: info: Scanning into folder /volumio/app/plugins/ Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category audio_interface Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category miscellanea Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category music_service Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category plugins.json Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category system_controller Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category user_interface Dec 06 16:26:49 volumio volumio[3908]: info: Scanning into folder /data/plugins/ Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category audio_interface Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category music_service Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category system_controller Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category system_hardware Dec 06 16:26:49 volumio volumio[3908]: info: Scanning category user_interface Dec 06 16:26:49 volumio volumio[3908]: info: Plugin folders cleanup completed Dec 06 16:26:49 volumio volumio[3908]: info: ------------------------------------------- Dec 06 16:26:49 volumio volumio[3908]: info: ----- Core plugins startup ---- Dec 06 16:26:49 volumio volumio[3908]: info: ------------------------------------------- Dec 06 16:26:49 volumio volumio[3908]: info: Loading plugins from folder /volumio/app/plugins/ Dec 06 16:26:49 volumio volumio[3908]: info: Adding plugin upnp to MyMusic Plugins Dec 06 16:26:49 volumio volumio[3908]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 06 16:26:49 volumio volumio[3908]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 06 16:26:49 volumio volumio[3908]: info: Loading plugins from folder /data/plugins/ Dec 06 16:26:49 volumio volumio[3908]: info: Loading plugin "system"... Dec 06 16:26:49 volumio volumio[3908]: info: Loading plugin "appearance"... Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "network"... Dec 06 16:26:50 volumio volumio[3908]: info: Refreshing Cached IP Addresses Dec 06 16:26:50 volumio sudo[3936]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 16:26:50 volumio sudo[3936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:50 volumio sudo[3938]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 16:26:50 volumio sudo[3938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:50 volumio sudo[3936]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "services"... Dec 06 16:26:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "alsa_controller"... Dec 06 16:26:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:50 volumio sudo[3938]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:50 volumio sudo[3949]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 06 16:26:50 volumio sudo[3949]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:50 volumio go-librespot[3952]: go-librespot daemon starting... Dec 06 16:26:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:50 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "wizard"... Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=debug msg="app state loaded" Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "networkfs"... Dec 06 16:26:50 volumio volumio[3908]: info: Starting Udev Watcher for removable devices Dec 06 16:26:50 volumio volumio[3908]: info: Ignoring mount for partition: boot Dec 06 16:26:50 volumio volumio[3908]: info: Ignoring mount for partition: volumio Dec 06 16:26:50 volumio volumio[3908]: info: Ignoring mount for partition: volumio_data Dec 06 16:26:50 volumio volumio[3908]: info: Mounting Device Wikipedia Dec 06 16:26:50 volumio sudo[3982]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 06 16:26:50 volumio sudo[3982]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:26:50 volumio sudo[3982]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:50 volumio volumio[3908]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 06 16:26:50 volumio volumio[3908]: dmesg(1) may have more information after failed mount system call. Dec 06 16:26:50 volumio volumio[3908]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 06 16:26:50 volumio volumio[3908]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 06 16:26:50 volumio volumio[3908]: dmesg(1) may have more information after failed mount system call. Dec 06 16:26:50 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "volumio_command_line_client"... Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "upnp"... Dec 06 16:26:50 volumio volumio[3908]: info: [1765060010713] Starting Upmpd Daemon Dec 06 16:26:50 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "my_music"... Dec 06 16:26:50 volumio volumio[3908]: info: Loading plugin "mpd"... Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=info msg="zeroconf server listening on port 43241" Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=debug msg="obtained new client token: AAAjv3pxruhLGc/SGkZndST0k3NCTHwr2ej76w2Sr5T+u65Ho/UDbX3V+wpBoQfAwmmfkVxEkCe5r4UlVxqKrFvKYPPEfHuIpe9Q0W4CKi9BtTzmCA/VpeV4DUN5Fv+i4Kg8TWCAy5ZpgATr0BpNrLEwgtSrPkwD/dV+w0CPFQ+esHOUGXDFKD9cTEaBBjkvOJXKQT0gln71Bj7b5BAbupIsY6kq0GSxxDcj4IRS8hdPURAYmhhL5sB1bA==" Dec 06 16:26:50 volumio go-librespot[3969]: time="2025-12-06T16:26:50-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:51 volumio go-librespot[3969]: time="2025-12-06T16:26:51-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:51 volumio go-librespot[3969]: time="2025-12-06T16:26:51-06:00" level=debug msg="completed challenge" Dec 06 16:26:51 volumio sudo[3949]: pam_unix(sudo:session): session closed for user root Dec 06 16:26:51 volumio volumio-remote-updater[2353]: [2025-12-06 16:26:51] [connect] Successful connection Dec 06 16:26:51 volumio go-librespot[3969]: time="2025-12-06T16:26:51-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:51 volumio volumio[3908]: info: Loading plugin "upnp_browser"... Dec 06 16:26:52 volumio volumio[3908]: info: Loading plugin "alarm-clock"... Dec 06 16:26:52 volumio volumio[3908]: info: Loading plugin "airplay_emulation"... Dec 06 16:26:52 volumio volumio[3908]: info: Starting Shairport Sync Dec 06 16:26:52 volumio volumio[3908]: info: Loading plugin "last_100"... Dec 06 16:26:52 volumio volumio[3908]: info: Loading plugin "webradio"... Dec 06 16:26:52 volumio volumio[3908]: info: Loading plugin "i2s_dacs"... Dec 06 16:26:52 volumio volumio[3908]: info: I2S DAC not set, start Auto-detection Dec 06 16:26:52 volumio volumio[3908]: info: Loading plugin "volumiodiscovery"... Dec 06 16:26:52 volumio volumio[3908]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 06 16:26:52 volumio volumio[3908]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:26:52 volumio volumio[3908]: *** WARNING *** For more information see Dec 06 16:26:52 volumio volumio[3908]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 06 16:26:52 volumio volumio[3908]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:26:52 volumio volumio[3908]: *** WARNING *** For more information see Dec 06 16:26:52 volumio node[3908]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 06 16:26:52 volumio node[3908]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:26:52 volumio node[3908]: *** WARNING *** For more information see Dec 06 16:26:52 volumio node[3908]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 06 16:26:52 volumio node[3908]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:26:52 volumio node[3908]: *** WARNING *** For more information see Dec 06 16:26:52 volumio volumio[3908]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 06 16:26:52 volumio volumio[3908]: info: Discovery: Started advertising with name: Volumio Dec 06 16:26:52 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:26:52 volumio volumio[3908]: info: Loading plugin "bandcamp"... Dec 06 16:26:54 volumio volumio[3908]: info: Plugin calmradio is not enabled Dec 06 16:26:54 volumio volumio[3908]: info: Loading plugin "soundcloud"... Dec 06 16:26:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 06 16:26:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:54 volumio go-librespot[3992]: go-librespot daemon starting... Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="app state loaded" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:54 volumio volumio[3908]: info: Loading plugin "spop"... Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=info msg="zeroconf server listening on port 44143" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="obtained new client token: AAASYFnT+GuUc/1zk9tkFB3UWivcCqgnT/mayk7U0slGFH5NaOvUUmWuTO1H+Ii19wa3mm9mc8I31R48HxJA+7bqrLOi34Xc0dY2/LfRkjprSFllSqKSIPvZ6V2tylYzvY4kxkNyO9wCUONgVxc7tWp8KSwjMedIaaI4ll0QUHYyAtF2tf3GnJ4S1Cl99IycEaUa5Q/DSkJzJywF56G4MAKzkTOvwm4fp2qA2xR1AhPMrT+nb/X7jiqOxQ==" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=debug msg="completed challenge" Dec 06 16:26:54 volumio go-librespot[3993]: time="2025-12-06T16:26:54-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:55 volumio volumio[3908]: info: Loading plugin "squeezelite_mc"... Dec 06 16:26:56 volumio volumio[3908]: info: Loading plugin "youtube2"... Dec 06 16:26:56 volumio volumio[3908]: info: Loading plugin "ytcr"... Dec 06 16:26:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 06 16:26:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:26:58 volumio go-librespot[4000]: go-librespot daemon starting... Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="app state loaded" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="stored credentials not found" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:26:58 volumio volumio[3908]: info: Loading plugin "ytmusic"... Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=info msg="zeroconf server listening on port 46577" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="obtained new client token: AAAwteTCG1hI6BWKhXq5OqiS1tF4tjdr1I3kkEqlBO8fX2GJhByderx5ND55axzBh+2rSYwkPvpQC3cWWfbdia6YPpmFjeyvrroAjdO8qkG9xjGqVWaLcNYAZLlqq5uc+dkJTfGCYvDY8va8UaqrD7B0SYqbCibmfmntrZbaec/O+wJuLw5Yv5eHwxNBZfK7SxiuaFV4HRArj2tOmc14iGliN2xhUlELZUucYjkmfzLfushfst92Yr1r4Q==" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="completed keyexchange" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=debug msg="completed challenge" Dec 06 16:26:58 volumio go-librespot[4001]: time="2025-12-06T16:26:58-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:26:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:26:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:26:58 volumio volumio[3908]: info: Plugin now_playing is not enabled Dec 06 16:26:58 volumio volumio[3908]: info: Loading plugin "outputs"... Dec 06 16:26:58 volumio volumio[3908]: info: Loading plugin "albumart"... Dec 06 16:26:58 volumio volumio[3908]: info: Plugin example_plugin is not enabled Dec 06 16:26:58 volumio volumio[3908]: info: Loading plugin "inputs"... Dec 06 16:26:58 volumio volumio[3908]: info: Loading plugin "updater_comm"... Dec 06 16:26:58 volumio volumio[3908]: info: Plugin mpdemulation is not enabled Dec 06 16:26:58 volumio volumio[3908]: info: Loading plugin "rest_api"... Dec 06 16:26:58 volumio volumio[3908]: info: Loading plugin "websocket"... Dec 06 16:26:58 volumio volumio[3908]: info: Starting Socket.io Server version 1.7.4 Dec 06 16:26:58 volumio volumio[3908]: info: Plugin fusiondsp is not enabled Dec 06 16:26:58 volumio volumio[3908]: info: Plugin mpdoutput is not enabled Dec 06 16:26:58 volumio volumio[3908]: info: Plugin RoonBridge is not enabled Dec 06 16:26:58 volumio volumio[3908]: info: Loading plugin "podcast"... Dec 06 16:26:59 volumio volumio[3908]: info: ControllerPodcast::constructor Dec 06 16:26:59 volumio volumio[3908]: info: Loading plugin "volusonic"... Dec 06 16:26:59 volumio volumio[4009]: Forking 3 albumart workers Dec 06 16:27:00 volumio volumio[3908]: info: Applying required configuration parameters for plugin volusonic Dec 06 16:27:00 volumio volumio[3908]: info: Loading plugin "backup_restore"... Dec 06 16:27:00 volumio volumio[4021]: Starting albumart workers Dec 06 16:27:00 volumio volumio[4020]: Starting albumart workers Dec 06 16:27:00 volumio volumio[4019]: Starting albumart workers Dec 06 16:27:01 volumio volumio[3908]: info: Applying required configuration parameters for plugin backup_restore Dec 06 16:27:01 volumio volumio[3908]: info: Plugin rpi_eeprom_config is not enabled Dec 06 16:27:01 volumio volumio[3908]: info: Plugin rpi_eeprom_updater is not enabled Dec 06 16:27:01 volumio volumio[3908]: info: Loading plugin "scheduledrestart"... Dec 06 16:27:01 volumio volumio[3908]: info: Applying required configuration parameters for plugin scheduledrestart Dec 06 16:27:01 volumio volumio[3908]: info: Plugin Bluetoothremote is not enabled Dec 06 16:27:01 volumio volumio[3908]: info: Plugin music_services_shield is not enabled Dec 06 16:27:01 volumio volumio[3908]: info: Loading plugin "Systeminfo"... Dec 06 16:27:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 06 16:27:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:01 volumio volumio[3908]: info: Plugin peppymeterbasic is not enabled Dec 06 16:27:01 volumio volumio[3908]: info: Loading plugin "peppyspectrum"... Dec 06 16:27:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:01 volumio go-librespot[4076]: go-librespot daemon starting... Dec 06 16:27:01 volumio go-librespot[4082]: time="2025-12-06T16:27:01-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:01 volumio go-librespot[4082]: time="2025-12-06T16:27:01-06:00" level=debug msg="app state loaded" Dec 06 16:27:01 volumio go-librespot[4082]: time="2025-12-06T16:27:01-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:01 volumio go-librespot[4082]: time="2025-12-06T16:27:01-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:02 volumio go-librespot[4082]: time="2025-12-06T16:27:02-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:02 volumio go-librespot[4082]: time="2025-12-06T16:27:02-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:02 volumio go-librespot[4082]: time="2025-12-06T16:27:02-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:02 volumio go-librespot[4082]: time="2025-12-06T16:27:02-06:00" level=info msg="zeroconf server listening on port 36225" Dec 06 16:27:02 volumio volumio[3908]: info: Loading i18n strings for locale en Dec 06 16:27:02 volumio go-librespot[4082]: time="2025-12-06T16:27:02-06:00" level=debug msg="obtained new client token: AACd3b1F39sRnp3ccvMUHoe78iDINsLprqpUD2+8ftxJUY4OdeuQwm4tCMHoe9RID+F0VqQx2S/6X8BCLbvTrxBpJGfWX2OKDCvbVxqL1uc4kAqpL7+d8RfTJy3wQyuBlMNSlxkWr/gMl+wXUAWOIQ3emNuU2ZvV12I7/zucDh755ElDvPdoVBbL7KZMIZrXP26Fx9yMjXw/pIBJKYYcBKBVS/GycTgyi4xoqr0T0i+I1dj0/Scfh5w=" Dec 06 16:27:02 volumio volumio[3908]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 06 16:27:02 volumio volumio[3908]: Updating browse sources language Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:02 volumio go-librespot[4082]: time="2025-12-06T16:27:02-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::initPlayerControls Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: Express server listening on port 3000 Dec 06 16:27:02 volumio volumio[3908]: [Metrics] WebUI: 14s 403.69ms Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::resetVolumioState Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::getcurrentVolume Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:02 volumio sudo[4094]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 16:27:02 volumio sudo[4094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:02 volumio sudo[4094]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:02 volumio sudo[4096]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 16:27:02 volumio sudo[4096]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:02 volumio sudo[4096]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:02 volumio volumio[3908]: info: Volumio Network Manager: Network status updated: 1 Dec 06 16:27:02 volumio volumio[3908]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::pushState Dec 06 16:27:02 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioPushState Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::updateTrackBlock Dec 06 16:27:02 volumio volumio[3908]: info: CorePlayQueue::getTrackBlock Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:27:02 volumio volumio[3908]: info: Reloading queue from file Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::setRepeat null single undefined Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::pushState Dec 06 16:27:02 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioPushState Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::setRandom null Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::pushState Dec 06 16:27:02 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioPushState Dec 06 16:27:02 volumio volumio[3908]: info: Setting Device type: Raspberry PI Dec 06 16:27:02 volumio volumio[3908]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:27:02 volumio volumio[3908]: info: CoreStateMachine::pushState Dec 06 16:27:02 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioPushState Dec 06 16:27:02 volumio sudo[4110]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 06 16:27:02 volumio volumio[3908]: info: Completed loading Core Plugins Dec 06 16:27:02 volumio sudo[4110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:02 volumio volumio[3908]: info: Preparing to generate the ALSA configuration file Dec 06 16:27:02 volumio sudo[4110]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:02 volumio volumio[3908]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 06 16:27:02 volumio volumio[3908]: info: Discovery: Found device Volumio Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioGetState Dec 06 16:27:02 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:02 volumio volumio[3908]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 06 16:27:02 volumio volumio[3908]: info: Discovery: Found device Volumio Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioGetState Dec 06 16:27:02 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:02 volumio volumio[3908]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 06 16:27:02 volumio volumio[3908]: info: Reading ALSA contributions from plugins. Dec 06 16:27:02 volumio volumio[3908]: info: Upmpdcli Daemon Started Dec 06 16:27:02 volumio volumio[3908]: info: Asound.conf file unchanged, so no further update is needed Dec 06 16:27:02 volumio volumio[3908]: info: Output device has changed, restarting MPD Dec 06 16:27:02 volumio volumio[3908]: info: Output device has changed, restarting Shairport Sync Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:02 volumio sudo[4113]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:27:02 volumio sudo[4113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:02 volumio sudo[4113]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:02 volumio sudo[4115]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:27:02 volumio sudo[4115]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:02 volumio volumio[3908]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:27:02 volumio volumio[3908]: info: ___________ START PLUGINS ___________ Dec 06 16:27:02 volumio volumio[3908]: info: ControllerMpd::onStart: Initializing MPD Dec 06 16:27:02 volumio volumio[3908]: info: Creating MPD Configuration file Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:02 volumio volumio[3908]: info: [1765060022886] CoreMusicLibrary::Adding element Media Servers Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:02 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 06 16:27:02 volumio sudo[4123]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:27:02 volumio sudo[4123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:02 volumio sudo[4123]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:02 volumio sudo[4125]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:27:02 volumio sudo[4125]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:02 volumio volumio[3908]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:03 volumio volumio[3908]: info: [1765060022996] CoreMusicLibrary::Adding element Last_100 Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:03 volumio volumio[3908]: info: [1765060023001] CoreMusicLibrary::Adding element Webradio Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 06 16:27:03 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 16:27:03 volumio systemd[1]: mpd.service: Consumed 4.477s CPU time. Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:27:03 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 06 16:27:03 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 16:27:03 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 16:27:03 volumio volumio[3908]: info: Initializing BBC Radios Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:03 volumio volumio[3908]: info: [1765060023072] CoreMusicLibrary::Adding element Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:03 volumio volumio[3908]: info: [1765060023082] CoreMusicLibrary::Adding element SoundCloud Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source SoundCloud Dec 06 16:27:03 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 16:27:03 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 16:27:03 volumio volumio[3908]: info: Creating Spotify config file Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:03 volumio sudo[4150]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 16:27:03 volumio sudo[4150]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 16:27:03 volumio sudo[4150]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:03 volumio volumio[3908]: info: [squeezelite_mc] Starting proxy server... Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:03 volumio volumio[3908]: info: [1765060023452] CoreMusicLibrary::Adding element YouTube2 Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source SoundCloud Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube2 Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:03 volumio volumio[3908]: info: [1765060023478] CoreMusicLibrary::Adding element YouTube Music Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source SoundCloud Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube2 Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube Music Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:03 volumio volumio[3908]: info: [1765060023490] CoreMusicLibrary::Adding element Podcast Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source SoundCloud Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube2 Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube Music Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Podcast Dec 06 16:27:03 volumio volumio[3908]: info: Loading i18n strings for locale en Dec 06 16:27:03 volumio volumio[3908]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 06 16:27:03 volumio volumio[3908]: Updating browse sources language Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source SoundCloud Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube2 Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube Music Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Podcast Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source SoundCloud Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube2 Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube Music Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Podcast Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:03 volumio volumio[3908]: info: [1765060023538] CoreMusicLibrary::Adding element Volusonic Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source SoundCloud Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube2 Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source YouTube Music Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Podcast Dec 06 16:27:03 volumio volumio[3908]: Cannot find translation for source Volusonic Dec 06 16:27:03 volumio volumio[3908]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 06 16:27:03 volumio volumio-remote-updater[2353]: [2025-12-06 16:27:03] [connect] Successful connection Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 06 16:27:03 volumio volumio[3908]: info: Volumio Calling Home Dec 06 16:27:03 volumio volumio[3908]: info: [squeezelite_mc] Proxy server started on port 36845 Dec 06 16:27:03 volumio volumio[3908]: info: Preparing to generate the ALSA configuration file Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:27:03 volumio volumio[3908]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 06 16:27:03 volumio volumio[3908]: info: Reading ALSA contributions from plugins. Dec 06 16:27:03 volumio go-librespot[4082]: time="2025-12-06T16:27:03-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:03 volumio go-librespot[4082]: time="2025-12-06T16:27:03-06:00" level=debug msg="completed challenge" Dec 06 16:27:03 volumio volumio[3908]: info: MPD Permissions set Dec 06 16:27:03 volumio volumio[3908]: info: MPD Permissions set Dec 06 16:27:03 volumio volumio-remote-updater[2353]: [2025-12-06 16:27:03] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765060023 101 Dec 06 16:27:03 volumio volumio[3908]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 06 16:27:03 volumio volumio[3908]: info: Spotify config file written Dec 06 16:27:03 volumio sudo[4160]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 06 16:27:03 volumio sudo[4160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:03 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 06 16:27:03 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 06 16:27:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:03 volumio volumio[3908]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 06 16:27:03 volumio volumio[3908]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:27:03 volumio volumio[3908]: info: CoreStateMachine::pushState Dec 06 16:27:03 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:03 volumio volumio[3908]: info: CoreCommandRouter::volumioPushState Dec 06 16:27:03 volumio volumio[3908]: info: [squeezelite_mc] Server discovery started Dec 06 16:27:03 volumio volumio[3908]: info: [squeezelite_mc] Player finder started Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 06 16:27:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio go-librespot[4162]: go-librespot daemon starting... Dec 06 16:27:04 volumio sudo[4160]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="app state loaded" Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: No need to fix Spotify hosts Dec 06 16:27:04 volumio volumio[3908]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 06 16:27:04 volumio volumio[3908]: info: Volumio called home Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:04 volumio volumio[3908]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"} Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=info msg="zeroconf server listening on port 43337" Dec 06 16:27:04 volumio volumio[3908]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 06 16:27:04 volumio volumio[3908]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 06 16:27:04 volumio volumio[3908]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 06 16:27:04 volumio volumio[3908]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 06 16:27:04 volumio volumio[3908]: SPOTIFY: BQBF2nyGT7s4xW9mtUCQgVhpXMhHUJFL_vHADWbE8Kh04uJly7miLDA8rMXoOEj2yapC34R4xXOImmCW2JG4x7Rqgbh1ar9Xt9cDEJCNSa98PyY5-CJ-gCYS5HPE8cCPcuNbw-gpaMfDYr1qap2jiaouN1zSV0tY27v0XPcRnwq2Id5LTb7fiOMJ4SlYUSl3xVj9VGNj4E6XL0MGe8FQYvRLQScURIkC0yt7ywk Dec 06 16:27:04 volumio volumio[3908]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 06 16:27:04 volumio volumio[3908]: info: New Spotify access token = BQBF2nyGT7s4xW9mtUCQgVhpXMhHUJFL_vHADWbE8Kh04uJly7miLDA8rMXoOEj2yapC34R4xXOImmCW2JG4x7Rqgbh1ar9Xt9cDEJCNSa98PyY5-CJ-gCYS5HPE8cCPcuNbw-gpaMfDYr1qap2jiaouN1zSV0tY27v0XPcRnwq2Id5LTb7fiOMJ4SlYUSl3xVj9VGNj4E6XL0MGe8FQYvRLQScURIkC0yt7ywk Dec 06 16:27:04 volumio volumio[3908]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="obtained new client token: AADggMSiDEw1ZRJOvjQMqOjfnzbAKf3X5Dp2YBqZgs83mQMYPF00KMOwvtMlGZjVMyY573nBBcgqGfYEztekaj7CnmlMvlnYNsrtyySKzMRufsnzvauuIaL7cwOi3H3bpeYl0uqZkuzIxo5RZoJpI+WrKIuuoGN12QF5hL9+NLnNQ5ylt3jpOReqJveqOU7sO6HbqA1ZvskBXDPguSSW0lbePDyTUGNKcck3dP2CWuOMhWOp8FOiiB6S2A==" Dec 06 16:27:04 volumio volumio[3908]: info: Starting Shairport Sync Dec 06 16:27:04 volumio volumio[3908]: info: Starting Shairport Sync Dec 06 16:27:04 volumio volumio[3908]: info: Starting Shairport Sync Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:04 volumio sudo[4187]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:27:04 volumio sudo[4187]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:04 volumio sudo[4189]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=debug msg="completed challenge" Dec 06 16:27:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:27:04 volumio sudo[4189]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:27:04 volumio sudo[4191]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:27:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:27:04 volumio sudo[4191]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:04 volumio systemd[1]: shairport-sync.service: Consumed 1.880s CPU time. Dec 06 16:27:04 volumio go-librespot[4165]: time="2025-12-06T16:27:04-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:04 volumio sudo[4184]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 06 16:27:04 volumio sudo[4184]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:27:04 volumio sudo[4184]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:04 volumio sudo[4187]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:04 volumio volumio[3908]: info: Asound.conf file unchanged, so no further update is needed Dec 06 16:27:04 volumio volumio[3908]: info: Output device has changed, restarting MPD Dec 06 16:27:04 volumio volumio[3908]: info: Output device has changed, restarting Shairport Sync Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:04 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:27:04 volumio sudo[4210]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:27:04 volumio sudo[4210]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:27:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:27:04 volumio sudo[4210]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:04 volumio volumio[3908]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:27:04 volumio sudo[4213]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:27:04 volumio sudo[4213]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:27:04 volumio sudo[4189]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:04 volumio sudo[4191]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:04 volumio volumio[3908]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 06 16:27:04 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 06 16:27:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 16:27:04 volumio systemd[1]: mpd.service: Consumed 1.632s CPU time. Dec 06 16:27:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 06 16:27:04 volumio sudo[4226]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 06 16:27:05 volumio sudo[4226]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:05 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 16:27:05 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 16:27:05 volumio sudo[4226]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:05 volumio volumio[3908]: info: MPD Permissions set Dec 06 16:27:05 volumio volumio[3908]: info: Shairport-Sync Started Dec 06 16:27:05 volumio volumio[3908]: Error adding Membership: Error: addMembership EINVAL Dec 06 16:27:05 volumio volumio[3908]: info: Shairport-Sync Started Dec 06 16:27:05 volumio volumio[3908]: info: Shairport-Sync Started Dec 06 16:27:05 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 16:27:05 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 16:27:05 volumio volumio[3908]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::volumioGetState Dec 06 16:27:05 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:05 volumio sudo[4247]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 06 16:27:05 volumio sudo[4247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:05 volumio sudo[4247]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:05 volumio volumio[3908]: info: Starting Shairport Sync Dec 06 16:27:05 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 06 16:27:05 volumio sudo[4244]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 16:27:05 volumio sudo[4244]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 16:27:05 volumio sudo[4255]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:27:05 volumio sudo[4255]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:05 volumio sudo[4244]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:05 volumio volumio[3908]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Dec 06 16:27:05 volumio volumio[3908]: info: Spotify Successfully logged in Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:27:05 volumio volumio[3908]: info: [1765060025382] CoreMusicLibrary::Adding element Spotify Dec 06 16:27:05 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:27:05 volumio volumio[3908]: Cannot find translation for source Bandcamp Discover Dec 06 16:27:05 volumio volumio[3908]: Cannot find translation for source SoundCloud Dec 06 16:27:05 volumio volumio[3908]: Cannot find translation for source YouTube2 Dec 06 16:27:05 volumio volumio[3908]: Cannot find translation for source YouTube Music Dec 06 16:27:05 volumio volumio[3908]: Cannot find translation for source Podcast Dec 06 16:27:05 volumio volumio[3908]: Cannot find translation for source Volusonic Dec 06 16:27:05 volumio volumio[3908]: Cannot find translation for source Spotify Dec 06 16:27:05 volumio sudo[4258]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 06 16:27:05 volumio sudo[4258]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:05 volumio systemd[1]: Reloading. Dec 06 16:27:05 volumio volumio[3908]: info: [squeezelite_mc] Notification listener started Dec 06 16:27:05 volumio volumio[3908]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 06 16:27:06 volumio volumio[3908]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 06 16:27:06 volumio volumio[3908]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 06 16:27:06 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:06 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:06 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:06 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:27:07 volumio volumio[3908]: info: CoreCommandRouter::volumioGetState Dec 06 16:27:07 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:07 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:27:07 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:27:07 volumio volumio[3908]: info: go-librespot daemon successfully initialized Dec 06 16:27:07 volumio sudo[4258]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:07 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:27:07 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:27:07 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:27:07 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:27:07 volumio systemd[1]: shairport-sync.service: Consumed 1.505s CPU time. Dec 06 16:27:07 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:27:07 volumio sudo[4255]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:07 volumio volumio[3908]: info: Shairport-Sync Started Dec 06 16:27:07 volumio sudo[4281]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:27:07 volumio sudo[4281]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:07 volumio sudo[4281]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:07 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 06 16:27:07 volumio sudo[4298]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 06 16:27:07 volumio sudo[4298]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 06 16:27:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:07 volumio go-librespot[4300]: go-librespot daemon starting... Dec 06 16:27:07 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 06 16:27:07 volumio go-librespot[4301]: time="2025-12-06T16:27:07-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:07 volumio go-librespot[4301]: time="2025-12-06T16:27:07-06:00" level=debug msg="app state loaded" Dec 06 16:27:07 volumio go-librespot[4301]: time="2025-12-06T16:27:07-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:07 volumio go-librespot[4301]: time="2025-12-06T16:27:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:08 volumio volumio[3908]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect' Dec 06 16:27:08 volumio volumio[3908]: info: CoreCommandRouter::volumioGetState Dec 06 16:27:08 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=info msg="zeroconf server listening on port 41323" Dec 06 16:27:08 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 06 16:27:08 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 06 16:27:08 volumio sudo[4298]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=debug msg="obtained new client token: AAB0p0jv6ZPt9OfZLZctQTjdbqda+yiZiYuqXHHYi1UacmSvs06mGBhRxzUmCyC/eOWg3A2OKonEfxv5LtuFll+MK04WlducY/TmHHiRIM/CaK2/G8l77SGfVpT7Hps2ijEwWTxp4NP0J6gnNws534ypZEw6Jr2dKnlwLtZ8wbqbLIxO4gk8vaLbhu9Yx+CBgS3H8GXnFqpzPZy3YFK6o9fcuganOFYEPusCIHxzJ3Y1SJhvBvq8Ok0Iew==" Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=debug msg="completed challenge" Dec 06 16:27:08 volumio go-librespot[4301]: time="2025-12-06T16:27:08-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:08 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:27:08 volumio sudo[4310]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:27:08 volumio sudo[4310]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:08 volumio sudo[4310]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:08 volumio volumio[3908]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 06 16:27:08 volumio sudo[4314]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 06 16:27:08 volumio sudo[4314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:08 volumio sudo[4314]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:08 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 06 16:27:09 volumio sudo[4317]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 06 16:27:09 volumio sudo[4317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:09 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 06 16:27:09 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 06 16:27:09 volumio sudo[4317]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:09 volumio volumio[3908]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect' Dec 06 16:27:09 volumio volumio[3908]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 06 16:27:09 volumio volumio[3908]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 06 16:27:09 volumio volumio[3908]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 06 16:27:09 volumio mpd[4260]: 2025-12-06T16:27:09 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 06 16:27:09 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 06 16:27:09 volumio sudo[4213]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:09 volumio sudo[4115]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:09 volumio sudo[4125]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:09 volumio volumio[3908]: error: MPD error: The expression evaluated to a falsy value: Dec 06 16:27:09 volumio volumio[3908]: assert.ok(self.idling) Dec 06 16:27:09 volumio volumio[3908]: error: The expression evaluated to a falsy value: Dec 06 16:27:09 volumio volumio[3908]: assert.ok(self.idling) Dec 06 16:27:09 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:27:09 volumio volumio[3908]: error: MPD error: The expression evaluated to a falsy value: Dec 06 16:27:09 volumio volumio[3908]: assert.ok(self.idling) Dec 06 16:27:09 volumio volumio[3908]: error: The expression evaluated to a falsy value: Dec 06 16:27:09 volumio volumio[3908]: assert.ok(self.idling) Dec 06 16:27:09 volumio volumio[3908]: info: MPD running with PID4260 Dec 06 16:27:09 volumio volumio[3908]: ,establishing connection Dec 06 16:27:09 volumio volumio[3908]: error: updateQueue error: null Dec 06 16:27:09 volumio volumio[3908]: error: updateQueue error: null Dec 06 16:27:09 volumio sudo[4328]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:27:09 volumio sudo[4328]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:09 volumio sudo[4328]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:10 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:27:10 volumio sudo[4331]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:27:10 volumio sudo[4331]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:10 volumio volumio[3908]: info: CoreCommandRouter::volumioGetState Dec 06 16:27:10 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:10 volumio sudo[4331]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:10 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:10 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:10 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:27:10 volumio sudo[4348]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:27:10 volumio sudo[4348]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:10 volumio sudo[4348]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:11 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:27:11 volumio sudo[4351]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:27:11 volumio sudo[4351]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 06 16:27:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:11 volumio go-librespot[4353]: go-librespot daemon starting... Dec 06 16:27:11 volumio sudo[4351]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=debug msg="app state loaded" Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=info msg="zeroconf server listening on port 39143" Dec 06 16:27:11 volumio go-librespot[4354]: time="2025-12-06T16:27:11-06:00" level=debug msg="obtained new client token: AAA0JPL4+ezVsiQSm+khOz1hBRYRgbdYxFDrU9lXPW1nSl49poFDXty0lfBRYbmNsHDDU1oLjspXTM6KsKOeN3iI2qJLJevZoijTtvXpuQHy//K2xZNsQc7ioWy3RbpZ/J5yO3WNTKpV34e5s0ipayYWYQtiD+CC/nE0TGtpq1x0PnD/vydwDYFaDlvRSuStMnUvZhNaw3tsYY9VCxSNsieGUK9QqIyjOYdX3Kr5aOCMcq5gO/gwhnbQFw==" Dec 06 16:27:12 volumio go-librespot[4354]: time="2025-12-06T16:27:12-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:12 volumio go-librespot[4354]: time="2025-12-06T16:27:12-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:12 volumio go-librespot[4354]: time="2025-12-06T16:27:12-06:00" level=debug msg="completed challenge" Dec 06 16:27:12 volumio go-librespot[4354]: time="2025-12-06T16:27:12-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:12 volumio volumio[3908]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:27:12 volumio sudo[4362]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:27:12 volumio sudo[4362]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:12 volumio sudo[4362]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:12 volumio volumio[3908]: info: Completed starting Core Plugins Dec 06 16:27:12 volumio volumio[3908]: info: ------------------------------------------- Dec 06 16:27:12 volumio volumio[3908]: info: ----- MyVolumio plugins startup ---- Dec 06 16:27:12 volumio volumio[3908]: info: ------------------------------------------- Dec 06 16:27:12 volumio volumio[3908]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 06 16:27:12 volumio sudo[4366]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:27:12 volumio sudo[4366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:12 volumio sudo[4368]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:27:12 volumio sudo[4368]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:12 volumio sudo[4371]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:27:12 volumio sudo[4371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:12 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 06 16:27:12 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 06 16:27:12 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 06 16:27:12 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 06 16:27:12 volumio sudo[4366]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:12 volumio mpd_monitor.sh[4374]: MPD Monitor Service: Starting MPD Monitor Service Dec 06 16:27:12 volumio sudo[4368]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:12 volumio volumio[3908]: info: Successfully started MPD Monitor Dec 06 16:27:12 volumio sudo[4371]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:12 volumio volumio[3908]: info: Successfully started MPD Monitor Dec 06 16:27:12 volumio volumio[3908]: info: Successfully started MPD Monitor Dec 06 16:27:13 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:13 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 06 16:27:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:15 volumio go-librespot[4378]: go-librespot daemon starting... Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="app state loaded" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=info msg="zeroconf server listening on port 37027" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="obtained new client token: AACHPXjycpSsiI/XRT1IU3D1UAj+VXhtdo1pJfh4DPoFBoNJYMAbZL17+VQ3kxmws8aMjwiPDawGKVUPuCEzLDnwBHBUvs0+hVnOOAjbIUTtdmBRJkyqcO/UrWhabvXp7/8fYK7uK7PenwZNgmYX+OuaGzxG6kF1/N0kgC3SD/1MITup8R5pzTkHRHSE5XNoCKHppu2oqa4W6w3xJpQ92tfCbi+nIIZxFo+KS1t9BqcQKx+WdbCOiBKRxA==" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=debug msg="completed challenge" Dec 06 16:27:15 volumio go-librespot[4379]: time="2025-12-06T16:27:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:16 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:17 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 06 16:27:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:18 volumio go-librespot[4387]: go-librespot daemon starting... Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="app state loaded" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=info msg="zeroconf server listening on port 37909" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="obtained new client token: AADhDUmAQzo+KgwxnDZfm5F6KGEia3OTp06zaLqZiZ4gyCnkv2/fzVLbjRpYH+fRFS7IVVtuJLkQjKaTOaFDblUAq+9X1OymCpdo+DtxMvgs0C+JZw5uhXaUPqKRITjQzw/nIKP9px4aVS1JkdE0UaFfbNsWDuNMJDo8jtYqLS7BJ8VI0FZuIQqYwJBBEaHJsmUJhWfToBGV7s9wffgYLC/l3gStLmrqwqG7AaCNy658KohThnG3loqZSQ==" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=debug msg="completed challenge" Dec 06 16:27:19 volumio go-librespot[4388]: time="2025-12-06T16:27:19-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 06 16:27:20 volumio volumio[3908]: info: Adding plugin bluetooth to MyMusic Plugins Dec 06 16:27:20 volumio volumio[3908]: info: Adding plugin multiroom to MyMusic Plugins Dec 06 16:27:20 volumio volumio[3908]: info: Adding plugin metavolumio to MyMusic Plugins Dec 06 16:27:20 volumio volumio[3908]: info: Adding plugin cd_controller to MyMusic Plugins Dec 06 16:27:20 volumio volumio[3908]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 06 16:27:20 volumio volumio[3908]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 06 16:27:20 volumio volumio[3908]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 06 16:27:20 volumio volumio[3908]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 06 16:27:21 volumio volumio[3908]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 06 16:27:21 volumio volumio[3908]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 06 16:27:21 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:21 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:21 volumio volumio[3908]: info: Starting MyVolumio Remote Streaming Endpoints Dec 06 16:27:21 volumio volumio[3908]: info: MyVolumio login type: Token Dec 06 16:27:21 volumio volumio[3908]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 06 16:27:21 volumio volumio[3908]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 06 16:27:22 volumio volumio[3908]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 06 16:27:22 volumio volumio[3908]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 06 16:27:22 volumio volumio[3908]: info: Streaming services startup Dec 06 16:27:22 volumio volumio[3908]: info: Starting Streaming Daemon Dec 06 16:27:22 volumio sudo[4410]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:27:22 volumio sudo[4410]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:22 volumio volumio[3908]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 06 16:27:22 volumio sudo[4410]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:22 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:22 volumio volumio[3908]: error: Cannot start Volumio Streaming Daemon Dec 06 16:27:22 volumio volumio[3908]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 16:27:22 volumio volumio[3908]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 16:27:22 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 06 16:27:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:22 volumio go-librespot[4416]: go-librespot daemon starting... Dec 06 16:27:22 volumio go-librespot[4417]: time="2025-12-06T16:27:22-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:22 volumio go-librespot[4417]: time="2025-12-06T16:27:22-06:00" level=debug msg="app state loaded" Dec 06 16:27:22 volumio go-librespot[4417]: time="2025-12-06T16:27:22-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:22 volumio go-librespot[4417]: time="2025-12-06T16:27:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:22 volumio volumio[3908]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=info msg="zeroconf server listening on port 32815" Dec 06 16:27:23 volumio volumio[3908]: info: MyVolumio token set successfully Dec 06 16:27:23 volumio volumio[3908]: info: MYVOLUMIO: Adding device Dec 06 16:27:23 volumio volumio[3908]: info: MYVOLUMIO: Evaluating Server Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=debug msg="obtained new client token: AABbzbkICOdxDgzxqQm+eFbkpAc6Go4QWmQS0n+HF94aGTuAeI1WcIvHKei9knZ8FxtSVNCQt/vmTCI2Pt1N4iY6HAMjEB55IxDTpI4c6SgPZDXAlaUHwi6Rfj397DnhiLmuv025YX2OjwW2EIVWPBD94QCTuFzwqGQZGRBh+6KsfvyZ9FKNVDu4hrZYAjyyHqH1z67zs9BWmnmw5ea4yqCaYO3VxsjQlQHM+uEaNuJ0TrumiE19FSM=" Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=debug msg="completed challenge" Dec 06 16:27:23 volumio go-librespot[4417]: time="2025-12-06T16:27:23-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:23 volumio volumio[3908]: info: MyVolumio status changed Dec 06 16:27:23 volumio volumio[3908]: info: Streaming services startup Dec 06 16:27:23 volumio volumio[3908]: info: Starting Streaming Daemon Dec 06 16:27:23 volumio volumio[3908]: info: Removing browser output: myVolumio user plan is not superstar Dec 06 16:27:23 volumio volumio[3908]: info: Removing audio output: Dec 06 16:27:23 volumio volumio[3908]: info: Stoppping Tunnel 1 Dec 06 16:27:23 volumio sudo[4445]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:27:23 volumio sudo[4445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:23 volumio sudo[4447]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 06 16:27:23 volumio sudo[4447]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:27:23 volumio sudo[4445]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:23 volumio volumio[3908]: error: Cannot start Volumio Streaming Daemon Dec 06 16:27:23 volumio volumio[3908]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 16:27:23 volumio volumio[3908]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 16:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:27:23 volumio sudo[4447]: pam_unix(sudo:session): session closed for user root Dec 06 16:27:23 volumio volumio[3908]: info: Remote SSH Stopped Dec 06 16:27:23 volumio volumio[3908]: info: Setting Geolocation for MyVolumio to us1 Dec 06 16:27:23 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:23 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:23 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:23 volumio volumio[3908]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 06 16:27:24 volumio volumio[3908]: info: Updating MyVolumio device info Dec 06 16:27:24 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:24 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:24 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:24 volumio volumio[3908]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 06 16:27:25 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:25 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 06 16:27:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:26 volumio go-librespot[4450]: go-librespot daemon starting... Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="app state loaded" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=info msg="zeroconf server listening on port 34553" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="obtained new client token: AAAMHP3nZzrcyVyzLF4KLJDXCCKvR7byTWOptr5VhzqnEBce+jnfkMjTJs41ADA4JvoDzRs07TWCn7HOZ6UB+LPEFA+CwqYbf9Kyci+96T3mg+A/pbRuSrxlD4dRtF2yMmnamCqjjeUAVvhC2XmFsZsGd/MmLlPUyf9WuozF66vqCZAI+UKf8yEwpT9hd8JfoR9c2pq6gO0Qq9+eaqzP4GQ8kdFWNepg0B0vJHbXiumhDAZiz4p+zsdqdQ==" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:26 volumio go-librespot[4451]: time="2025-12-06T16:27:26-06:00" level=debug msg="completed challenge" Dec 06 16:27:27 volumio go-librespot[4451]: time="2025-12-06T16:27:27-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:27 volumio volumio[3908]: info: MYVOLUMIO: Adding device Dec 06 16:27:27 volumio volumio[3908]: info: MYVOLUMIO: Evaluating Server Dec 06 16:27:28 volumio volumio[3908]: info: Setting Geolocation for MyVolumio to us1 Dec 06 16:27:28 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:28 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:28 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:28 volumio volumio[3908]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 06 16:27:28 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:28 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:29 volumio volumio[3908]: info: Updating MyVolumio device info Dec 06 16:27:29 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:29 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:29 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:29 volumio volumio[3908]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 06 16:27:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 06 16:27:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:30 volumio go-librespot[4476]: go-librespot daemon starting... Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="app state loaded" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=info msg="zeroconf server listening on port 32815" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="obtained new client token: AABpSHq9wgGPg4+UaF3jQkcOq5wQsqDfMipDx6aBVCrYW+XOFleKMmnaiVvRxIZmVGYdxTupMFEQPAU0pVY4THt7rqnIvClqbjEXAwdKs3/vQo22BNXnC6gIR+ajjdWtnEqJZYe5msZEk7nEKugAoh6StAKSf0Ld6fLxqUjG7fWEEVPoSdIiUnlDi+LEhDF/A7DU+c36gVssezksOKvZebH/wqBezQpKQcc+mjWSNgZ5LMRRHtY6sUwJXA==" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=debug msg="completed challenge" Dec 06 16:27:30 volumio go-librespot[4477]: time="2025-12-06T16:27:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:31 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:31 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:33 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:27:33 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:33 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 06 16:27:33 volumio volumio-remote-updater[2353]: Test mode disabled Dec 06 16:27:33 volumio volumio-remote-updater[2353]: Alpha mode disabled Dec 06 16:27:33 volumio volumio-remote-updater[2353]: Alpha legacy test mode disabled Dec 06 16:27:33 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 06 16:27:33 volumio volumio[3908]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

ANNOUNCEMENT

\n
    \n
  • Production line
    • \n
\n

FIX

\n
    \n
  • Nodejs 20.5.1 version pinning with static package fallback
    • \n
\n","title":"Update v4.073","updateavailable":true} Dec 06 16:27:33 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 06 16:27:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 06 16:27:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:33 volumio go-librespot[4506]: go-librespot daemon starting... Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="app state loaded" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=info msg="zeroconf server listening on port 46569" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="obtained new client token: AABzJMdRMrwOs9oAZJWqb+VE1+ceYN8KU1UGP4KFcQVrMG1oqTOIfciss3Tof4sArWKaRrKDp8kQ2V2hq+CB+q0UUzzEYbB+Qgt3gGRfLMvA4tdlCmfXvsaRHSi3JXKkcrPt2qNJT57FGMVnRDQvClkUntx4tdszm8DVGL2i9A+SDGM3aeRcLa/5tDNNRRo0Mvzj4leckhd9F7dlWRi3bf1MgqiSp5uszkjsHOltXwUJjg44iLxvIVdZNA==" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=debug msg="completed challenge" Dec 06 16:27:34 volumio go-librespot[4507]: time="2025-12-06T16:27:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:34 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:34 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:36 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 06 16:27:36 volumio volumio[3908]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 06 16:27:36 volumio volumio[3908]: info: CoreCommandRouter::volumioGetState Dec 06 16:27:36 volumio volumio[3908]: info: CorePlayQueue::getTrack 0 Dec 06 16:27:37 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:37 volumio volumio[3908]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 06 16:27:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:37 volumio go-librespot[4514]: go-librespot daemon starting... Dec 06 16:27:37 volumio go-librespot[4515]: time="2025-12-06T16:27:37-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:37 volumio go-librespot[4515]: time="2025-12-06T16:27:37-06:00" level=debug msg="app state loaded" Dec 06 16:27:37 volumio go-librespot[4515]: time="2025-12-06T16:27:37-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:37 volumio go-librespot[4515]: time="2025-12-06T16:27:37-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:40 volumio volumio[3908]: info: Initializing connection to go-librespot Websocket Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=debug msg="new websocket client" Dec 06 16:27:40 volumio volumio[3908]: info: Connection to go-librespot Websocket established Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=info msg="zeroconf server listening on port 46251" Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=debug msg="obtained new client token: AADmr8hC7xJhz6RSx9MEcCfKPCm5OuyHnedzOCb8UO3IA3oPszw/hZcOF6wbet/zMZJ1dzPO1rhPOpD6wHU0oEFj5ravlPyLRaw6wSKd6vnHIiHCZRItFUJ44Rjv9JpCs+/rISd8oy72JyyFHeThnjZUEOin2N4Hk7m3Ik8hrIuZG6dnxrAJDEnslyd+vyxr6sZ/iMumE4Tp0hy5rH7dn1wFmtcFWtzUp1a88yBWs2eDlbY4ecToMAEvRQ==" Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=debug msg="completed challenge" Dec 06 16:27:40 volumio go-librespot[4515]: time="2025-12-06T16:27:40-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:27:40 volumio volumio[3908]: info: Connection to go-librespot Websocket closed Dec 06 16:27:41 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:41 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:41 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 06 16:27:41 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 06 16:27:41 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 06 16:27:41 volumio volumio[3908]: info: CoreCommandRouter::volumioGetBrowseSources Dec 06 16:27:41 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:27:42 volumio volumio[3908]: error: MyVolumio Plugin failed to authenticate in a timely fashion Dec 06 16:27:42 volumio volumio[3908]: info: Completed starting MyVolumio Plugin Dec 06 16:27:42 volumio volumio[3908]: [Metrics] CommandRouter: 54s 9.65ms Dec 06 16:27:42 volumio volumio[3908]: info: CoreCommandRouter::volumiosetStartupVolume Dec 06 16:27:42 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:27:42 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:27:42 volumio volumio[3908]: info: CoreCommandRouter::Close All Modals sent Dec 06 16:27:42 volumio volumio[3908]: info: CoreCommandRouter::Close All Modals sent Dec 06 16:27:43 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 06 16:27:43 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 06 16:27:43 volumio volumio[3908]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 06 16:27:43 volumio volumio[3908]: info: Getting Spotify volume Dec 06 16:27:43 volumio volumio[3908]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:27:43 volumio volumio[3908]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:27:43 volumio volumio[3908]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 06 16:27:43 volumio volumio[3908]: errno: -111, Dec 06 16:27:43 volumio volumio[3908]: code: 'ECONNREFUSED', Dec 06 16:27:43 volumio volumio[3908]: syscall: 'connect', Dec 06 16:27:43 volumio volumio[3908]: address: '127.0.0.1', Dec 06 16:27:43 volumio volumio[3908]: port: 9879, Dec 06 16:27:43 volumio volumio[3908]: response: undefined Dec 06 16:27:43 volumio volumio[3908]: } Dec 06 16:27:43 volumio volumio[3908]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:27:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Dec 06 16:27:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:27:44 volumio go-librespot[4554]: go-librespot daemon starting... Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="app state loaded" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="stored credentials not found" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=info msg="zeroconf server listening on port 43391" Dec 06 16:27:44 volumio sudo[4564]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 16:26' Dec 06 16:27:44 volumio sudo[4564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="obtained new client token: AAAlET73ERZg0O7OVBfL1LnL179jxGHdyJ3FwLs3r5diLdXyTWJPycovSOtKSBMtFhaQ4OU6U3Jyt9nx+n7m8yxWOQ+9ZRMXdxWpGoZJihOUVwDsZIdowVsQbTwf9jc3SA1ATEkbvLR2Q19OjbKHUA78Xgw66a11VSpd8tZFqqdtR+1T9YPNR3mH6lkoJwnP0/33UJxGXpQf7UQfho8y/3KQ/izqsLR9H9fyeiLKPNd0QIYjFvd23D0xGg==" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="completed keyexchange" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=debug msg="completed challenge" Dec 06 16:27:44 volumio go-librespot[4555]: time="2025-12-06T16:27:44-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:27:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:27:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. 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="ac7dd5922ede329d1459d48b226ddc71f5209a2c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="3441cddd43405c36fe444484553f10f2f5bc830b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Nov 13 11:04:27 UTC 2025" VOLUMIO_VERSION="4.069" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7da8d6d9f8baf8621af4ec2af5a00f00"