Feb 17 11:32:03 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:03.986+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:04 garage volumio[1219]: info: Check plugin dependencies Feb 17 11:32:04 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 17 11:32:04 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:04.482+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:04 garage volumio[1219]: info: Checking if plugin already exists Feb 17 11:32:04 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:04.542+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:04 garage volumio[1219]: info: Rename folder Feb 17 11:32:04 garage volumio[1219]: info: Folder /tmp/downloaded_plugin.zip removed Feb 17 11:32:04 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:04.686+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:04 garage volumio[1219]: info: Move to category Feb 17 11:32:23 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:23.545+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:23 garage volumio[1219]: info: Checking if install.sh is present Feb 17 11:32:23 garage volumio[1219]: info: Executing install.sh Feb 17 11:32:24 garage sudo[1947]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/music_service/spop/install.sh Feb 17 11:32:24 garage sudo[1947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 11:32:24 garage volumio[1219]: info: Installing Go-librespot Feb 17 11:32:24 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:24.236+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:24 garage volumio[1219]: info: Checking old vollibrespot installs Feb 17 11:32:24 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:24.328+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:24 garage systemd[1]: Reloading. Feb 17 11:32:26 garage volumio[1219]: info: Downloading daemon Feb 17 11:32:26 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:26.263+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:33 garage volumio[1219]: info: Creating directories Feb 17 11:32:33 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:33.831+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:33 garage volumio[1219]: info: Creating data directory Feb 17 11:32:33 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:33.890+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:33 garage volumio[1219]: info: Creating Start Script Feb 17 11:32:33 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:33.975+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:34 garage systemd[1]: Reloading. Feb 17 11:32:35 garage sudo[1947]: pam_unix(sudo:session): session closed for user root Feb 17 11:32:35 garage volumio[1219]: info: Install script completed Feb 17 11:32:35 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:35.960+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:35 garage volumio[1219]: info: Adding reference to registry Feb 17 11:32:36 garage volumio5-onboarding[1691]: time=2026-02-17T11:32:36.066+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 17 11:32:36 garage volumio[1219]: info: Done installing plugin. Feb 17 11:32:36 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 17 11:32:36 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 17 11:32:36 garage volumio[1219]: Plugin install end detected on script Feb 17 11:32:36 garage volumio[1219]: info: Folder /tmp/plugins removed Feb 17 11:32:36 garage volumio[1219]: info: Folder /tmp/downloaded_plugin.zip removed Feb 17 11:32:36 garage volumio[1219]: info: Folder /data/temp removed Feb 17 11:32:38 garage volumio[1219]: info: Enabling plugin spop Feb 17 11:32:38 garage volumio[1219]: info: Loading plugin "spop"... Feb 17 11:32:44 garage volumio[1219]: info: PLUGIN START: spop Feb 17 11:32:44 garage volumio[1219]: info: Creating Spotify config file Feb 17 11:32:44 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 11:32:44 garage volumio[1219]: info: Done. Feb 17 11:32:45 garage volumio[1219]: info: Spotify config file written Feb 17 11:32:45 garage volumio[1219]: info: No need to fix Spotify hosts Feb 17 11:32:45 garage sudo[2032]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 11:32:45 garage sudo[2032]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 11:32:45 garage systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 17 11:32:45 garage systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 17 11:32:45 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:32:45 garage go-librespot[2034]: go-librespot daemon starting... Feb 17 11:32:45 garage sudo[2032]: pam_unix(sudo:session): session closed for user root Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=info msg="running go-librespot 0.6.2" Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=debug msg="no app state found" Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=debug msg="stored credentials not found" Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=info msg="generated new device id: b3016cfe4a69d053df5ad03b697895d8b56cb6c1" Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 17 11:32:45 garage go-librespot[2035]: time="2026-02-17T11:32:45+01:00" level=info msg="zeroconf server listening on port 43639" Feb 17 11:32:46 garage volumio[1219]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 17 11:32:48 garage volumio[1219]: info: go-librespot daemon successfully initialized Feb 17 11:32:51 garage volumio[1219]: info: Received OAUTH Data Feb 17 11:32:51 garage volumio[1219]: info: Executing Spotify Oauth Login Feb 17 11:32:51 garage volumio[1219]: info: Saving Spotify Refresh Token Feb 17 11:32:51 garage volumio[1219]: info: Initializing connection to go-librespot Websocket Feb 17 11:32:51 garage go-librespot[2035]: time="2026-02-17T11:32:51+01:00" level=debug msg="new websocket client" Feb 17 11:32:51 garage volumio[1219]: info: Connection to go-librespot Websocket established Feb 17 11:32:51 garage volumio[1219]: info: New Spotify access tokenBQB4D3Qv6h... Feb 17 11:32:51 garage volumio[1219]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 17 11:32:52 garage volumio[1219]: SPOTIFY: User informations: {"country":"FR","display_name":"Dam","email":"dam2111@hotmail.fr","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31dwwjcjyxq4ihonoyr6uqdjye3a"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31dwwjcjyxq4ihonoyr6uqdjye3a","id":"31dwwjcjyxq4ihonoyr6uqdjye3a","images":[],"product":"premium","type":"user","uri":"spotify:user:31dwwjcjyxq4ihonoyr6uqdjye3a"} Feb 17 11:32:52 garage volumio[1219]: info: Creating Spotify config file Feb 17 11:32:52 garage sudo[2046]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 17 11:32:52 garage sudo[2046]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 11:32:52 garage sudo[2048]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 17 11:32:52 garage sudo[2048]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 11:32:52 garage sudo[2046]: pam_unix(sudo:session): session closed for user root Feb 17 11:32:52 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 11:32:52 garage sudo[2048]: pam_unix(sudo:session): session closed for user root Feb 17 11:32:52 garage volumio[1219]: info: Spotify config file written Feb 17 11:32:52 garage sudo[2052]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 11:32:52 garage sudo[2052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 11:32:52 garage volumio[1219]: verbose: New Socket.io Connection to 192.168.1.151 from 192.168.1.84 UA: Mozilla/5.0 (Linux; Android 16; Pixel 9a Build/BP4A.260205.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/144.0.7559.132 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Feb 17 11:32:52 garage systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 11:32:52 garage systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 11:32:52 garage systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:32:53 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:32:53 garage go-librespot[2063]: go-librespot daemon starting... Feb 17 11:32:53 garage sudo[2052]: pam_unix(sudo:session): session closed for user root Feb 17 11:32:53 garage volumio[1219]: info: Connection to go-librespot Websocket closed Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=info msg="running go-librespot 0.6.2" Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=debug msg="app state loaded" Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=debug msg="stored credentials not found" Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::volumioGetVisibleSources Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::volumioGetState Feb 17 11:32:53 garage volumio[1219]: info: CorePlayQueue::getTrack 0 Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 17 11:32:53 garage volumio[1219]: info: Received Get System Info Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 11:32:53 garage volumio[1219]: info: Discovery: Getting this device information Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::volumioGetState Feb 17 11:32:53 garage volumio[1219]: info: CorePlayQueue::getTrack 0 Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::volumioGetState Feb 17 11:32:53 garage volumio[1219]: info: CorePlayQueue::getTrack 0 Feb 17 11:32:53 garage volumio[1219]: info: Listing playlists Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 17 11:32:53 garage volumio[1219]: info: New Spotify access tokenBQAvpkAR-K... Feb 17 11:32:53 garage volumio[1219]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=info msg="zeroconf server listening on port 40679" Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=debug msg="obtained new client token: AADsVOls0sEzc9+R9/kMONWnfxipmSjuzNVp44VmVdp9xWlFrFpORAmHa/T0I95OaWHU0jIXNZKgV4HK1a8caP/AffY04V+8zIm48F2jzcwRE/qmkCx+bD36TBwCAZ4XRENwxWs75hysRMHe/TndK4vUs0gNp1nVrI2fe5+LUesCs3MeOlX0yMnqiXPgPbUnxZitLSj//th8gtIsAGsQBpSoW8qriSCxk2nXLWzE0xRrG5QWIyWNpqy6lw==" Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 17 11:32:53 garage go-librespot[2068]: time="2026-02-17T11:32:53+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.1.151:48846->104.199.65.9:4070: read: connection reset by peer" Feb 17 11:32:53 garage volumio[1219]: SPOTIFY: User informations: {"country":"FR","display_name":"Dam","email":"dam2111@hotmail.fr","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31dwwjcjyxq4ihonoyr6uqdjye3a"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31dwwjcjyxq4ihonoyr6uqdjye3a","id":"31dwwjcjyxq4ihonoyr6uqdjye3a","images":[],"product":"premium","type":"user","uri":"spotify:user:31dwwjcjyxq4ihonoyr6uqdjye3a"} Feb 17 11:32:53 garage volumio[1219]: info: Spotify Successfully logged in Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 11:32:53 garage volumio[1219]: info: [1771324373974] CoreMusicLibrary::Adding element Spotify Feb 17 11:32:53 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 11:32:53 garage volumio[1219]: Cannot find translation for source Spotify Feb 17 11:32:54 garage go-librespot[2068]: time="2026-02-17T11:32:54+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 17 11:32:54 garage go-librespot[2068]: time="2026-02-17T11:32:54+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 17 11:32:54 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 17 11:32:54 garage volumio[1219]: info: Received Get System Info Feb 17 11:32:54 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 11:32:54 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 11:32:54 garage volumio[1219]: info: Discovery: Getting this device information Feb 17 11:32:54 garage volumio[1219]: info: CoreCommandRouter::volumioGetState Feb 17 11:32:54 garage volumio[1219]: info: CorePlayQueue::getTrack 0 Feb 17 11:32:54 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 11:32:54 garage volumio[1219]: info: Getting Spotify volume Feb 17 11:32:54 garage volumio[1219]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Feb 17 11:32:54 garage go-librespot[2068]: time="2026-02-17T11:32:54+01:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 17 11:32:55 garage go-librespot[2068]: time="2026-02-17T11:32:55+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 17 11:32:55 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 17 11:32:55 garage volumio[1219]: info: CoreCommandRouter::volumioGetState Feb 17 11:32:55 garage volumio[1219]: info: CorePlayQueue::getTrack 0 Feb 17 11:32:55 garage volumio[1219]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 11:32:55 garage volumio[1219]: SPOTIFY: SPOTIFY VOLUME undefined Feb 17 11:32:55 garage volumio[1219]: SPOTIFY: VOLUMIO VOLUME 100 Feb 17 11:32:55 garage volumio[1219]: info: Aligning Spotify Volume to Volumio Volume Feb 17 11:32:55 garage volumio[1219]: info: CoreCommandRouter::volumioGetState Feb 17 11:32:55 garage volumio[1219]: info: CorePlayQueue::getTrack 0 Feb 17 11:32:55 garage volumio[1219]: info: Setting Spotify Volume from Volumio: 100 Feb 17 11:32:55 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 17 11:32:55 garage volumio[1219]: info: Received Get System Info Feb 17 11:32:55 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 11:32:55 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 11:32:55 garage go-librespot[2068]: time="2026-02-17T11:32:55+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 17 11:32:55 garage volumio[1219]: info: Discovery: Getting this device information Feb 17 11:32:55 garage volumio[1219]: info: CoreCommandRouter::volumioGetState Feb 17 11:32:55 garage volumio[1219]: info: CorePlayQueue::getTrack 0 Feb 17 11:32:55 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 11:32:55 garage go-librespot[2068]: time="2026-02-17T11:32:55+01:00" level=debug msg="completed keyexchange" Feb 17 11:32:55 garage go-librespot[2068]: time="2026-02-17T11:32:55+01:00" level=debug msg="completed challenge" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=info msg="authenticated AP" username="31************************3a" Feb 17 11:32:56 garage volumio[1219]: info: Initializing connection to go-librespot Websocket Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="new websocket client" Feb 17 11:32:56 garage volumio[1219]: info: Connection to go-librespot Websocket established Feb 17 11:32:56 garage volumio[1219]: info: go-librespot daemon successfully initialized Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=info msg="authenticated Login5" username="31************************3a" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="stored credentials" username="31************************3a" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="initializing zeroconf session" username="31************************3a" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="dealer connection opened" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=trace msg="starting accesspoint recv loop" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=trace msg="starting dealer recv loop" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=trace msg="received accesspoint ping" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="received connection id: MWExOTg5MWYtOWU2...NkU1QjAzNjM0Rg==" Feb 17 11:32:56 garage volumio[1219]: info: Spotify volume: 100 Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=trace msg="received accesspoint pong ack" Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="put connect state because NEW_DEVICE" Feb 17 11:32:56 garage volumio[1219]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Feb 17 11:32:56 garage volumio[1219]: info: Sending Spotify command with payload to local API: /player/volume Feb 17 11:32:56 garage go-librespot[2068]: time="2026-02-17T11:32:56+01:00" level=debug msg="update volume requested to 65535/65535" Feb 17 11:32:57 garage go-librespot[2068]: time="2026-02-17T11:32:57+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 17 11:32:57 garage go-librespot[2068]: time="2026-02-17T11:32:57+01:00" level=trace msg="emitting websocket event: volume" Feb 17 11:32:57 garage volumio[1219]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Feb 17 11:32:57 garage volumio[1219]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Feb 17 11:32:59 garage volumio[1219]: info: Getting Spotify volume Feb 17 11:32:59 garage volumio[1219]: info: Initializing connection to go-librespot Websocket Feb 17 11:32:59 garage volumio[1219]: info: Spotify volume: 100 Feb 17 11:32:59 garage go-librespot[2068]: time="2026-02-17T11:32:59+01:00" level=debug msg="new websocket client" Feb 17 11:32:59 garage volumio[1219]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 17 11:32:59 garage volumio[1219]: info: Connection to go-librespot Websocket established Feb 17 11:32:59 garage volumio[1219]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 11:32:59 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 11:32:59 garage volumio[1219]: info: Creating Spotify config file Feb 17 11:32:59 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 11:32:59 garage volumio[1219]: info: CoreCommandRouter::volumioGetState Feb 17 11:32:59 garage volumio[1219]: info: CorePlayQueue::getTrack 0 Feb 17 11:32:59 garage volumio[1219]: info: Spotify config file written Feb 17 11:32:59 garage volumio[1219]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 11:32:59 garage sudo[2080]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 11:32:59 garage sudo[2080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 11:32:59 garage systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 11:32:59 garage systemd[1]: go-librespot-daemon.service: Killing process 2077 (go-librespot) with signal SIGKILL. Feb 17 11:32:59 garage volumio[1219]: info: Connection to go-librespot Websocket closed Feb 17 11:32:59 garage systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 11:32:59 garage systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:32:59 garage volumio[1219]: info: Connection to go-librespot Websocket closed Feb 17 11:32:59 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:32:59 garage go-librespot[2082]: go-librespot daemon starting... Feb 17 11:32:59 garage sudo[2080]: pam_unix(sudo:session): session closed for user root Feb 17 11:32:59 garage go-librespot[2083]: time="2026-02-17T11:32:59+01:00" level=info msg="running go-librespot 0.6.2" Feb 17 11:32:59 garage go-librespot[2083]: time="2026-02-17T11:32:59+01:00" level=debug msg="app state loaded" Feb 17 11:33:00 garage go-librespot[2083]: time="2026-02-17T11:33:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 11:33:00 garage go-librespot[2083]: time="2026-02-17T11:33:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 17 11:33:00 garage go-librespot[2083]: time="2026-02-17T11:33:00+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 17 11:33:00 garage go-librespot[2083]: time="2026-02-17T11:33:00+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 17 11:33:00 garage go-librespot[2083]: time="2026-02-17T11:33:00+01:00" level=info msg="zeroconf server listening on port 36059" Feb 17 11:33:00 garage go-librespot[2083]: time="2026-02-17T11:33:00+01:00" level=debug msg="obtained new client token: AABg4i0kBEx3UehbfnL283DfosXx+ecrpfBOsscK7Jz6F3CqsaUCdvLzQVUstfLM55kCcYCnbUbCCnXoT37Es3dz0fiGahv60pG05/L2sVE8ohHsXNEqRz9uCv1ENKl37Ek5kXc/fJq5dgWZ4mCnE1OAwkgxyKcoYI25Yzr1Rcm07UKHq5aOd5T3UK17lEzhW72qs+L2Svsr2WOlVp4fr1CxLWMaWcxQi/Y9yNB/lubXtLQip9gFiMEOKQ==" Feb 17 11:33:00 garage volumio[1219]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 11:33:00 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 11:33:00 garage volumio[1219]: info: Creating Spotify config file Feb 17 11:33:00 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 11:33:00 garage volumio[1219]: info: Spotify config file written Feb 17 11:33:00 garage go-librespot[2083]: time="2026-02-17T11:33:00+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 17 11:33:00 garage go-librespot[2083]: time="2026-02-17T11:33:00+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 17 11:33:00 garage sudo[2093]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 11:33:00 garage sudo[2093]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 11:33:00 garage systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 11:33:00 garage systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 11:33:00 garage systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:33:00 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:33:00 garage go-librespot[2095]: go-librespot daemon starting... Feb 17 11:33:00 garage sudo[2093]: pam_unix(sudo:session): session closed for user root Feb 17 11:33:00 garage go-librespot[2096]: time="2026-02-17T11:33:00+01:00" level=info msg="running go-librespot 0.6.2" Feb 17 11:33:00 garage go-librespot[2096]: time="2026-02-17T11:33:00+01:00" level=debug msg="app state loaded" Feb 17 11:33:00 garage go-librespot[2096]: time="2026-02-17T11:33:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=info msg="zeroconf server listening on port 38289" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=debug msg="obtained new client token: AADabwNSFNe0xe3SQh9rZbM+j/tEmc9rsYqyA1ry9ul8lQ80cM1R8zqaK0IDew4WWlKFbnduj6MQHSoWQvNFj2gueR12K1wixbtk8QpUxgeaHiBeC2pNhs1JMKhm9sGCueG5FhUnviCxcZc7AAE+savlFWdqfKSItMoBfjJZvP0DJ/JRq+ILfEYaj2ukdHzrp50WZfVu+UQNrJTJ7BXdUDMvO0JONn9em9TjR3279W48/xUTEjP9jkgP3w==" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=debug msg="completed keyexchange" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=debug msg="completed challenge" Feb 17 11:33:01 garage go-librespot[2096]: time="2026-02-17T11:33:01+01:00" level=info msg="authenticated AP" username="31************************3a" Feb 17 11:33:02 garage volumio[1219]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 11:33:02 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 11:33:02 garage volumio[1219]: info: Creating Spotify config file Feb 17 11:33:02 garage volumio[1219]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=info msg="authenticated Login5" username="31************************3a" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=debug msg="initializing zeroconf session" username="31************************3a" Feb 17 11:33:02 garage volumio[1219]: info: Spotify config file written Feb 17 11:33:02 garage sudo[2106]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 11:33:02 garage sudo[2106]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=debug msg="dealer connection opened" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=trace msg="starting accesspoint recv loop" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=trace msg="starting dealer recv loop" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=trace msg="received accesspoint ping" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=debug msg="received connection id: YTk5N2U2ZGQtY2U2...Q0JCQkI4NDdCNg==" Feb 17 11:33:02 garage go-librespot[2096]: time="2026-02-17T11:33:02+01:00" level=trace msg="received accesspoint pong ack" Feb 17 11:33:02 garage systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 11:33:02 garage systemd[1]: go-librespot-daemon.service: Killing process 2097 (go-librespot) with signal SIGKILL. Feb 17 11:33:02 garage systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 11:33:02 garage systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:33:02 garage volumio[1219]: info: Getting Spotify volume Feb 17 11:33:02 garage systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 11:33:02 garage go-librespot[2108]: go-librespot daemon starting... Feb 17 11:33:02 garage sudo[2106]: pam_unix(sudo:session): session closed for user root Feb 17 11:33:02 garage go-librespot[2109]: time="2026-02-17T11:33:02+01:00" level=info msg="running go-librespot 0.6.2" Feb 17 11:33:02 garage go-librespot[2109]: time="2026-02-17T11:33:02+01:00" level=debug msg="app state loaded" Feb 17 11:33:02 garage volumio[1219]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 11:33:02 garage go-librespot[2109]: time="2026-02-17T11:33:02+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 11:33:02 garage volumio[1219]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 17 11:33:02 garage volumio[1219]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 17 11:33:02 garage volumio[1219]: errno: -111, Feb 17 11:33:02 garage volumio[1219]: code: 'ECONNREFUSED', Feb 17 11:33:02 garage volumio[1219]: syscall: 'connect', Feb 17 11:33:02 garage volumio[1219]: address: '127.0.0.1', Feb 17 11:33:02 garage volumio[1219]: port: 9879, Feb 17 11:33:02 garage volumio[1219]: response: undefined Feb 17 11:33:02 garage volumio[1219]: } Feb 17 11:33:02 garage volumio[1219]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 11:33:02 garage go-librespot[2109]: time="2026-02-17T11:33:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 17 11:33:02 garage go-librespot[2109]: time="2026-02-17T11:33:02+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 17 11:33:02 garage go-librespot[2109]: time="2026-02-17T11:33:02+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 17 11:33:02 garage go-librespot[2109]: time="2026-02-17T11:33:02+01:00" level=info msg="zeroconf server listening on port 42159" Feb 17 11:33:03 garage go-librespot[2109]: time="2026-02-17T11:33:03+01:00" level=debug msg="obtained new client token: AAArqp64MZE9AJdJQzzPk+/lOxOTGfO+67tfUmc4c1zBug348pOCwrEKrmt952/V/yj9vzUiENAqQFv/5LalXri7u/hotYyYVJdv3mD8C6oHP36qiqsT6EubUb7rA4m4JPFnP+2/ebTIxQ6m4YEoHU75QKN4RCY9mN5WOI7kXsJTzVFqjBaY0JQNItoYbeVcAjRfdGo3/IaoMIm/jvv+ev8xJnSGVpUuW4wxVoYiMMWeYQW7szt9r5w=" Feb 17 11:33:03 garage go-librespot[2109]: time="2026-02-17T11:33:03+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 17 11:33:03 garage go-librespot[2109]: time="2026-02-17T11:33:03+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 17 11:33:03 garage go-librespot[2109]: time="2026-02-17T11:33:03+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 17 11:33:03 garage go-librespot[2109]: time="2026-02-17T11:33:03+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 17 11:33:04 garage go-librespot[2109]: time="2026-02-17T11:33:04+01:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 17 11:33:04 garage go-librespot[2109]: time="2026-02-17T11:33:04+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 17 11:33:05 garage go-librespot[2109]: time="2026-02-17T11:33:05+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 17 11:33:08 garage sudo[2147]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-17 11:32' Feb 17 11:33:08 garage sudo[2147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"