Dec 26 14:11:02 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 26 14:11:02 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:02 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:02 paulin go-librespot[2158]: go-librespot daemon starting... Dec 26 14:11:02 paulin go-librespot[2159]: time="2025-12-26T14:11:02-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:02 paulin go-librespot[2159]: time="2025-12-26T14:11:02-03:00" level=debug msg="app state loaded" Dec 26 14:11:02 paulin go-librespot[2159]: time="2025-12-26T14:11:02-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:03 paulin go-librespot[2159]: time="2025-12-26T14:11:03-03: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 26 14:11:03 paulin go-librespot[2159]: time="2025-12-26T14:11:03-03: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 26 14:11:03 paulin go-librespot[2159]: time="2025-12-26T14:11:03-03: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 26 14:11:03 paulin go-librespot[2159]: time="2025-12-26T14:11:03-03:00" level=info msg="zeroconf server listening on port 44893" Dec 26 14:11:03 paulin volumio[1768]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 26 14:11:03 paulin volumio[1768]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 26 14:11:03 paulin volumio[1768]: info: Streaming services startup Dec 26 14:11:03 paulin volumio[1768]: info: Starting Streaming Daemon Dec 26 14:11:03 paulin sudo[2167]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 26 14:11:03 paulin sudo[2167]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:03 paulin go-librespot[2159]: time="2025-12-26T14:11:03-03:00" level=debug msg="obtained new client token: AABDg+J02eAIek4uZYBFkHT8XObQosseQ7KMItBez/QIYfafkLXR8yeqvtuJ1lonBahA8Z2n1w6jC+GkdtNZTVxIFEyuq58XBVgoo9Xz6h7YPOaEDEuxDJJgoen1fpUWxBzNG8D4ksyndpzUdomoEJQFwjZq0dbuluBYjyclqfdlrPj9tzI1u8PZ7yVD0Tw2inhxbmGw8AusR6yyCB3E26Gbd1L+5i6+UYTaRX+KgUoQeICLyYHv7u2u3TA=" Dec 26 14:11:03 paulin volumio[1768]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 26 14:11:03 paulin sudo[2167]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:03 paulin go-librespot[2159]: time="2025-12-26T14:11:03-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:03 paulin volumio[1768]: info: Initializing connection to go-librespot Websocket Dec 26 14:11:04 paulin volumio[1768]: error: Cannot start Volumio Streaming Daemon Dec 26 14:11:04 paulin volumio[1768]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 26 14:11:04 paulin volumio[1768]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 26 14:11:04 paulin go-librespot[2159]: time="2025-12-26T14:11:04-03:00" level=debug msg="new websocket client" Dec 26 14:11:04 paulin volumio[1768]: info: Connection to go-librespot Websocket established Dec 26 14:11:04 paulin volumio[1768]: error: MyVolumio Custom Token format not valid, refreshing it Dec 26 14:11:05 paulin sudo[2177]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 14:11:05 paulin sudo[2177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:05 paulin sudo[2178]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 14:11:05 paulin sudo[2178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:05 paulin sudo[2177]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:05 paulin sudo[2178]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:05 paulin volumio[1768]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.17 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 4 Dec 26 14:11:05 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 26 14:11:06 paulin go-librespot[2159]: time="2025-12-26T14:11:06-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:06 paulin go-librespot[2159]: time="2025-12-26T14:11:06-03:00" level=debug msg="completed challenge" Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::volumioGetVisibleSources Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::volumioGetState Dec 26 14:11:06 paulin volumio[1768]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 26 14:11:06 paulin volumio[1768]: info: Received Get System Info Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 14:11:06 paulin volumio[1768]: info: Discovery: Getting this device information Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::volumioGetState Dec 26 14:11:06 paulin volumio[1768]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::volumioGetState Dec 26 14:11:06 paulin volumio[1768]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:06 paulin volumio[1768]: info: Listing playlists Dec 26 14:11:06 paulin go-librespot[2159]: time="2025-12-26T14:11:06-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:06 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:06 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 26 14:11:06 paulin volumio[1768]: info: Connection to go-librespot Websocket closed Dec 26 14:11:06 paulin volumio[1768]: info: CoreCommandRouter::volumioGetState Dec 26 14:11:06 paulin volumio[1768]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:07 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 26 14:11:07 paulin volumio[1768]: info: Received Get System Info Dec 26 14:11:07 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 14:11:07 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 14:11:07 paulin volumio[1768]: info: Discovery: Getting this device information Dec 26 14:11:07 paulin volumio[1768]: info: CoreCommandRouter::volumioGetState Dec 26 14:11:07 paulin volumio[1768]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:07 paulin volumio[1768]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 14:11:07 paulin volumio[1768]: info: MyVolumio login type: Token Dec 26 14:11:07 paulin volumio[1768]: info: Getting Spotify volume Dec 26 14:11:07 paulin volumio[1768]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 14:11:07 paulin volumio[1768]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 14:11:07 paulin volumio[1768]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 26 14:11:07 paulin volumio[1768]: errno: -111, Dec 26 14:11:07 paulin volumio[1768]: code: 'ECONNREFUSED', Dec 26 14:11:07 paulin volumio[1768]: syscall: 'connect', Dec 26 14:11:07 paulin volumio[1768]: address: '127.0.0.1', Dec 26 14:11:07 paulin volumio[1768]: port: 9879, Dec 26 14:11:07 paulin volumio[1768]: response: undefined Dec 26 14:11:07 paulin volumio[1768]: } Dec 26 14:11:07 paulin volumio[1768]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 14:11:09 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 26 14:11:09 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:09 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:09 paulin go-librespot[2196]: go-librespot daemon starting... Dec 26 14:11:09 paulin go-librespot[2197]: time="2025-12-26T14:11:09-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:09 paulin go-librespot[2197]: time="2025-12-26T14:11:09-03:00" level=debug msg="app state loaded" Dec 26 14:11:09 paulin go-librespot[2197]: time="2025-12-26T14:11:09-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:09 paulin go-librespot[2197]: time="2025-12-26T14:11:09-03: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 26 14:11:09 paulin go-librespot[2197]: time="2025-12-26T14:11:09-03: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 26 14:11:09 paulin go-librespot[2197]: time="2025-12-26T14:11:09-03: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 26 14:11:10 paulin go-librespot[2197]: time="2025-12-26T14:11:10-03:00" level=info msg="zeroconf server listening on port 33345" Dec 26 14:11:10 paulin go-librespot[2197]: time="2025-12-26T14:11:10-03:00" level=debug msg="obtained new client token: AABE3cdoF9XeMhpM7bDvpukPrCtdZbeKbpkg4j5J42wSLL3rs2jXqbNYwwsO8GfWv1uFTHPKu2Mdg0XMnA82WQJzWJ6wQM8PJ87LyuDaPqre/P6kOh1U3dmhjMpQ9IVZ6XBJWApj/NQWLI2M89mVA2vaJzjrYyYr38EFkMGxGMNpYeZZNCa7ooVELPQzJMisuvH/GDjM2kyGf3uz7OzfIGqPiE0ZdK2IYD08waUWjNpItL5UczroqNNw" Dec 26 14:11:10 paulin go-librespot[2197]: time="2025-12-26T14:11:10-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:10 paulin go-librespot[2197]: time="2025-12-26T14:11:10-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:10 paulin go-librespot[2197]: time="2025-12-26T14:11:10-03:00" level=debug msg="completed challenge" Dec 26 14:11:10 paulin go-librespot[2197]: time="2025-12-26T14:11:10-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:10 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:10 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:13 paulin sudo[2221]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 14:10' Dec 26 14:11:13 paulin sudo[2221]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:13 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 26 14:11:13 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:14 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:14 paulin go-librespot[2223]: go-librespot daemon starting... Dec 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03:00" level=debug msg="app state loaded" Dec 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:14 paulin sudo[2221]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03: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 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03: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 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03: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 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03:00" level=info msg="zeroconf server listening on port 38107" Dec 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03:00" level=debug msg="obtained new client token: AACFpXMMqBN6kMPyb2+YX6CMTC1BrfznoIcx7uUm3ucOFeSmThlpiXkzfy9IDg8viGyTTsf2+jaB8bDKlbiDh1oLOsWupIazaU9CEZ9p0OU3JvcHc1+peGeCwZBDPRTNZj5FNeK9p9w4k2VWWzemtJIdtmhJQ1D2yQ6xD8c4sf/VGxS1GolmWvdOmEsrrFgty2Ye+eFAp5M926WeyV/sfYUZkkJrYXXRguQPNFcIeemZLCAZA3v+1gFzF7Y=" Dec 26 14:11:14 paulin go-librespot[2224]: time="2025-12-26T14:11:14-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:15 paulin go-librespot[2224]: time="2025-12-26T14:11:15-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:15 paulin go-librespot[2224]: time="2025-12-26T14:11:15-03:00" level=debug msg="completed challenge" Dec 26 14:11:15 paulin go-librespot[2224]: time="2025-12-26T14:11:15-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:15 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:15 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:16 paulin volumio-remote-updater[657]: [2025-12-26 14:11:16] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Dec 26 14:11:16 paulin volumio-remote-updater[657]: [2025-12-26 14:11:16] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Dec 26 14:11:16 paulin systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:16 paulin systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 26 14:11:16 paulin systemd[1]: volumio.service: Consumed 2min 32.348s CPU time. Dec 26 14:11:16 paulin systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 26 14:11:16 paulin systemd[1]: dynamicswap.service: Deactivated successfully. Dec 26 14:11:16 paulin systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2. Dec 26 14:11:16 paulin systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 26 14:11:16 paulin systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 26 14:11:16 paulin systemd[1]: volumio.service: Consumed 2min 32.348s CPU time. Dec 26 14:11:16 paulin systemd[1]: Started volumio.service - Volumio Backend Module. Dec 26 14:11:16 paulin systemd[1]: dynamicswap.service: Deactivated successfully. Dec 26 14:11:18 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 26 14:11:18 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:18 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:18 paulin go-librespot[2262]: go-librespot daemon starting... Dec 26 14:11:18 paulin go-librespot[2263]: time="2025-12-26T14:11:18-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:18 paulin go-librespot[2263]: time="2025-12-26T14:11:18-03:00" level=debug msg="app state loaded" Dec 26 14:11:18 paulin go-librespot[2263]: time="2025-12-26T14:11:18-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:19 paulin go-librespot[2263]: time="2025-12-26T14:11:19-03: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 26 14:11:19 paulin go-librespot[2263]: time="2025-12-26T14:11:19-03: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 26 14:11:19 paulin go-librespot[2263]: time="2025-12-26T14:11:19-03: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 26 14:11:19 paulin go-librespot[2263]: time="2025-12-26T14:11:19-03:00" level=info msg="zeroconf server listening on port 41447" Dec 26 14:11:19 paulin go-librespot[2263]: time="2025-12-26T14:11:19-03:00" level=debug msg="obtained new client token: AAANiOB5jdmCcygXV0fZ1IgMfpnxpLxY3/iNkU5Nr07YH8P4NA3zAkiTDQkcrxXA2a6ole3K1uxqp4VKwoVHhbkvEAc2L+bMgaUFsttnBr6O0sgWLNJnVk4vdgCJ0vxWGpzFRnNQ9Gm3I45koo3H1L3MiLNVs47PJ28Xu+I1hQvEples4h1w0eHLF0qbl6p3kr+ES0Fcuej3sC1jFrEHNsdA5x3Sa3vh7ZSlJstjbsw8HhRNYUPcV8fDFCY=" Dec 26 14:11:19 paulin go-librespot[2263]: time="2025-12-26T14:11:19-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:20 paulin go-librespot[2263]: time="2025-12-26T14:11:20-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:20 paulin go-librespot[2263]: time="2025-12-26T14:11:20-03:00" level=debug msg="completed challenge" Dec 26 14:11:20 paulin volumio[2248]: info: ------------------------------------------- Dec 26 14:11:20 paulin volumio[2248]: info: ----- Volumio3 ---- Dec 26 14:11:20 paulin volumio[2248]: info: ------------------------------------------- Dec 26 14:11:20 paulin volumio[2248]: info: ----- System startup ---- Dec 26 14:11:20 paulin volumio[2248]: info: ------------------------------------------- Dec 26 14:11:20 paulin go-librespot[2263]: time="2025-12-26T14:11:20-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:20 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:20 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:21 paulin volumio-remote-updater[657]: [2025-12-26 14:11:21] [connect] Successful connection Dec 26 14:11:21 paulin volumio[2248]: info: MYVOLUMIO Environment detected Dec 26 14:11:21 paulin volumio[2248]: info: Plugin folders cleanup Dec 26 14:11:21 paulin volumio[2248]: info: Scanning into folder /volumio/app/plugins/ Dec 26 14:11:21 paulin volumio[2248]: info: Scanning category audio_interface Dec 26 14:11:21 paulin volumio[2248]: info: Scanning category miscellanea Dec 26 14:11:21 paulin volumio[2248]: info: Scanning category music_service Dec 26 14:11:21 paulin volumio[2248]: info: Scanning category plugins.json Dec 26 14:11:21 paulin volumio[2248]: info: Scanning category system_controller Dec 26 14:11:21 paulin volumio[2248]: info: Scanning category user_interface Dec 26 14:11:21 paulin volumio[2248]: info: Scanning into folder /data/plugins/ Dec 26 14:11:21 paulin volumio[2248]: info: Scanning category music_service Dec 26 14:11:21 paulin volumio[2248]: info: Plugin folders cleanup completed Dec 26 14:11:21 paulin volumio[2248]: info: ------------------------------------------- Dec 26 14:11:21 paulin volumio[2248]: info: ----- Core plugins startup ---- Dec 26 14:11:21 paulin volumio[2248]: info: ------------------------------------------- Dec 26 14:11:21 paulin volumio[2248]: info: Loading plugins from folder /volumio/app/plugins/ Dec 26 14:11:21 paulin volumio[2248]: info: Adding plugin upnp to MyMusic Plugins Dec 26 14:11:21 paulin volumio[2248]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 26 14:11:21 paulin volumio[2248]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 26 14:11:21 paulin volumio[2248]: info: Loading plugins from folder /data/plugins/ Dec 26 14:11:21 paulin volumio[2248]: info: Loading plugin "system"... Dec 26 14:11:21 paulin volumio[2248]: info: Loading plugin "appearance"... Dec 26 14:11:23 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 26 14:11:23 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:23 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:23 paulin go-librespot[2284]: go-librespot daemon starting... Dec 26 14:11:23 paulin go-librespot[2285]: time="2025-12-26T14:11:23-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:23 paulin go-librespot[2285]: time="2025-12-26T14:11:23-03:00" level=debug msg="app state loaded" Dec 26 14:11:23 paulin go-librespot[2285]: time="2025-12-26T14:11:23-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:23 paulin volumio[2248]: info: Loading plugin "network"... Dec 26 14:11:23 paulin volumio[2248]: info: Refreshing Cached IP Addresses Dec 26 14:11:23 paulin sudo[2294]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 14:11:23 paulin sudo[2294]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:23 paulin sudo[2294]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:23 paulin volumio[2248]: info: Loading plugin "services"... Dec 26 14:11:23 paulin volumio[2248]: info: Loading plugin "alsa_controller"... Dec 26 14:11:23 paulin sudo[2297]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 14:11:23 paulin sudo[2297]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:23 paulin go-librespot[2285]: time="2025-12-26T14:11:23-03: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 26 14:11:23 paulin go-librespot[2285]: time="2025-12-26T14:11:23-03: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 26 14:11:23 paulin go-librespot[2285]: time="2025-12-26T14:11:23-03: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 26 14:11:23 paulin go-librespot[2285]: time="2025-12-26T14:11:23-03:00" level=info msg="zeroconf server listening on port 46735" Dec 26 14:11:23 paulin sudo[2297]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:23 paulin sudo[2304]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 26 14:11:23 paulin sudo[2304]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:23 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 14:11:23 paulin volumio[2248]: info: Loading plugin "wizard"... Dec 26 14:11:23 paulin volumio[2248]: info: Loading plugin "networkfs"... Dec 26 14:11:23 paulin volumio[2248]: info: Starting Udev Watcher for removable devices Dec 26 14:11:23 paulin go-librespot[2285]: time="2025-12-26T14:11:23-03:00" level=debug msg="obtained new client token: AAAVoBIriP3TV88LSPJSIBOV6T1EJDxcV4hToYVqGjEn97bVnfqj8mNQ7n4bSije12vX4jNYSD7zWhXUlEizj5XsLf5UMEgRuwINr2WAetgikJ1PY3+mazQ57xO4qp0AqbUQM+ShJVl+IWuW5Qs56WBhKbUO7NXhMGT4b3+dRYYA5VM2Ej321p6fTHS6dOumzkUE78FhVOX7XJomsHRmYyEtd6k9hWaXdKcnRgguA5Njf5heb36pV0NW1Ew=" Dec 26 14:11:24 paulin volumio[2248]: info: Ignoring mount for partition: boot Dec 26 14:11:24 paulin volumio[2248]: info: Ignoring mount for partition: volumio Dec 26 14:11:24 paulin volumio[2248]: info: Ignoring mount for partition: volumio_data Dec 26 14:11:24 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 14:11:24 paulin volumio[2248]: info: Loading plugin "volumio_command_line_client"... Dec 26 14:11:24 paulin volumio[2248]: info: Loading plugin "upnp"... Dec 26 14:11:24 paulin volumio[2248]: info: [1766769084036] Starting Upmpd Daemon Dec 26 14:11:24 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 14:11:24 paulin volumio[2248]: info: Loading plugin "my_music"... Dec 26 14:11:24 paulin volumio[2248]: info: Loading plugin "mpd"... Dec 26 14:11:24 paulin go-librespot[2285]: time="2025-12-26T14:11:24-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:24 paulin go-librespot[2285]: time="2025-12-26T14:11:24-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:24 paulin go-librespot[2285]: time="2025-12-26T14:11:24-03:00" level=debug msg="completed challenge" Dec 26 14:11:24 paulin go-librespot[2285]: time="2025-12-26T14:11:24-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:24 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:24 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:24 paulin volumio[2248]: info: Loading plugin "upnp_browser"... Dec 26 14:11:26 paulin sudo[2304]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:27 paulin volumio[2248]: info: Loading plugin "alarm-clock"... Dec 26 14:11:27 paulin volumio[2248]: info: Loading plugin "airplay_emulation"... Dec 26 14:11:27 paulin volumio[2248]: info: Starting Shairport Sync Dec 26 14:11:27 paulin volumio[2248]: info: Loading plugin "last_100"... Dec 26 14:11:27 paulin volumio[2248]: info: Loading plugin "webradio"... Dec 26 14:11:27 paulin volumio[2248]: info: Loading plugin "i2s_dacs"... Dec 26 14:11:27 paulin volumio[2248]: info: I2S DAC not set, start Auto-detection Dec 26 14:11:27 paulin volumio[2248]: info: Loading plugin "volumiodiscovery"... Dec 26 14:11:27 paulin volumio[2248]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 14:11:27 paulin node[2248]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 26 14:11:27 paulin volumio[2248]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 14:11:27 paulin node[2248]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 14:11:27 paulin volumio[2248]: *** WARNING *** For more information see Dec 26 14:11:27 paulin node[2248]: *** WARNING *** For more information see Dec 26 14:11:27 paulin volumio[2248]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 14:11:27 paulin node[2248]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 26 14:11:27 paulin volumio[2248]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 14:11:27 paulin node[2248]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 26 14:11:27 paulin volumio[2248]: *** WARNING *** For more information see Dec 26 14:11:27 paulin node[2248]: *** WARNING *** For more information see Dec 26 14:11:27 paulin volumio[2248]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 26 14:11:27 paulin volumio[2248]: info: Discovery: Started advertising with name: Paulin Dec 26 14:11:27 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 26 14:11:27 paulin volumio[2248]: info: Loading plugin "spop"... Dec 26 14:11:27 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 26 14:11:27 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:27 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:27 paulin go-librespot[2332]: go-librespot daemon starting... Dec 26 14:11:27 paulin go-librespot[2333]: time="2025-12-26T14:11:27-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:27 paulin go-librespot[2333]: time="2025-12-26T14:11:27-03:00" level=debug msg="app state loaded" Dec 26 14:11:27 paulin go-librespot[2333]: time="2025-12-26T14:11:27-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:28 paulin go-librespot[2333]: time="2025-12-26T14:11:28-03: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 26 14:11:28 paulin go-librespot[2333]: time="2025-12-26T14:11:28-03: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 26 14:11:28 paulin go-librespot[2333]: time="2025-12-26T14:11:28-03: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 26 14:11:28 paulin go-librespot[2333]: time="2025-12-26T14:11:28-03:00" level=info msg="zeroconf server listening on port 33831" Dec 26 14:11:28 paulin go-librespot[2333]: time="2025-12-26T14:11:28-03:00" level=debug msg="obtained new client token: AADaRuKUFUcZqKY6eIJ/YGk3M/E9jA5sXGnZWhR0qpEV0W3nNnUZOfVurZ+lnx/7HUoPcey35UMYo8Q/ynckX1lOWsNzLKO7CguDOtH4hIGTIWVA5GO1gZgXKaP0ehlPgVjQV7S0W28KlF8hCONNmNxD6ynnejU5MO3m1bvuEDZoE7tCiF0zXf4YzMhi6PsemuG4ZNhB0Sn51hcwW7+T7HJXv+zXTNgByWKhv09h8B1TRP1DF3HQxMWziv4=" Dec 26 14:11:28 paulin go-librespot[2333]: time="2025-12-26T14:11:28-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:28 paulin go-librespot[2333]: time="2025-12-26T14:11:28-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:28 paulin go-librespot[2333]: time="2025-12-26T14:11:28-03:00" level=debug msg="completed challenge" Dec 26 14:11:29 paulin go-librespot[2333]: time="2025-12-26T14:11:29-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:29 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:29 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:29 paulin volumio[2248]: info: Loading plugin "outputs"... Dec 26 14:11:29 paulin volumio[2248]: info: Loading plugin "albumart"... Dec 26 14:11:29 paulin volumio[2248]: info: Plugin example_plugin is not enabled Dec 26 14:11:29 paulin volumio[2248]: info: Loading plugin "inputs"... Dec 26 14:11:29 paulin volumio[2248]: info: Loading plugin "updater_comm"... Dec 26 14:11:29 paulin volumio[2248]: info: Plugin mpdemulation is not enabled Dec 26 14:11:29 paulin volumio[2248]: info: Loading plugin "rest_api"... Dec 26 14:11:29 paulin volumio[2248]: info: Loading plugin "websocket"... Dec 26 14:11:29 paulin volumio[2248]: info: Starting Socket.io Server version 1.7.4 Dec 26 14:11:29 paulin volumio[2248]: info: Loading i18n strings for locale es Dec 26 14:11:29 paulin volumio[2248]: Updating browse sources language Dec 26 14:11:29 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::initPlayerControls Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: Express server listening on port 3000 Dec 26 14:11:30 paulin volumio[2248]: [Metrics] WebUI: 11s 117.79ms Dec 26 14:11:30 paulin volumio[2248]: info: CoreStateMachine::resetVolumioState Dec 26 14:11:30 paulin volumio[2248]: info: CoreStateMachine::getcurrentVolume Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:30 paulin volumio[2248]: info: Volumio Network Manager: Network status updated: 1 Dec 26 14:11:30 paulin volumio[2248]: info: VolumeController:: Volume=66 Mute =false Dec 26 14:11:30 paulin volumio[2248]: info: CoreStateMachine::pushState Dec 26 14:11:30 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::volumioPushState Dec 26 14:11:30 paulin volumio[2248]: info: CoreStateMachine::updateTrackBlock Dec 26 14:11:30 paulin volumio[2248]: info: CorePlayQueue::getTrackBlock Dec 26 14:11:30 paulin volumio[2248]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 14:11:30 paulin volumio[2248]: info: Reloading queue from file Dec 26 14:11:30 paulin volumio[2340]: Forking 3 albumart workers Dec 26 14:11:31 paulin volumio[2248]: info: CoreStateMachine::setRepeat true single undefined Dec 26 14:11:31 paulin volumio[2248]: info: CoreStateMachine::pushState Dec 26 14:11:31 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:31 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 14:11:31 paulin volumio[2248]: info: CoreCommandRouter::volumioPushState Dec 26 14:11:31 paulin volumio[2248]: info: CoreStateMachine::setRandom null Dec 26 14:11:31 paulin volumio[2248]: info: CoreStateMachine::pushState Dec 26 14:11:31 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:31 paulin volumio[2248]: info: CoreCommandRouter::volumioPushState Dec 26 14:11:31 paulin volumio[2248]: info: Setting Device type: Raspberry PI Dec 26 14:11:31 paulin volumio[2248]: info: VolumeController:: Volume=66 Mute =false Dec 26 14:11:31 paulin volumio[2248]: info: CoreStateMachine::pushState Dec 26 14:11:31 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:31 paulin volumio[2248]: info: CoreCommandRouter::volumioPushState Dec 26 14:11:32 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Dec 26 14:11:32 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:32 paulin volumio[2248]: info: Discovery: adding 2faea66e-cdcc-4cb2-b575-db76a09e79cb Dec 26 14:11:32 paulin volumio[2248]: info: Discovery: Found device Paulin Dec 26 14:11:32 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:11:32 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:32 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:32 paulin go-librespot[2393]: go-librespot daemon starting... Dec 26 14:11:32 paulin go-librespot[2394]: time="2025-12-26T14:11:32-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:32 paulin go-librespot[2394]: time="2025-12-26T14:11:32-03:00" level=debug msg="app state loaded" Dec 26 14:11:32 paulin go-librespot[2394]: time="2025-12-26T14:11:32-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:32 paulin volumio[2248]: info: Completed loading Core Plugins Dec 26 14:11:32 paulin volumio[2248]: info: Preparing to generate the ALSA configuration file Dec 26 14:11:32 paulin volumio[2248]: info: Discovery: this is already registered, 2faea66e-cdcc-4cb2-b575-db76a09e79cb Dec 26 14:11:32 paulin volumio[2248]: info: Discovery: Found device Paulin Dec 26 14:11:32 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:11:32 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:32 paulin go-librespot[2394]: time="2025-12-26T14:11:32-03: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 26 14:11:32 paulin go-librespot[2394]: time="2025-12-26T14:11:32-03: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 26 14:11:32 paulin go-librespot[2394]: time="2025-12-26T14:11:32-03: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 26 14:11:32 paulin go-librespot[2394]: time="2025-12-26T14:11:32-03:00" level=info msg="zeroconf server listening on port 39015" Dec 26 14:11:32 paulin volumio[2248]: info: Asound.conf file unchanged, so no further update is needed Dec 26 14:11:32 paulin volumio[2248]: info: Output device has changed, restarting MPD Dec 26 14:11:33 paulin go-librespot[2394]: time="2025-12-26T14:11:33-03:00" level=debug msg="obtained new client token: AADSZqT5IPcNtEOHGxR3FJ4pinPKy4BZICgZuNCJafrI6FJ/PZf8nwWFnw8ci6rgHihaldtKv3fuKrjmY5fAGqbqElHc8idYQykgZAOwYRHGZeZ2PUS4AQ47K5g/eBqZMH58Y7kTY20xu1Yvos4SdiTE/OV489kb78ybYb2Wx5CtWafrX8QijGfaOznVR83z7sNKUzSIOKSGh/yfuLYpKYYjsS3GuzwT0oAabMGa3Z+YFddvdIoOwTTvLes=" Dec 26 14:11:33 paulin volumio[2248]: info: Output device has changed, restarting Shairport Sync Dec 26 14:11:33 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:33 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:33 paulin sudo[2403]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 14:11:33 paulin go-librespot[2394]: time="2025-12-26T14:11:33-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:33 paulin sudo[2403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:33 paulin sudo[2403]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:33 paulin sudo[2405]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 14:11:33 paulin volumio[2248]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 14:11:33 paulin sudo[2405]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:33 paulin volumio[2248]: info: ___________ START PLUGINS ___________ Dec 26 14:11:33 paulin go-librespot[2394]: time="2025-12-26T14:11:33-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:33 paulin go-librespot[2394]: time="2025-12-26T14:11:33-03:00" level=debug msg="completed challenge" Dec 26 14:11:33 paulin volumio[2248]: info: ControllerMpd::onStart: Initializing MPD Dec 26 14:11:33 paulin volumio[2248]: info: Creating MPD Configuration file Dec 26 14:11:33 paulin systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 26 14:11:33 paulin go-librespot[2394]: time="2025-12-26T14:11:33-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:33 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:33 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:33 paulin systemd[1]: mpd.service: Deactivated successfully. Dec 26 14:11:33 paulin systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 14:11:33 paulin systemd[1]: mpd.service: Consumed 5.516s CPU time. Dec 26 14:11:33 paulin systemd[1]: mpd.socket: Deactivated successfully. Dec 26 14:11:33 paulin systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 14:11:33 paulin systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 14:11:33 paulin volumio-remote-updater[657]: [2025-12-26 14:11:33] [connect] Successful connection Dec 26 14:11:33 paulin systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 14:11:33 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 26 14:11:33 paulin systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 14:11:33 paulin volumio[2248]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 14:11:33 paulin volumio[2248]: info: [1766769093721] CoreMusicLibrary::Adding element Media Servers Dec 26 14:11:33 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 14:11:33 paulin sudo[2413]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 14:11:33 paulin sudo[2413]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:33 paulin sudo[2413]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:33 paulin sudo[2416]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 14:11:33 paulin sudo[2416]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 14:11:33 paulin sudo[2416]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:34 paulin sudo[2417]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 14:11:34 paulin sudo[2417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:34 paulin systemd[1]: mpd.service: Deactivated successfully. Dec 26 14:11:34 paulin systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 14:11:34 paulin systemd[1]: mpd.socket: Deactivated successfully. Dec 26 14:11:34 paulin systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 14:11:34 paulin systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 14:11:34 paulin volumio[2248]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:34 paulin systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 14:11:34 paulin systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 14:11:34 paulin volumio[2248]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 14:11:34 paulin volumio[2248]: info: [1766769094360] CoreMusicLibrary::Adding element Last_100 Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 26 14:11:34 paulin volumio[2248]: info: [1766769094430] CoreMusicLibrary::Adding element Webradio Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 14:11:34 paulin sudo[2444]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 14:11:34 paulin sudo[2444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 14:11:34 paulin sudo[2444]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:34 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 14:11:34 paulin volumio[2248]: info: Initializing BBC Radios Dec 26 14:11:35 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 14:11:35 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:35 paulin volumio[2248]: info: Creating Spotify config file Dec 26 14:11:35 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:36 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Dec 26 14:11:36 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:36 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:36 paulin go-librespot[2461]: go-librespot daemon starting... Dec 26 14:11:36 paulin go-librespot[2462]: time="2025-12-26T14:11:36-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:37 paulin mpd[2447]: 2025-12-26T14:11:37 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 14:11:37 paulin systemd[1]: Started mpd.service - Music Player Daemon. Dec 26 14:11:37 paulin sudo[2417]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:37 paulin sudo[2405]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:37 paulin go-librespot[2462]: time="2025-12-26T14:11:37-03:00" level=info msg="zeroconf server listening on port 41335" Dec 26 14:11:38 paulin volumio[2248]: info: Volumio Calling Home Dec 26 14:11:40 paulin sudo[2476]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 14:11:40 paulin sudo[2476]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:40 paulin volumio[2361]: Starting albumart workers Dec 26 14:11:40 paulin sudo[2476]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:40 paulin sudo[2478]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 14:11:40 paulin sudo[2478]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:40 paulin sudo[2478]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:40 paulin volumio[2248]: info: Completed starting Core Plugins Dec 26 14:11:40 paulin volumio[2248]: info: ------------------------------------------- Dec 26 14:11:40 paulin volumio[2248]: info: ----- MyVolumio plugins startup ---- Dec 26 14:11:40 paulin volumio[2248]: info: ------------------------------------------- Dec 26 14:11:40 paulin volumio[2248]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 26 14:11:40 paulin volumio[2248]: info: MPD Permissions set Dec 26 14:11:40 paulin volumio[2248]: info: MPD Permissions set Dec 26 14:11:41 paulin volumio[2360]: Starting albumart workers Dec 26 14:11:41 paulin volumio[2248]: info: Volumio called home Dec 26 14:11:41 paulin volumio[2248]: info: Spotify config file written Dec 26 14:11:41 paulin volumio[2363]: Starting albumart workers Dec 26 14:11:41 paulin sudo[2484]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 26 14:11:41 paulin sudo[2484]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:42 paulin systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 26 14:11:42 paulin systemd[1]: go-librespot-daemon.service: Killing process 2466 (go-librespot) with signal SIGKILL. Dec 26 14:11:42 paulin systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 26 14:11:42 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:42 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:42 paulin go-librespot[2486]: go-librespot daemon starting... Dec 26 14:11:42 paulin sudo[2484]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:42 paulin go-librespot[2487]: time="2025-12-26T14:11:42-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:42 paulin go-librespot[2487]: time="2025-12-26T14:11:42-03:00" level=debug msg="app state loaded" Dec 26 14:11:42 paulin go-librespot[2487]: time="2025-12-26T14:11:42-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:42 paulin go-librespot[2487]: time="2025-12-26T14:11:42-03: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 26 14:11:42 paulin go-librespot[2487]: time="2025-12-26T14:11:42-03: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 26 14:11:42 paulin go-librespot[2487]: time="2025-12-26T14:11:42-03: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 26 14:11:42 paulin go-librespot[2487]: time="2025-12-26T14:11:42-03:00" level=info msg="zeroconf server listening on port 37731" Dec 26 14:11:42 paulin go-librespot[2487]: time="2025-12-26T14:11:42-03:00" level=debug msg="obtained new client token: AADtIXLYvWS6ekx3aP2A3AF4kYUEchP5OztukAxfsX8iyiy6nkxRQUWWorlTAVmY0Xj2xLHf+NOCXyE3wWKNV+iGAbfXrrD1vhQjhVt4ZR+y2dsUJtBEkWAEMjTWkd93V8rsTnRdGqlRcuoxpxATDUNBFgA0GKa2XY10FyzRcM5LKMpFDspzPRk4W63RhhO8ERUF5Mn9Ib/U9iMKm/L0u0AKT18By4HioYHfin6IQ6RUnAVt06m1XqPSc4M=" Dec 26 14:11:43 paulin go-librespot[2487]: time="2025-12-26T14:11:43-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:43 paulin go-librespot[2487]: time="2025-12-26T14:11:43-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:43 paulin go-librespot[2487]: time="2025-12-26T14:11:43-03:00" level=debug msg="completed challenge" Dec 26 14:11:43 paulin volumio[2248]: error: MPD error: The expression evaluated to a falsy value: Dec 26 14:11:43 paulin volumio[2248]: assert.ok(self.idling) Dec 26 14:11:43 paulin volumio[2248]: error: The expression evaluated to a falsy value: Dec 26 14:11:43 paulin volumio[2248]: assert.ok(self.idling) Dec 26 14:11:43 paulin go-librespot[2487]: time="2025-12-26T14:11:43-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:43 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:43 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:43 paulin volumio[2248]: info: MPD running with PID2447 Dec 26 14:11:43 paulin volumio[2248]: ,establishing connection Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 14:11:43 paulin volumio[2248]: info: No need to fix Spotify hosts Dec 26 14:11:44 paulin volumio[2248]: error: updateQueue error: null Dec 26 14:11:44 paulin volumio[2248]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Dec 26 14:11:44 paulin volumio[2248]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 26 14:11:44 paulin sudo[2520]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 14:11:44 paulin sudo[2520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:44 paulin sudo[2522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 14:11:44 paulin sudo[2522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:44 paulin systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 14:11:44 paulin systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 14:11:44 paulin systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 14:11:45 paulin systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 14:11:45 paulin mpd_monitor.sh[2526]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 14:11:45 paulin systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 14:11:45 paulin systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 14:11:45 paulin systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 14:11:45 paulin sudo[2520]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:45 paulin systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 14:11:45 paulin sudo[2522]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:45 paulin mpd_monitor.sh[2535]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 14:11:45 paulin volumio[2248]: error: updateQueue error: null Dec 26 14:11:45 paulin volumio[2248]: info: Successfully started MPD Monitor Dec 26 14:11:45 paulin volumio[2248]: info: Starting Shairport Sync Dec 26 14:11:45 paulin volumio[2248]: info: Starting Shairport Sync Dec 26 14:11:45 paulin volumio[2248]: info: Starting Shairport Sync Dec 26 14:11:45 paulin sudo[2540]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 14:11:45 paulin sudo[2540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:45 paulin systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 14:11:45 paulin systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 14:11:45 paulin systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 14:11:45 paulin systemd[1]: shairport-sync.service: Consumed 1.764s CPU time. Dec 26 14:11:45 paulin sudo[2545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 14:11:45 paulin sudo[2545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:45 paulin sudo[2542]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 26 14:11:45 paulin sudo[2542]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:45 paulin systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 14:11:45 paulin sudo[2540]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:45 paulin volumio[2248]: info: Successfully started MPD Monitor Dec 26 14:11:45 paulin sudo[2547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 26 14:11:45 paulin systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 26 14:11:45 paulin systemd[1]: shairport-sync.service: Deactivated successfully. Dec 26 14:11:45 paulin systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 14:11:45 paulin sudo[2547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:46 paulin volumio[2248]: info: Shairport-Sync Started Dec 26 14:11:46 paulin volumio[2248]: Error adding Membership: Error: addMembership EINVAL Dec 26 14:11:46 paulin systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 26 14:11:46 paulin sudo[2545]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:46 paulin sudo[2542]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:46 paulin sudo[2547]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:46 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 26 14:11:46 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:46 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:46 paulin go-librespot[2588]: go-librespot daemon starting... Dec 26 14:11:46 paulin volumio[2248]: info: Upmpdcli Daemon Started Dec 26 14:11:46 paulin volumio[2248]: info: Shairport-Sync Started Dec 26 14:11:46 paulin volumio[2248]: info: Shairport-Sync Started Dec 26 14:11:46 paulin go-librespot[2589]: time="2025-12-26T14:11:46-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:46 paulin go-librespot[2589]: time="2025-12-26T14:11:46-03:00" level=debug msg="app state loaded" Dec 26 14:11:46 paulin go-librespot[2589]: time="2025-12-26T14:11:46-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:46 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:11:46 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03: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 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03: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 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03: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 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03:00" level=info msg="zeroconf server listening on port 38747" Dec 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03:00" level=debug msg="obtained new client token: AACyHYHrNMfReS5uIwOGzrFC3i8T9ATO5j92Xxl+Oqi/s0tjtNoUmpjhBUMJjZuD0qG6CYkWZY8LGPy41Q/AL8jss36Y2aXHGWsx2Z9617M+1/KONRGO9C/D/HVvR1LJszeXVnLX9anla6wB7qQrn9EoBkyAaUKXzQPa7UtsIX+ucBkcn7FANhH9ntqxwB+HIkkYHCtk4Bg7gSzCR+s1njfg73LzRLs7CvD+agrmvZeOI1LmU/Rx1BlN" Dec 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:47 paulin volumio[2248]: info: go-librespot daemon successfully initialized Dec 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03:00" level=debug msg="completed challenge" Dec 26 14:11:47 paulin volumio[2248]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 26 14:11:47 paulin go-librespot[2589]: time="2025-12-26T14:11:47-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:47 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:47 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:48 paulin volumio-remote-updater[657]: [2025-12-26 14:11:48] [connect] Successful connection Dec 26 14:11:48 paulin volumio-remote-updater[657]: [2025-12-26 14:11:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766769108 101 Dec 26 14:11:48 paulin volumio[2248]: 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: 2 Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 26 14:11:49 paulin sudo[2604]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 26 14:11:49 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 26 14:11:49 paulin sudo[2604]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:49 paulin sudo[2606]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 26 14:11:50 paulin sudo[2604]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 26 14:11:50 paulin sudo[2606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:11:50 paulin sudo[2606]: pam_unix(sudo:session): session closed for user root Dec 26 14:11:50 paulin volumio[2248]: info: Adding plugin bluetooth to MyMusic Plugins Dec 26 14:11:50 paulin volumio[2248]: info: Adding plugin multiroom to MyMusic Plugins Dec 26 14:11:50 paulin volumio[2248]: info: Adding plugin metavolumio to MyMusic Plugins Dec 26 14:11:50 paulin volumio[2248]: info: Adding plugin cd_controller to MyMusic Plugins Dec 26 14:11:50 paulin volumio[2248]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 26 14:11:50 paulin volumio[2248]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 26 14:11:50 paulin volumio[2248]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 26 14:11:50 paulin volumio[2248]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 26 14:11:50 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 26 14:11:50 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:51 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:51 paulin go-librespot[2609]: go-librespot daemon starting... Dec 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03:00" level=debug msg="app state loaded" Dec 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03: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 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03: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 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03: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 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03:00" level=info msg="zeroconf server listening on port 38773" Dec 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03:00" level=debug msg="obtained new client token: AABnmbH7iMHIjG81HRchsV4vWRMuafyB4mYxx5klFLpCQpd4+HTM+fZuvnVSR4+/T7waONcaO7eXvFunsCr7X+sEWrbyZDS5pJ8g3R+1cifdUMK2Pwf8xPJ/M3j58EofDxkLy/RiWwQ+A6fcPpK55xOyPGdF3vHuOkCMZXUdFUUFHiBe+gfxWUJ92dUA9xRTnpyh25TV5Xgn23NWFGtCM5xWXxVnBVtIDyhjy6eFRkZPGEdnM0tQiHeNTEw=" Dec 26 14:11:51 paulin go-librespot[2610]: time="2025-12-26T14:11:51-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:52 paulin go-librespot[2610]: time="2025-12-26T14:11:52-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:52 paulin go-librespot[2610]: time="2025-12-26T14:11:52-03:00" level=debug msg="completed challenge" Dec 26 14:11:52 paulin go-librespot[2610]: time="2025-12-26T14:11:52-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:52 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:52 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:55 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 26 14:11:55 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:55 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:11:55 paulin go-librespot[2631]: go-librespot daemon starting... Dec 26 14:11:55 paulin go-librespot[2632]: time="2025-12-26T14:11:55-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:11:55 paulin go-librespot[2632]: time="2025-12-26T14:11:55-03:00" level=debug msg="app state loaded" Dec 26 14:11:55 paulin go-librespot[2632]: time="2025-12-26T14:11:55-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:11:55 paulin volumio[2248]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 26 14:11:55 paulin go-librespot[2632]: time="2025-12-26T14:11:55-03: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 26 14:11:55 paulin go-librespot[2632]: time="2025-12-26T14:11:55-03: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 26 14:11:55 paulin go-librespot[2632]: time="2025-12-26T14:11:55-03: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 26 14:11:56 paulin volumio[2248]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 26 14:11:56 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:56 paulin go-librespot[2632]: time="2025-12-26T14:11:56-03:00" level=info msg="zeroconf server listening on port 44299" Dec 26 14:11:56 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:11:56 paulin volumio[2248]: info: Starting MyVolumio Remote Streaming Endpoints Dec 26 14:11:56 paulin go-librespot[2632]: time="2025-12-26T14:11:56-03:00" level=debug msg="obtained new client token: AAA97Pqxqsd4lrBCXmj3ZymWUKsj92bm5qAv7Z64L/5b/3U3CJwbPFjgQUUfkPn/OqasTaXXQFKuNxb1tofzbiQNvTFhJtKEcjdAChFDwUheRNgfi0dP9W8+H8QcC2jWrSKvJ4uq+g6K7uABiTIt9Z4WsOb+1Z4kzATymdqv4kfFHVdtFhFGrPYz2cXp209F/nwokt3JrIdINreuaAVo5aAfD3mTM3Li8E3kR4BLut4kwMWNEL3jQCev" Dec 26 14:11:56 paulin volumio[2248]: info: MyVolumio login type: Token Dec 26 14:11:56 paulin go-librespot[2632]: time="2025-12-26T14:11:56-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:11:56 paulin volumio[2248]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 26 14:11:56 paulin volumio[2248]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 26 14:11:56 paulin go-librespot[2632]: time="2025-12-26T14:11:56-03:00" level=debug msg="completed keyexchange" Dec 26 14:11:56 paulin go-librespot[2632]: time="2025-12-26T14:11:56-03:00" level=debug msg="completed challenge" Dec 26 14:11:56 paulin go-librespot[2632]: time="2025-12-26T14:11:56-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:11:56 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:11:56 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:11:59 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 26 14:11:59 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:12:00 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:12:00 paulin go-librespot[2640]: go-librespot daemon starting... Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="app state loaded" Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03: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 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03: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 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03: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 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=info msg="zeroconf server listening on port 42167" Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="obtained new client token: AAAhuM7XIb812F2ZUzRAuqQHBisDf3oJhcqpICcFo1pYrf54oV33f5k6pB7tVSt31PqX3lze6jQg2VBK7TQTp93RuFdzV4c1I3KOoYbcYNo6Ca0D//AhkXxKRY0rGUqR2Eow8wAI4blLs2jJ+nMCWVhV6XVk8nOZEbEf8WolVSpKwK0xmCpRS7BFxQUB+Ecu4Eu7OigiIG8ifRHqdtDRR5hYHSZLgWxz4h73mHR41evkCsVC4y/SOS9ZHtI=" Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:12:01 paulin go-librespot[2641]: time="2025-12-26T14:12:01-03:00" level=debug msg="completed keyexchange" Dec 26 14:12:01 paulin go-librespot[2641]: time="2025-12-26T14:12:01-03:00" level=debug msg="completed challenge" Dec 26 14:12:01 paulin go-librespot[2641]: time="2025-12-26T14:12:01-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:12:01 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:12:01 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:12:01 paulin volumio[2248]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 26 14:12:01 paulin volumio[2248]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 26 14:12:01 paulin volumio[2248]: info: Streaming services startup Dec 26 14:12:01 paulin volumio[2248]: info: Starting Streaming Daemon Dec 26 14:12:01 paulin volumio[2248]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 26 14:12:01 paulin sudo[2649]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 26 14:12:01 paulin sudo[2649]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:12:01 paulin sudo[2649]: pam_unix(sudo:session): session closed for user root Dec 26 14:12:01 paulin volumio[2248]: info: Initializing connection to go-librespot Websocket Dec 26 14:12:02 paulin volumio[2248]: error: Cannot start Volumio Streaming Daemon Dec 26 14:12:02 paulin volumio[2248]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 26 14:12:02 paulin volumio[2248]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 26 14:12:02 paulin volumio[2248]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 26 14:12:02 paulin volumio[2248]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.11 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 3 Dec 26 14:12:02 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::volumioGetVisibleSources Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:12:03 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 26 14:12:03 paulin volumio[2248]: info: Received Get System Info Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 14:12:03 paulin volumio[2248]: info: Discovery: Getting this device information Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:12:03 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:12:03 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:12:03 paulin volumio[2248]: info: Listing playlists Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 14:12:03 paulin volumio[2248]: error: MyVolumio Custom Token format not valid, refreshing it Dec 26 14:12:04 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 26 14:12:04 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 26 14:12:04 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:12:04 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:12:04 paulin go-librespot[2655]: go-librespot daemon starting... Dec 26 14:12:04 paulin go-librespot[2656]: time="2025-12-26T14:12:04-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:12:04 paulin go-librespot[2656]: time="2025-12-26T14:12:04-03:00" level=debug msg="app state loaded" Dec 26 14:12:04 paulin go-librespot[2656]: time="2025-12-26T14:12:04-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03: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 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03: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 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03: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 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=info msg="zeroconf server listening on port 36269" Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="obtained new client token: AAD7XDOVFkHOGvqgFKnyQgn1O1WAQ7xF7oTLRUfmm+tO8oX3SGUU5LAJhfDZ5y1sJEw/RhZImQrrM1yzZHmmJqNtHT15ivIN2XDOk0kd18n/m1gii/EnNhKZhhnhqe3JZKGxQGIB30BsJ06KSCzroxacD4Eux8h/3oq1BrLWcEKYbUpMEjPbxWI/+7m0LaknhhNcVLJbPYa1iqDud9/O1hj16Mx+AyOxhwDqypW09bWZGs/gqEsDKP6M" Dec 26 14:12:05 paulin sudo[2684]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 14:12:05 paulin sudo[2682]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 14:12:05 paulin sudo[2682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:12:05 paulin sudo[2684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:12:05 paulin sudo[2684]: pam_unix(sudo:session): session closed for user root Dec 26 14:12:05 paulin sudo[2682]: pam_unix(sudo:session): session closed for user root Dec 26 14:12:05 paulin volumio[2248]: info: Initializing connection to go-librespot Websocket Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="completed keyexchange" Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="completed challenge" Dec 26 14:12:05 paulin volumio[2248]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.11 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 4 Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="new websocket client" Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:12:05 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:12:05 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 26 14:12:05 paulin volumio[2248]: info: Connection to go-librespot Websocket established Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::volumioGetVisibleSources Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:12:05 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 26 14:12:05 paulin volumio[2248]: info: Received Get System Info Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 14:12:05 paulin volumio[2248]: info: Discovery: Getting this device information Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:12:06 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:12:06 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:12:06 paulin volumio[2248]: info: Listing playlists Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 14:12:06 paulin volumio[2248]: info: Connection to go-librespot Websocket closed Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 26 14:12:06 paulin volumio[2248]: info: MyVolumio login type: Token Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:12:06 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 26 14:12:06 paulin volumio[2248]: info: Received Get System Info Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 26 14:12:06 paulin volumio[2248]: info: Discovery: Getting this device information Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState Dec 26 14:12:06 paulin volumio[2248]: info: CorePlayQueue::getTrack 0 Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 26 14:12:08 paulin volumio[2248]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 26 14:12:08 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 26 14:12:08 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 26 14:12:08 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 14:12:08 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 26 14:12:08 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 26 14:12:08 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:12:09 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:12:09 paulin go-librespot[2691]: go-librespot daemon starting... Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="app state loaded" Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:12:09 paulin volumio[2248]: info: Getting Spotify volume Dec 26 14:12:09 paulin volumio-remote-updater[657]: Test mode disabled Dec 26 14:12:09 paulin volumio-remote-updater[657]: Alpha mode disabled Dec 26 14:12:09 paulin volumio-remote-updater[657]: Alpha legacy test mode disabled Dec 26 14:12:09 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 26 14:12:09 paulin volumio[2248]: info: Initializing connection to go-librespot Websocket Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03: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 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03: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 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03: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 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=info msg="zeroconf server listening on port 38585" Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="obtained new client token: AAADcO/wGc8rNKs1ssLEBADXECItRtPVGSVNsvMiXxGizcaUKVp0EjC6uqM4bnU1f8jtdrl9z4mUFHYe2IjRSCVUzyICvMpjHLzXkPxkRsMuBCMwl2lsZKcStUd6jcyZonk+exjnPD0W4dwh5IyKrCfCyRGbBylKMTQKK7/dD7FiTkQcbRf1HBCI44jthgRkRgoT+R/+9Eb5WXaKOHlAb2WZJB1dJT98dUvar4hNuRRT0O/iuOUpgfTh4NY=" Dec 26 14:12:09 paulin volumio[2248]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="new websocket client" Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:12:09 paulin volumio[2248]: info: MyVolumio token set successfully Dec 26 14:12:09 paulin volumio[2248]: info: MYVOLUMIO: Adding device Dec 26 14:12:09 paulin volumio[2248]: info: MYVOLUMIO: Evaluating Server Dec 26 14:12:10 paulin go-librespot[2692]: time="2025-12-26T14:12:10-03:00" level=debug msg="completed keyexchange" Dec 26 14:12:10 paulin go-librespot[2692]: time="2025-12-26T14:12:10-03:00" level=debug msg="completed challenge" Dec 26 14:12:10 paulin volumio[2248]: info: Connection to go-librespot Websocket established Dec 26 14:12:10 paulin volumio[2248]: 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 26 14:12:10 paulin go-librespot[2692]: time="2025-12-26T14:12:10-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:12:10 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:12:10 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:12:10 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 26 14:12:11 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 26 14:12:11 paulin volumio[2248]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 14:12:11 paulin volumio[2248]: Error: socket hang up Dec 26 14:12:11 paulin volumio[2248]: at connResetException (node:internal/errors:720:14) Dec 26 14:12:11 paulin volumio[2248]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 26 14:12:11 paulin volumio[2248]: at Socket.emit (node:events:526:35) Dec 26 14:12:11 paulin volumio[2248]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 26 14:12:11 paulin volumio[2248]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 26 14:12:11 paulin volumio[2248]: code: 'ECONNRESET', Dec 26 14:12:11 paulin volumio[2248]: response: undefined Dec 26 14:12:11 paulin volumio[2248]: } Dec 26 14:12:11 paulin volumio[2248]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 14:12:13 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 26 14:12:13 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:12:13 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 26 14:12:13 paulin go-librespot[2738]: go-librespot daemon starting... Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=info msg="running go-librespot 0.4.0" Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=debug msg="app state loaded" Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03: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 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03: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 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03: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 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=info msg="zeroconf server listening on port 35331" Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=debug msg="obtained new client token: AABOEMb/Ob2TBAd0PXO5zuQQoVOEvChSblCWQJPkxT85GBKsBIZoIsXbSX/n4O+JvK1POZ2WCbP/Or1flCUlRzfKRSrtAPoOhW7BsI3pxJ+dhQyo4EBrBmvD1HRnHe6YAl93Swc+l/6EebwdAc8w5+htJhsXjwCcHZ2EKpvyKPF3K8sI4Jr1m9Jd4R3BtJfmNvm7GnQTthf9H/rUkWK6W6wCCs/lcuQep43iHonXI6jImpagLUe1K+Pn" Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=debug msg="completed keyexchange" Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=debug msg="completed challenge" Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 26 14:12:14 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 26 14:12:14 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 26 14:12:17 paulin sudo[2763]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 14:11' Dec 26 14:12:17 paulin sudo[2763]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 14:12:17 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. 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="ec1ce6b3390e13e82b9cc0453f957c4f5298419e" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="8bcc10c3dbcbcb349e9887dc0527d54876b32688" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon Nov 17 16:31:40 UTC 2025" VOLUMIO_VERSION="4.071" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5fbe1bcf6936184712979c0bfaf061f2"