Dec 15 09:28:00 volumio volumio[1232]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Dec 15 09:28:00 volumio volumio[1232]: info: Sending Spotify command with payload to local API: /player/volume Dec 15 09:28:03 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 15 09:28:03 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 15 09:28:05 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 15 09:28:10 volumio volumio[1232]: info: CoreCommandRouter::Close All Modals sent Dec 15 09:28:10 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: appearance , setTOSAccepted Dec 15 09:28:13 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 15 09:28:13 volumio volumio[1232]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 15 09:28:13 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 15 09:28:13 volumio volumio[1232]: info: Received Get System Version Dec 15 09:28:13 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 15 09:28:13 volumio volumio[1232]: info: Received Get System Info Dec 15 09:28:13 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 15 09:28:13 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 15 09:28:13 volumio volumio[1232]: info: Discovery: Getting this device information Dec 15 09:28:13 volumio volumio[1232]: info: CoreCommandRouter::volumioGetState Dec 15 09:28:13 volumio volumio[1232]: info: CorePlayQueue::getTrack 0 Dec 15 09:28:13 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 15 09:28:15 volumio volumio[1232]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 15 09:28:53 volumio ntpd[1020]: PROTO: 212.132.108.186 unlink local addr 192.168.2.83 -> Dec 15 09:29:11 volumio ntpd[1020]: PROTO: 188.174.253.188 unlink local addr 192.168.2.83 -> Dec 15 09:29:11 volumio volumio[1232]: info: Received OAUTH Data Dec 15 09:29:11 volumio volumio[1232]: info: Executing Spotify Oauth Login Dec 15 09:29:11 volumio volumio[1232]: info: Saving Spotify Refresh Token Dec 15 09:29:12 volumio volumio[1232]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 09:29:12 volumio volumio[1232]: SPOTIFY: BQAeQgd5XkU2bScme3kXbMdVsvUsAQoxbFopQoMVASaL5vXqgrnm2mGMBUJDKLEIEwL-8lOH0oXc6nRfa3a82TpLV9JYlb739nAMrQYch2J6fs0UecGdE5HQ8rhbCkxIOVFdDW1-S43lSViH5AQGMpGvukbLJNII_J19uvPZaeVhWzzAr5mQCpN-xD_3Ae0_Mi4ciTivf3jQ-o8inMljoFLRp_N_Y17CLQcOSAh3P87ZP0dPVcDLHUfCvNzw5JO9kO8WDiN4kykAdn2nqcIVt8R5d8G_X4emkVui8bd4szQ Dec 15 09:29:12 volumio volumio[1232]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 09:29:12 volumio volumio[1232]: info: New Spotify access token = BQAeQgd5XkU2bScme3kXbMdVsvUsAQoxbFopQoMVASaL5vXqgrnm2mGMBUJDKLEIEwL-8lOH0oXc6nRfa3a82TpLV9JYlb739nAMrQYch2J6fs0UecGdE5HQ8rhbCkxIOVFdDW1-S43lSViH5AQGMpGvukbLJNII_J19uvPZaeVhWzzAr5mQCpN-xD_3Ae0_Mi4ciTivf3jQ-o8inMljoFLRp_N_Y17CLQcOSAh3P87ZP0dPVcDLHUfCvNzw5JO9kO8WDiN4kykAdn2nqcIVt8R5d8G_X4emkVui8bd4szQ Dec 15 09:29:12 volumio volumio[1232]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 15 09:29:12 volumio sudo[5091]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 15 09:29:12 volumio sudo[5091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 09:29:12 volumio sudo[5093]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 15 09:29:12 volumio sudo[5091]: pam_unix(sudo:session): session closed for user root Dec 15 09:29:12 volumio sudo[5093]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 09:29:12 volumio sudo[5093]: pam_unix(sudo:session): session closed for user root Dec 15 09:29:12 volumio volumio[1232]: verbose: New Socket.io Connection to 192.168.2.83 from 192.168.2.52 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::volumioGetVisibleSources Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::volumioGetState Dec 15 09:29:12 volumio volumio[1232]: info: CorePlayQueue::getTrack 0 Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 15 09:29:12 volumio volumio[1232]: info: Received Get System Info Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 15 09:29:12 volumio volumio[1232]: info: Discovery: Getting this device information Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::volumioGetState Dec 15 09:29:12 volumio volumio[1232]: info: CorePlayQueue::getTrack 0 Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::volumioGetState Dec 15 09:29:12 volumio volumio[1232]: info: CorePlayQueue::getTrack 0 Dec 15 09:29:12 volumio volumio[1232]: info: Listing playlists Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 15 09:29:12 volumio volumio[1232]: SPOTIFY: User informations: {"country":"DE","display_name":"martin.lange.de","email":"martin.lange.de@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/martin.lange.de"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/martin.lange.de","id":"martin.lange.de","images":[],"product":"premium","type":"user","uri":"spotify:user:martin.lange.de"} Dec 15 09:29:12 volumio volumio[1232]: info: Creating Spotify config file Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 09:29:12 volumio volumio[1232]: info: Spotify config file written Dec 15 09:29:12 volumio sudo[5097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 15 09:29:12 volumio sudo[5097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 09:29:12 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 15 09:29:12 volumio systemd[1]: go-librespot-daemon.service: Killing process 4938 (go-librespot) with signal SIGKILL. Dec 15 09:29:12 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 15 09:29:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 15 09:29:12 volumio volumio[1232]: info: Connection to go-librespot Websocket closed Dec 15 09:29:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 09:29:12 volumio volumio[1232]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 09:29:12 volumio go-librespot[5099]: go-librespot daemon starting... Dec 15 09:29:12 volumio volumio[1232]: SPOTIFY: BQBhQ7AGeeQXy1RAnzq0IEWXHM2E6SUXhTHyKLKM6RtJFhzo04LROkvIDbYo98bKHOn5g_ztVFCybhlPIogMOLu5gGS28suEEKms9zZ3tloMd4QIJ7Xia9_x6fsKgUltqHIUPRGY3wKbbpw-Dczoa1zf1BCb4BxTgF0-3asjrgY4Q6tTRx-u4VY1T_93D1-utUL1mwQXyp04tJ7c6R10Y7i-D0SjHxvw8e7SZGInUTxSCsQdsBHKJkmKD6wqmj26ZZep0-gTlwAjd-5XVFockEm0OyM8jVgGNcjFXb2lE0g Dec 15 09:29:12 volumio volumio[1232]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 15 09:29:12 volumio volumio[1232]: info: New Spotify access token = BQBhQ7AGeeQXy1RAnzq0IEWXHM2E6SUXhTHyKLKM6RtJFhzo04LROkvIDbYo98bKHOn5g_ztVFCybhlPIogMOLu5gGS28suEEKms9zZ3tloMd4QIJ7Xia9_x6fsKgUltqHIUPRGY3wKbbpw-Dczoa1zf1BCb4BxTgF0-3asjrgY4Q6tTRx-u4VY1T_93D1-utUL1mwQXyp04tJ7c6R10Y7i-D0SjHxvw8e7SZGInUTxSCsQdsBHKJkmKD6wqmj26ZZep0-gTlwAjd-5XVFockEm0OyM8jVgGNcjFXb2lE0g Dec 15 09:29:12 volumio volumio[1232]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 15 09:29:12 volumio sudo[5097]: pam_unix(sudo:session): session closed for user root Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=info msg="running go-librespot 0.4.0" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=debug msg="app state loaded" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=debug msg="stored credentials not found" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 09:29:12 volumio volumio[1232]: SPOTIFY: User informations: {"country":"DE","display_name":"martin.lange.de","email":"martin.lange.de@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/martin.lange.de"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/martin.lange.de","id":"martin.lange.de","images":[],"product":"premium","type":"user","uri":"spotify:user:martin.lange.de"} Dec 15 09:29:12 volumio volumio[1232]: info: Spotify Successfully logged in Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 15 09:29:12 volumio volumio[1232]: info: [1765787352544] CoreMusicLibrary::Adding element Spotify Dec 15 09:29:12 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 15 09:29:12 volumio volumio[1232]: Cannot find translation for source Spotify Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=info msg="zeroconf server listening on port 44475" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=debug msg="obtained new client token: AABzyMD4FiaYpCE7YoEWyH3b8+MuN+TzxLOOgq4S+OgpjioJI4c3B6wQR1asBVbjg1IlUDa1YWQ7AYgbl4Hz+F/cdRZneotM+NnaLT6U/lDdJvwjOR1OifRRvzi2TN8fb9ECQGxJR+11WGfpkdDV1ox+Wca9xDncEWNTNEgkgc3lSTo30C0dcX7Nk/xmVbZcFFobJagu0qFzOby3wlBdAiRCjfQ4LcMASfnETlteSQsk+RvTIkBnWm0TOA==" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 15 09:29:12 volumio go-librespot[5101]: time="2025-12-15T09:29:12+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.2.83:39578->34.158.1.133:4070: read: connection reset by peer" Dec 15 09:29:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 09:29:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 09:29:13 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 15 09:29:14 volumio volumio[1232]: info: Received Get System Info Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 15 09:29:14 volumio volumio[1232]: info: Discovery: Getting this device information Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::volumioGetState Dec 15 09:29:14 volumio volumio[1232]: info: CorePlayQueue::getTrack 0 Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 15 09:29:14 volumio volumio[1232]: info: Received Get System Info Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 15 09:29:14 volumio volumio[1232]: info: Discovery: Getting this device information Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::volumioGetState Dec 15 09:29:14 volumio volumio[1232]: info: CorePlayQueue::getTrack 0 Dec 15 09:29:14 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 15 09:29:15 volumio volumio[1232]: info: Initializing connection to go-librespot Websocket Dec 15 09:29:15 volumio volumio[1232]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 15 09:29:15 volumio volumio[1232]: info: go-librespot daemon successfully initialized Dec 15 09:29:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 15 09:29:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 09:29:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 09:29:16 volumio go-librespot[5109]: go-librespot daemon starting... Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=info msg="running go-librespot 0.4.0" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="app state loaded" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="stored credentials not found" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=info msg="zeroconf server listening on port 46729" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="obtained new client token: AADAq35tgtscfcHasW3aXYaU0w0T3Sd03FXUrxmhVBNXOsDDykHICoKso2ZDCtZD5czFgnEIKfrafWm4ZqpKNQUJuXW1xmYu/ZOg3rs3P4u7uhthJUnC/JCJc4o1SoUEZjkIX4pBuaf1FmohvjTVhi51FK4qWQAVU6etg4yfhbMmpygtIw4vJDCCdbeLORsz/LwMu5FrLkdSbYDeO9iVpwVfcR16AtGGZgtBO7dOqMOF17EJmn4UX+4=" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="completed keyexchange" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="completed challenge" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=info msg="authenticated AP" username="ma***********de" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=info msg="authenticated Login5" username="ma***********de" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="stored credentials" username="ma***********de" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="initializing zeroconf session" username="ma***********de" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="dealer connection opened" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=trace msg="starting accesspoint recv loop" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=trace msg="starting dealer recv loop" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=trace msg="received accesspoint ping" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="received connection id: MjU4NWNkZTYtYWM2...RjcxMUE4MEI3QQ==" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=trace msg="received accesspoint pong ack" Dec 15 09:29:16 volumio go-librespot[5110]: time="2025-12-15T09:29:16+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 15 09:29:18 volumio volumio[1232]: info: Initializing connection to go-librespot Websocket Dec 15 09:29:18 volumio go-librespot[5110]: time="2025-12-15T09:29:18+01:00" level=debug msg="new websocket client" Dec 15 09:29:18 volumio volumio[1232]: info: Connection to go-librespot Websocket established Dec 15 09:29:18 volumio volumio[1232]: info: Initializing connection to go-librespot Websocket Dec 15 09:29:18 volumio volumio[1232]: info: Connection to go-librespot Websocket established Dec 15 09:29:18 volumio go-librespot[5110]: time="2025-12-15T09:29:18+01:00" level=debug msg="new websocket client" Dec 15 09:29:18 volumio volumio[1232]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 15 09:29:18 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 15 09:29:18 volumio volumio[1232]: info: Creating Spotify config file Dec 15 09:29:18 volumio volumio[1232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 15 09:29:18 volumio volumio[1232]: info: Spotify config file written Dec 15 09:29:18 volumio sudo[5135]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 15 09:29:18 volumio sudo[5135]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 15 09:29:18 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 15 09:29:18 volumio systemd[1]: go-librespot-daemon.service: Killing process 5113 (go-librespot) with signal SIGKILL. Dec 15 09:29:18 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 15 09:29:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 15 09:29:18 volumio volumio[1232]: info: Connection to go-librespot Websocket closed Dec 15 09:29:18 volumio volumio[1232]: info: Connection to go-librespot Websocket closed Dec 15 09:29:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 15 09:29:18 volumio go-librespot[5137]: go-librespot daemon starting... Dec 15 09:29:18 volumio sudo[5135]: pam_unix(sudo:session): session closed for user root Dec 15 09:29:18 volumio go-librespot[5138]: time="2025-12-15T09:29:18+01:00" level=info msg="running go-librespot 0.4.0" Dec 15 09:29:18 volumio go-librespot[5138]: time="2025-12-15T09:29:18+01:00" level=debug msg="app state loaded" Dec 15 09:29:18 volumio go-librespot[5138]: time="2025-12-15T09:29:18+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 15 09:29:19 volumio go-librespot[5138]: time="2025-12-15T09:29:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 15 09:29:19 volumio go-librespot[5138]: time="2025-12-15T09:29:19+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 15 09:29:19 volumio go-librespot[5138]: time="2025-12-15T09:29:19+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 15 09:29:19 volumio go-librespot[5138]: time="2025-12-15T09:29:19+01:00" level=info msg="zeroconf server listening on port 41303" Dec 15 09:29:19 volumio go-librespot[5138]: time="2025-12-15T09:29:19+01:00" level=debug msg="obtained new client token: AACpQ4A9v9xWBmfnCQ4muOx4FCttBBQf5k3SZJFoTQcn9JnkQmUCMozfBmP4V9DQ2ZXnCpgie17NRyLEzIp2I5G96xxiF5yBegGbYnRk1ink9nuzUXxV1q8ATWlMlA3taBsD8C0kh5STJrHo7BnoYSSaoxU6YqgLI+CSYp0GYLUwHeH4l8ThllY3oEPrAvJqOZVb4pHxNn3W+I8/v5IiYMvkf2Fw89+GQ+BaQBjnvXB7vPQD54wey1g=" Dec 15 09:29:19 volumio go-librespot[5138]: time="2025-12-15T09:29:19+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 15 09:29:19 volumio go-librespot[5138]: time="2025-12-15T09:29:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 15 09:29:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 15 09:29:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 15 09:29:21 volumio volumio[1232]: info: Getting Spotify volume Dec 15 09:29:21 volumio volumio[1232]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 15 09:29:21 volumio volumio[1232]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 15 09:29:21 volumio volumio[1232]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 15 09:29:21 volumio volumio[1232]: errno: -111, Dec 15 09:29:21 volumio volumio[1232]: code: 'ECONNREFUSED', Dec 15 09:29:21 volumio volumio[1232]: syscall: 'connect', Dec 15 09:29:21 volumio volumio[1232]: address: '127.0.0.1', Dec 15 09:29:21 volumio volumio[1232]: port: 9879, Dec 15 09:29:21 volumio volumio[1232]: response: undefined Dec 15 09:29:21 volumio volumio[1232]: } Dec 15 09:29:21 volumio volumio[1232]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 15 09:29:21 volumio sudo[5161]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-15 09:28' Dec 15 09:29:21 volumio sudo[5161]: 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"