Dec 10 08:23:02 volumiobox volumio[1202]: error: MyVolumio Plugin failed to authenticate in a timely fashion Dec 10 08:23:02 volumiobox volumio[1202]: info: Completed starting MyVolumio Plugin Dec 10 08:23:02 volumiobox volumio[1202]: [Metrics] CommandRouter: 119s 639.30ms Dec 10 08:23:02 volumiobox volumio[1202]: info: CoreCommandRouter::volumiosetStartupVolume Dec 10 08:23:02 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 08:23:02 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 10 08:23:02 volumiobox volumio[1202]: info: CoreCommandRouter::Close All Modals sent Dec 10 08:23:02 volumiobox volumio[1202]: info: CoreCommandRouter::Close All Modals sent Dec 10 08:23:02 volumiobox volumio[1202]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 10 08:23:02 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 10 08:23:03 volumiobox volumio[1202]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Dec 10 08:23:03 volumiobox volumio[1202]: info: FusionDsp - ---- read samplerate from file: 44100 Dec 10 08:23:03 volumiobox volumio[1202]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 10 08:23:03 volumiobox volumio[1202]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Dec 10 08:23:03 volumiobox volumio[1202]: info: FusionDsp - ---- read samplerate from file: 44100 Dec 10 08:23:03 volumiobox volumio[1202]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 10 08:23:05 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 10 08:23:05 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 10 08:23:05 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 10 08:23:05 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 10 08:23:05 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 10 08:23:06 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Dec 10 08:23:06 volumiobox volumio[1202]: info: Received Get System Version Dec 10 08:23:06 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 10 08:23:09 volumiobox volumio[1202]: info: BOOT COMPLETED Dec 10 08:23:11 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:23:17 volumiobox go-librespot[1558]: time="2025-12-10T08:23:17-03:00" level=debug msg="fetched chunk 6/16, size: 524288" uri="spotify:track:1e21WWJUeqFhZhDuakGkdd" Dec 10 08:23:20 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 10 08:23:20 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 10 08:23:20 volumiobox volumio[1202]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 10 08:23:21 volumiobox volumio[1202]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 10 08:23:21 volumiobox go-librespot[1558]: time="2025-12-10T08:23:21-03:00" level=trace msg="sent dealer ping" Dec 10 08:23:21 volumiobox go-librespot[1558]: time="2025-12-10T08:23:21-03:00" level=trace msg="received dealer pong" Dec 10 08:23:29 volumiobox go-librespot[1558]: time="2025-12-10T08:23:29-03:00" level=debug msg="fetched chunk 7/16, size: 524288" uri="spotify:track:1e21WWJUeqFhZhDuakGkdd" Dec 10 08:23:30 volumiobox volumio[1202]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 10 08:23:32 volumiobox upmpdcli[1897]: writing RSA key Dec 10 08:23:39 volumiobox go-librespot[1558]: time="2025-12-10T08:23:39-03:00" level=debug msg="fetched chunk 8/16, size: 524288" uri="spotify:track:1e21WWJUeqFhZhDuakGkdd" Dec 10 08:23:51 volumiobox go-librespot[1558]: time="2025-12-10T08:23:51-03:00" level=trace msg="sent dealer ping" Dec 10 08:23:51 volumiobox go-librespot[1558]: time="2025-12-10T08:23:51-03:00" level=trace msg="received dealer pong" Dec 10 08:23:52 volumiobox go-librespot[1558]: time="2025-12-10T08:23:52-03:00" level=debug msg="fetched chunk 9/16, size: 524288" uri="spotify:track:1e21WWJUeqFhZhDuakGkdd" Dec 10 08:24:05 volumiobox go-librespot[1558]: time="2025-12-10T08:24:05-03:00" level=debug msg="fetched chunk 10/16, size: 524288" uri="spotify:track:1e21WWJUeqFhZhDuakGkdd" Dec 10 08:24:09 volumiobox volumio[1202]: info: Received OAUTH Data Dec 10 08:24:09 volumiobox volumio[1202]: info: Executing Spotify Oauth Login Dec 10 08:24:09 volumiobox volumio[1202]: info: Saving Spotify Refresh Token Dec 10 08:24:09 volumiobox volumio[1202]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 10 08:24:09 volumiobox volumio[1202]: SPOTIFY: BQDLKd8MWNwYgOstXdOkP5BIFdYqTJsR_3MRGliY_BrDEOu7FtnqXL-Lof7nxSfL95RarIChP4Ipz676jMiEBQ0qKWGyBisMJaEuZFlWYT45x8PttXNujSPIhazomkqhTCyZPTW1Rj0jKrfcJmGOnmoch8npYTpkEL2hTujedfkphgKzscLp7b__tDIQFnzqRg4Mx2WmWajJdI8f6O2Wkogv4W_fjHVsqbxzBMNYtXPlnM4JRBwXPKgu_RHBvytXsHf1NyLsWAsCWcOJB69VWShKd9r1Hmv- Dec 10 08:24:09 volumiobox volumio[1202]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 10 08:24:09 volumiobox volumio[1202]: info: New Spotify access token = BQDLKd8MWNwYgOstXdOkP5BIFdYqTJsR_3MRGliY_BrDEOu7FtnqXL-Lof7nxSfL95RarIChP4Ipz676jMiEBQ0qKWGyBisMJaEuZFlWYT45x8PttXNujSPIhazomkqhTCyZPTW1Rj0jKrfcJmGOnmoch8npYTpkEL2hTujedfkphgKzscLp7b__tDIQFnzqRg4Mx2WmWajJdI8f6O2Wkogv4W_fjHVsqbxzBMNYtXPlnM4JRBwXPKgu_RHBvytXsHf1NyLsWAsCWcOJB69VWShKd9r1Hmv- Dec 10 08:24:09 volumiobox volumio[1202]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 10 08:24:10 volumiobox volumio[1202]: SPOTIFY: User informations: {"country":"AR","display_name":"gcariel","email":"gonzalezteruel.cristian@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/gcariel"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/gcariel","id":"gcariel","images":[],"product":"premium","type":"user","uri":"spotify:user:gcariel"} Dec 10 08:24:10 volumiobox volumio[1202]: info: Creating Spotify config file Dec 10 08:24:10 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 08:24:10 volumiobox volumio[1202]: info: Spotify config file written Dec 10 08:24:10 volumiobox sudo[1995]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 10 08:24:10 volumiobox sudo[1995]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 10 08:24:10 volumiobox sudo[1997]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 10 08:24:10 volumiobox sudo[1997]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 10 08:24:10 volumiobox sudo[1995]: pam_unix(sudo:session): session closed for user root Dec 10 08:24:10 volumiobox sudo[1993]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 10 08:24:10 volumiobox sudo[1993]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 10 08:24:10 volumiobox sudo[1993]: pam_unix(sudo:session): session closed for user root Dec 10 08:24:10 volumiobox systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 10 08:24:10 volumiobox systemd[1]: go-librespot-daemon.service: Killing process 1564 (go-librespot) with signal SIGKILL. Dec 10 08:24:10 volumiobox systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 10 08:24:10 volumiobox systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 10 08:24:10 volumiobox systemd[1]: go-librespot-daemon.service: Consumed 11.493s CPU time. Dec 10 08:24:11 volumiobox systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 10 08:24:11 volumiobox go-librespot[2001]: go-librespot daemon starting... Dec 10 08:24:11 volumiobox sudo[1997]: pam_unix(sudo:session): session closed for user root Dec 10 08:24:11 volumiobox go-librespot[2002]: time="2025-12-10T08:24:11-03:00" level=info msg="running go-librespot 0.4.0" Dec 10 08:24:11 volumiobox go-librespot[2002]: time="2025-12-10T08:24:11-03:00" level=debug msg="app state loaded" Dec 10 08:24:11 volumiobox go-librespot[2002]: time="2025-12-10T08:24:11-03:00" level=debug msg="stored credentials not found" Dec 10 08:24:11 volumiobox go-librespot[2002]: time="2025-12-10T08:24:11-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 10 08:24:11 volumiobox kernel: bcm2835-audio bcm2835-audio: failed to close VCHI service connection (status=-11) Dec 10 08:24:11 volumiobox volumio[1202]: info: Connection to go-librespot Websocket closed Dec 10 08:24:11 volumiobox go-librespot[2002]: time="2025-12-10T08:24:11-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 10 08:24:11 volumiobox go-librespot[2002]: time="2025-12-10T08:24:11-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 10 08:24:11 volumiobox go-librespot[2002]: time="2025-12-10T08:24:11-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 10 08:24:11 volumiobox go-librespot[2002]: time="2025-12-10T08:24:11-03:00" level=info msg="zeroconf server listening on port 34781" Dec 10 08:24:12 volumiobox volumio[1202]: verbose: New Socket.io Connection to 192.168.1.19 from 192.168.1.22 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Dec 10 08:24:12 volumiobox volumio[1202]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 10 08:24:12 volumiobox volumio[1202]: SPOTIFY: BQD17ZP7lXDYgffcBSuPe53lnhnGExoQgxZjm9z_dmmrYPKll5ypd1QBrqxhSfZzv2ExvTwn3L-TfTN8xVYk61L4_P5IChuxlbKHC5LX3a5lF-ubCgvkFSKyCzpbvF6ecPMpm7CEz0xiI9-KtoxftXI9LAz6rm7B96IXM1vGloF-wab6TINCxxbYOQublRJU2HFJgkqLvCYsvjNXRogSk4ElTougn-nkp7x-VoAQj55NP5kkzTc0Yj6f5TpluxXmcBsHA6p7zTpnFMCGZaesBQVgPgmMdx4n Dec 10 08:24:12 volumiobox go-librespot[2002]: time="2025-12-10T08:24:12-03:00" level=debug msg="obtained new client token: AADI3HBcRdRr/TvVMRcYgPM1t633uthG0YAsb51IBBk8M3Shfqqi/+lScaLT/cT8LusUX46YcnuafxR8MTMNaL0o1b+eD2lOsTEXAA5bK9HA51z5+J3pVcUzLY4AERnANOBcdSMsbiyyMJcTjH2tbHnTB9Y2dZNHjdk3P+J5iSv2ViY4yxpY/A77bIBLoR/36SNLDCzOwwzOpJSeSlMd+7OexYI6SHJCmOTNrSpBYOfWq1ywqO/rdtRKoKU=" Dec 10 08:24:12 volumiobox volumio[1202]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 10 08:24:12 volumiobox volumio[1202]: info: New Spotify access token = BQD17ZP7lXDYgffcBSuPe53lnhnGExoQgxZjm9z_dmmrYPKll5ypd1QBrqxhSfZzv2ExvTwn3L-TfTN8xVYk61L4_P5IChuxlbKHC5LX3a5lF-ubCgvkFSKyCzpbvF6ecPMpm7CEz0xiI9-KtoxftXI9LAz6rm7B96IXM1vGloF-wab6TINCxxbYOQublRJU2HFJgkqLvCYsvjNXRogSk4ElTougn-nkp7x-VoAQj55NP5kkzTc0Yj6f5TpluxXmcBsHA6p7zTpnFMCGZaesBQVgPgmMdx4n Dec 10 08:24:12 volumiobox volumio[1202]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 10 08:24:12 volumiobox go-librespot[2002]: time="2025-12-10T08:24:12-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 10 08:24:12 volumiobox go-librespot[2002]: time="2025-12-10T08:24:12-03:00" level=debug msg="completed keyexchange" Dec 10 08:24:12 volumiobox go-librespot[2002]: time="2025-12-10T08:24:12-03:00" level=debug msg="completed challenge" Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetVisibleSources Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 10 08:24:12 volumiobox volumio[1202]: info: Received Get System Info Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 10 08:24:12 volumiobox volumio[1202]: info: Discovery: Getting this device information Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:12 volumiobox go-librespot[2002]: time="2025-12-10T08:24:12-03:00" level=info msg="authenticated AP" username="gc***el" Dec 10 08:24:12 volumiobox volumio[1202]: info: Listing playlists Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 10 08:24:12 volumiobox volumio[1202]: info: Received Get System Info Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 10 08:24:12 volumiobox volumio[1202]: info: Discovery: Getting this device information Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 10 08:24:12 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=info msg="authenticated Login5" username="gc***el" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=debug msg="stored credentials" username="gc***el" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=debug msg="initializing zeroconf session" username="gc***el" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=debug msg="dealer connection opened" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=trace msg="starting accesspoint recv loop" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=trace msg="received accesspoint ping" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=trace msg="starting dealer recv loop" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 10 08:24:13 volumiobox go-librespot[2002]: time="2025-12-10T08:24:13-03:00" level=debug msg="received connection id: MTg2OTQ1M2ItNTZl...NjFCQkNCNzE2Ng==" Dec 10 08:24:14 volumiobox ntpd[872]: CLOCK: time stepped by 0.580134 Dec 10 08:24:14 volumiobox ntpd[872]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Dec 10 08:24:14 volumiobox go-librespot[2002]: time="2025-12-10T08:24:14-03:00" level=debug msg="put connect state because NEW_DEVICE" Dec 10 08:24:14 volumiobox go-librespot[2002]: time="2025-12-10T08:24:14-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 10 08:24:14 volumiobox go-librespot[2002]: time="2025-12-10T08:24:14-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 10 08:24:14 volumiobox go-librespot[2002]: time="2025-12-10T08:24:14-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 10 08:24:14 volumiobox go-librespot[2002]: time="2025-12-10T08:24:14-03:00" level=trace msg="received accesspoint pong ack" Dec 10 08:24:14 volumiobox volumio[1202]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 10 08:24:14 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 10 08:24:14 volumiobox volumio[1202]: info: Received Get System Info Dec 10 08:24:14 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 10 08:24:14 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 10 08:24:14 volumiobox volumio[1202]: info: Discovery: Getting this device information Dec 10 08:24:14 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:14 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 10 08:24:16 volumiobox volumio[1202]: info: Initializing connection to go-librespot Websocket Dec 10 08:24:16 volumiobox volumio[1202]: info: go-librespot daemon successfully initialized Dec 10 08:24:17 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 10 08:24:17 volumiobox go-librespot[2002]: time="2025-12-10T08:24:17-03:00" level=debug msg="new websocket client" Dec 10 08:24:17 volumiobox volumio[1202]: info: Connection to go-librespot Websocket established Dec 10 08:24:17 volumiobox volumio[1202]: SPOTIFY: User informations: {"country":"AR","display_name":"gcariel","email":"gonzalezteruel.cristian@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/gcariel"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/gcariel","id":"gcariel","images":[],"product":"premium","type":"user","uri":"spotify:user:gcariel"} Dec 10 08:24:17 volumiobox volumio[1202]: info: Spotify Successfully logged in Dec 10 08:24:17 volumiobox volumio[1202]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 10 08:24:17 volumiobox volumio[1202]: info: [1765365857797] CoreMusicLibrary::Adding element Spotify Dec 10 08:24:17 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 10 08:24:17 volumiobox volumio[1202]: Cannot find translation for source Spotify Dec 10 08:24:19 volumiobox volumio[1202]: info: Initializing connection to go-librespot Websocket Dec 10 08:24:19 volumiobox go-librespot[2002]: time="2025-12-10T08:24:19-03:00" level=debug msg="new websocket client" Dec 10 08:24:19 volumiobox volumio[1202]: info: Connection to go-librespot Websocket established Dec 10 08:24:20 volumiobox volumio[1202]: info: Getting Spotify volume Dec 10 08:24:20 volumiobox volumio[1202]: info: Spotify volume: 100 Dec 10 08:24:20 volumiobox volumio[1202]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 10 08:24:21 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:21 volumiobox volumio[1202]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 10 08:24:22 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 10 08:24:22 volumiobox volumio[1202]: info: Getting Spotify volume Dec 10 08:24:22 volumiobox volumio[1202]: info: Spotify volume: 100 Dec 10 08:24:22 volumiobox volumio[1202]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 10 08:24:23 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:23 volumiobox volumio[1202]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 10 08:24:25 volumiobox kernel: hwmon hwmon1: Voltage normalised Dec 10 08:24:28 volumiobox volumio[1202]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 10 08:24:28 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 10 08:24:28 volumiobox volumio[1202]: info: Creating Spotify config file Dec 10 08:24:28 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 08:24:28 volumiobox volumio[1202]: info: Spotify config file written Dec 10 08:24:28 volumiobox sudo[2053]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 10 08:24:28 volumiobox sudo[2053]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 10 08:24:28 volumiobox systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 10 08:24:28 volumiobox systemd[1]: go-librespot-daemon.service: Killing process 2008 (go-librespot) with signal SIGKILL. Dec 10 08:24:28 volumiobox systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 10 08:24:28 volumiobox systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 10 08:24:28 volumiobox volumio[1202]: info: Connection to go-librespot Websocket closed Dec 10 08:24:28 volumiobox volumio[1202]: info: Connection to go-librespot Websocket closed Dec 10 08:24:28 volumiobox systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 10 08:24:28 volumiobox go-librespot[2055]: go-librespot daemon starting... Dec 10 08:24:28 volumiobox sudo[2053]: pam_unix(sudo:session): session closed for user root Dec 10 08:24:29 volumiobox go-librespot[2056]: time="2025-12-10T08:24:29-03:00" level=info msg="running go-librespot 0.4.0" Dec 10 08:24:29 volumiobox go-librespot[2056]: time="2025-12-10T08:24:29-03:00" level=debug msg="app state loaded" Dec 10 08:24:29 volumiobox go-librespot[2056]: time="2025-12-10T08:24:29-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 10 08:24:29 volumiobox go-librespot[2056]: time="2025-12-10T08:24:29-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 10 08:24:29 volumiobox go-librespot[2056]: time="2025-12-10T08:24:29-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 10 08:24:29 volumiobox go-librespot[2056]: time="2025-12-10T08:24:29-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 10 08:24:29 volumiobox go-librespot[2056]: time="2025-12-10T08:24:29-03:00" level=info msg="zeroconf server listening on port 34301" Dec 10 08:24:29 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 10 08:24:29 volumiobox volumio[1202]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 10 08:24:29 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 10 08:24:30 volumiobox volumio[1202]: info: Received Get System Version Dec 10 08:24:30 volumiobox go-librespot[2056]: time="2025-12-10T08:24:30-03:00" level=debug msg="obtained new client token: AAB/GDXvkmtlT7JenUqyovXbOoYcOLo4aXaKr24oIiq6SztFOb6wzKcc6nLtuuyWYeNgQw7tsMKfg7mRmdlyqUdF6QAVwwcL53j4zStactEKwqaB851qj8zrzb7kjVel9O6gp51xjf9jIhFbkQmyl8uPJRILRP83bT7RmQtxe7yrKi6vubaOyaMazf4BuN/RPJkS6yz1T2RaQgUrb1+h0go+BMEycUVQdlFptZQqFnscqEKf+A/BzChXm7Q=" Dec 10 08:24:30 volumiobox kernel: hwmon hwmon1: Undervoltage detected! Dec 10 08:24:30 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 10 08:24:30 volumiobox volumio[1202]: info: Received Get System Info Dec 10 08:24:30 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 10 08:24:30 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 10 08:24:30 volumiobox volumio[1202]: info: Discovery: Getting this device information Dec 10 08:24:30 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:30 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 10 08:24:30 volumiobox go-librespot[2056]: time="2025-12-10T08:24:30-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 10 08:24:30 volumiobox go-librespot[2056]: time="2025-12-10T08:24:30-03:00" level=debug msg="completed keyexchange" Dec 10 08:24:30 volumiobox go-librespot[2056]: time="2025-12-10T08:24:30-03:00" level=debug msg="completed challenge" Dec 10 08:24:30 volumiobox go-librespot[2056]: time="2025-12-10T08:24:30-03:00" level=info msg="authenticated AP" username="gc***el" Dec 10 08:24:30 volumiobox go-librespot[2056]: time="2025-12-10T08:24:30-03:00" level=info msg="authenticated Login5" username="gc***el" Dec 10 08:24:30 volumiobox go-librespot[2056]: time="2025-12-10T08:24:30-03:00" level=debug msg="initializing zeroconf session" username="gc***el" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="dealer connection opened" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=trace msg="starting accesspoint recv loop" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=trace msg="starting dealer recv loop" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=trace msg="received accesspoint ping" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="received connection id: YmM0MWFiZWItNzQ2...MzY4QkNGMURFNQ==" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="put connect state because NEW_DEVICE" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=trace msg="received accesspoint pong ack" Dec 10 08:24:31 volumiobox volumio[1202]: info: Initializing connection to go-librespot Websocket Dec 10 08:24:31 volumiobox go-librespot[2056]: time="2025-12-10T08:24:31-03:00" level=debug msg="new websocket client" Dec 10 08:24:31 volumiobox volumio[1202]: info: Connection to go-librespot Websocket established Dec 10 08:24:32 volumiobox volumio[1202]: info: go-librespot daemon successfully initialized Dec 10 08:24:34 volumiobox kernel: hwmon hwmon1: Voltage normalised Dec 10 08:24:34 volumiobox volumio[1202]: info: Getting Spotify volume Dec 10 08:24:35 volumiobox volumio[1202]: info: Initializing connection to go-librespot Websocket Dec 10 08:24:35 volumiobox volumio[1202]: info: Spotify volume: 100 Dec 10 08:24:35 volumiobox go-librespot[2056]: time="2025-12-10T08:24:35-03:00" level=debug msg="new websocket client" Dec 10 08:24:35 volumiobox volumio[1202]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 10 08:24:35 volumiobox volumio[1202]: info: Connection to go-librespot Websocket established Dec 10 08:24:35 volumiobox volumio[1202]: info: CoreCommandRouter::volumioGetState Dec 10 08:24:35 volumiobox volumio[1202]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 10 08:24:36 volumiobox kernel: hwmon hwmon1: Undervoltage detected! Dec 10 08:24:37 volumiobox volumio[1202]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 10 08:24:37 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 10 08:24:37 volumiobox volumio[1202]: info: Creating Spotify config file Dec 10 08:24:37 volumiobox volumio[1202]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 10 08:24:37 volumiobox volumio[1202]: info: Spotify config file written Dec 10 08:24:37 volumiobox sudo[2074]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 10 08:24:37 volumiobox sudo[2074]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 10 08:24:38 volumiobox systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 10 08:24:38 volumiobox systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 10 08:24:38 volumiobox systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 10 08:24:38 volumiobox volumio[1202]: info: Getting Spotify volume Dec 10 08:24:38 volumiobox systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 10 08:24:38 volumiobox go-librespot[2076]: go-librespot daemon starting... Dec 10 08:24:38 volumiobox sudo[2074]: pam_unix(sudo:session): session closed for user root Dec 10 08:24:38 volumiobox volumio[1202]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 10 08:24:38 volumiobox go-librespot[2077]: time="2025-12-10T08:24:38-03:00" level=info msg="running go-librespot 0.4.0" Dec 10 08:24:38 volumiobox go-librespot[2077]: time="2025-12-10T08:24:38-03:00" level=debug msg="app state loaded" Dec 10 08:24:38 volumiobox go-librespot[2077]: time="2025-12-10T08:24:38-03:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 10 08:24:38 volumiobox volumio[1202]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 10 08:24:38 volumiobox volumio[1202]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 10 08:24:38 volumiobox volumio[1202]: errno: -111, Dec 10 08:24:38 volumiobox volumio[1202]: code: 'ECONNREFUSED', Dec 10 08:24:38 volumiobox volumio[1202]: syscall: 'connect', Dec 10 08:24:38 volumiobox volumio[1202]: address: '127.0.0.1', Dec 10 08:24:38 volumiobox volumio[1202]: port: 9879, Dec 10 08:24:38 volumiobox volumio[1202]: response: undefined Dec 10 08:24:38 volumiobox volumio[1202]: } Dec 10 08:24:38 volumiobox volumio[1202]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-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 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-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 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-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 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-03:00" level=info msg="zeroconf server listening on port 38203" Dec 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-03:00" level=debug msg="obtained new client token: AABu8IZZGyVaIwhbfbGhyFi/+A8b5uPxL0XZHR6Ph7cwt8h0+MeadHQ8kKymVtFtEJFSMXhthkN22+8vjLhAxSMW9fyrNbtt2HAlkhv2z6pEbc37pGrSTF2Qoeq8VH3iPr81xT5LsiG3S9nzL0HEHoRdpp+DibmcUtwC4J8RPIYPlqDA3kEj18FBLXs70lYOKE4xlr50Ml7RK7PR7N9UV2Vcznzy7BarFTrJA+pddVnIOH3aW1zuPPxd" Dec 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-03:00" level=debug msg="completed keyexchange" Dec 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-03:00" level=debug msg="completed challenge" Dec 10 08:24:39 volumiobox go-librespot[2077]: time="2025-12-10T08:24:39-03:00" level=info msg="authenticated AP" username="gc***el" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=info msg="authenticated Login5" username="gc***el" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="initializing zeroconf session" username="gc***el" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="dealer connection opened" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=trace msg="starting accesspoint recv loop" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=trace msg="starting dealer recv loop" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=trace msg="received accesspoint ping" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="received connection id: MmZmNDJjOWQtMzM5...Q0RCMDgwRUQ4MQ==" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="put connect state because NEW_DEVICE" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 10 08:24:40 volumiobox go-librespot[2077]: time="2025-12-10T08:24:40-03:00" level=trace msg="received accesspoint pong ack" Dec 10 08:24:43 volumiobox go-librespot[2077]: time="2025-12-10T08:24:43-03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 10 08:24:43 volumiobox go-librespot[2077]: time="2025-12-10T08:24:43-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 378" Dec 10 08:24:43 volumiobox go-librespot[2077]: time="2025-12-10T08:24:43-03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 10 08:24:43 volumiobox go-librespot[2077]: time="2025-12-10T08:24:43-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1391" Dec 10 08:24:45 volumiobox go-librespot[2077]: time="2025-12-10T08:24:45-03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 10 08:24:45 volumiobox go-librespot[2077]: time="2025-12-10T08:24:45-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 378" Dec 10 08:24:46 volumiobox kernel: hwmon hwmon1: Voltage normalised Dec 10 08:24:46 volumiobox sudo[2116]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-10 08:23' Dec 10 08:24:46 volumiobox sudo[2116]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"