Dec 05 11:17:32 volumio volumio[1127]: info: Received OAUTH Data Dec 05 11:17:32 volumio volumio[1127]: info: Executing Spotify Oauth Login Dec 05 11:17:32 volumio volumio[1127]: info: Saving Spotify Refresh Token Dec 05 11:17:32 volumio volumio[1127]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 05 11:17:32 volumio volumio[1127]: SPOTIFY: BQB11VvzmPzenZ8vZ6_lKTb1eWbiRaf-Nfb7OWdwJh6usE5g03lmb1HS7QyvYkXfd3NGK3QIq4Tu2bpTzfiPY_GH7IO--P2_yJ6dBU6ZLybmdIMUQuBWn5vEVxUu1KjppFTQEtq3o64Jo3VBH0byeV1RQkN8JZbkWldUpMV_DA3eFcW1YiJciEAXkIkFjpe3qk348J9e8TKIAqhhJUFEDVoKJ7187pO6LheZQzg5mbqHl4cRcS3HC-Az5yQ6b6XjeJmK8fdrDMZ5YpmguaZNfx9ppORHTDxTr9wsJutJII0g13S0VgVz19M-xsh9 Dec 05 11:17:32 volumio volumio[1127]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 05 11:17:32 volumio volumio[1127]: info: New Spotify access token = BQB11VvzmPzenZ8vZ6_lKTb1eWbiRaf-Nfb7OWdwJh6usE5g03lmb1HS7QyvYkXfd3NGK3QIq4Tu2bpTzfiPY_GH7IO--P2_yJ6dBU6ZLybmdIMUQuBWn5vEVxUu1KjppFTQEtq3o64Jo3VBH0byeV1RQkN8JZbkWldUpMV_DA3eFcW1YiJciEAXkIkFjpe3qk348J9e8TKIAqhhJUFEDVoKJ7187pO6LheZQzg5mbqHl4cRcS3HC-Az5yQ6b6XjeJmK8fdrDMZ5YpmguaZNfx9ppORHTDxTr9wsJutJII0g13S0VgVz19M-xsh9 Dec 05 11:17:32 volumio volumio[1127]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 05 11:17:32 volumio volumio[1127]: SPOTIFY: User informations: {"country":"NL","display_name":"Dennis","email":"dhjbals1@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31lpffwlpug6jrx2civqhmz6gdje"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31lpffwlpug6jrx2civqhmz6gdje","id":"31lpffwlpug6jrx2civqhmz6gdje","images":[],"product":"premium","type":"user","uri":"spotify:user:31lpffwlpug6jrx2civqhmz6gdje"} Dec 05 11:17:32 volumio volumio[1127]: info: Creating Spotify config file Dec 05 11:17:32 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 11:17:32 volumio volumio[1127]: info: Spotify config file written Dec 05 11:17:32 volumio sudo[4702]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 11:17:32 volumio sudo[4702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:17:32 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 11:17:32 volumio systemd[1]: go-librespot-daemon.service: Killing process 4615 (go-librespot) with signal SIGKILL. Dec 05 11:17:32 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 11:17:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:17:32 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:17:32 volumio sudo[4708]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 05 11:17:32 volumio sudo[4706]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 05 11:17:32 volumio sudo[4708]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:17:32 volumio sudo[4706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:17:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:17:32 volumio go-librespot[4704]: go-librespot daemon starting... Dec 05 11:17:32 volumio sudo[4708]: pam_unix(sudo:session): session closed for user root Dec 05 11:17:32 volumio sudo[4706]: pam_unix(sudo:session): session closed for user root Dec 05 11:17:32 volumio sudo[4702]: pam_unix(sudo:session): session closed for user root Dec 05 11:17:32 volumio go-librespot[4711]: time="2025-12-05T11:17:32+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 11:17:32 volumio go-librespot[4711]: time="2025-12-05T11:17:32+01:00" level=debug msg="app state loaded" Dec 05 11:17:32 volumio go-librespot[4711]: time="2025-12-05T11:17:32+01:00" level=debug msg="stored credentials not found" Dec 05 11:17:32 volumio go-librespot[4711]: time="2025-12-05T11:17:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 11:17:33 volumio volumio[1127]: verbose: New Socket.io Connection to 192.168.2.23 from 192.168.2.59 UA: Mozilla/5.0 (Linux; Android 16; SM-S921B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/142.0.7444.171 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Dec 05 11:17:33 volumio volumio[1127]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 05 11:17:33 volumio volumio[1127]: SPOTIFY: BQDIWf7MwKJjV1yfL8kqVMgKfDl26fuhEAO39DQOrcWrZ5lqV8gGS8zjWDUcVJI60I420Gswt55umyWqtZEVrWgyZWhCozr8EWfFcWWoPLVMi5uBv8w0DJO3dTj0JHCP4fn414qUvB4u6rh-06V9wgfl-3_H-k5IcGIVo6Jkco2R-vn5KE9wo_bNeoVvMnKEGlPDXb2nfgDYIiiGCPjXFF32iW6AvQhY0Ak0K3wqXCEmAuV7ZDKi0NXS1DoBzsCZ2f8yYIOCPobf8SqB8d9St0KrzoEUwRbqe5mf23Io7Pl7Msi-TKtav7kxiBxV Dec 05 11:17:33 volumio volumio[1127]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 05 11:17:33 volumio volumio[1127]: info: New Spotify access token = BQDIWf7MwKJjV1yfL8kqVMgKfDl26fuhEAO39DQOrcWrZ5lqV8gGS8zjWDUcVJI60I420Gswt55umyWqtZEVrWgyZWhCozr8EWfFcWWoPLVMi5uBv8w0DJO3dTj0JHCP4fn414qUvB4u6rh-06V9wgfl-3_H-k5IcGIVo6Jkco2R-vn5KE9wo_bNeoVvMnKEGlPDXb2nfgDYIiiGCPjXFF32iW6AvQhY0Ak0K3wqXCEmAuV7ZDKi0NXS1DoBzsCZ2f8yYIOCPobf8SqB8d9St0KrzoEUwRbqe5mf23Io7Pl7Msi-TKtav7kxiBxV Dec 05 11:17:33 volumio volumio[1127]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::volumioGetVisibleSources Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:17:33 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 05 11:17:33 volumio volumio[1127]: info: Received Get System Info Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 05 11:17:33 volumio volumio[1127]: info: Discovery: Getting this device information Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:17:33 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:17:33 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:17:33 volumio volumio[1127]: info: Listing playlists Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 05 11:17:33 volumio volumio[1127]: SPOTIFY: User informations: {"country":"NL","display_name":"Dennis","email":"dhjbals1@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31lpffwlpug6jrx2civqhmz6gdje"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31lpffwlpug6jrx2civqhmz6gdje","id":"31lpffwlpug6jrx2civqhmz6gdje","images":[],"product":"premium","type":"user","uri":"spotify:user:31lpffwlpug6jrx2civqhmz6gdje"} Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+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 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+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 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+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 05 11:17:33 volumio volumio[1127]: info: Spotify Successfully logged in Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 05 11:17:33 volumio volumio[1127]: info: [1764929853166] CoreMusicLibrary::Adding element Spotify Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 05 11:17:33 volumio volumio[1127]: Cannot find translation for source Spotify Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=info msg="zeroconf server listening on port 46615" Dec 05 11:17:33 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="obtained new client token: AACG4hI/6t9DhKu26gzG4LGj9rM/v2Bv6mnQ9RvCmmiP8nEHM5c5Gaoj5YxD4huZP675fdm1jXClSC/Qq8xPk4ZB28tvLspOdne9dwmXlAgh3hZeHGc3HjD4Lvx3O6bNUetRk4h7WEDlEZbjq1nmVN8ApBizh7plFB2gmL3VkuTZj1Gg+Mq4U/bbHgIOmmgfp83y39g/B8L1C4977LoQDTFPa91hAPIMtoWRescSrdTIH77F+7yJr6Xh" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="completed keyexchange" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="completed challenge" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=info msg="authenticated AP" username="31************************je" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=info msg="authenticated Login5" username="31************************je" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="stored credentials" username="31************************je" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="initializing zeroconf session" username="31************************je" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="dealer connection opened" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=trace msg="starting accesspoint recv loop" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=trace msg="starting dealer recv loop" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=trace msg="received accesspoint ping" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="received connection id: ZGU3MWUwMmItYzYy...NzMxRkU5REVGRQ==" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=trace msg="received accesspoint pong ack" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="update volume requested to 65535/65535" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 05 11:17:33 volumio go-librespot[4711]: time="2025-12-05T11:17:33+01:00" level=trace msg="emitting websocket event: volume" Dec 05 11:17:34 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 05 11:17:34 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 05 11:17:34 volumio volumio[1127]: info: Received Get System Info Dec 05 11:17:34 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 05 11:17:34 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 05 11:17:34 volumio volumio[1127]: info: Discovery: Getting this device information Dec 05 11:17:34 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:17:34 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:17:34 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 05 11:17:35 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 05 11:17:35 volumio volumio[1127]: info: Received Get System Info Dec 05 11:17:35 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 05 11:17:35 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 05 11:17:35 volumio volumio[1127]: info: Discovery: Getting this device information Dec 05 11:17:35 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:17:35 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:17:35 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 05 11:17:35 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:17:35 volumio go-librespot[4711]: time="2025-12-05T11:17:35+01:00" level=debug msg="new websocket client" Dec 05 11:17:35 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:17:35 volumio volumio[1127]: info: go-librespot daemon successfully initialized Dec 05 11:17:38 volumio volumio[1127]: info: Getting Spotify volume Dec 05 11:17:38 volumio volumio[1127]: info: Spotify volume: 100 Dec 05 11:17:38 volumio volumio[1127]: 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 05 11:17:38 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:17:38 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:17:38 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:17:38 volumio go-librespot[4711]: time="2025-12-05T11:17:38+01:00" level=debug msg="new websocket client" Dec 05 11:17:38 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:17:41 volumio volumio[1127]: info: Getting Spotify volume Dec 05 11:17:41 volumio volumio[1127]: info: Spotify volume: 100 Dec 05 11:17:41 volumio volumio[1127]: 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 05 11:17:42 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:17:42 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:17:43 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 05 11:17:51 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 05 11:17:51 volumio volumio[1127]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 05 11:17:51 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 05 11:17:51 volumio volumio[1127]: info: Received Get System Version Dec 05 11:17:51 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 05 11:17:51 volumio volumio[1127]: info: Received Get System Info Dec 05 11:17:51 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 05 11:17:51 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 05 11:17:51 volumio volumio[1127]: info: Discovery: Getting this device information Dec 05 11:17:51 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:17:51 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:17:51 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 05 11:17:55 volumio volumio[1127]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 05 11:17:55 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 05 11:17:55 volumio volumio[1127]: info: Creating Spotify config file Dec 05 11:17:55 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 11:17:55 volumio volumio[1127]: info: Spotify config file written Dec 05 11:17:55 volumio sudo[4755]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 11:17:55 volumio sudo[4755]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:17:55 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 11:17:55 volumio systemd[1]: go-librespot-daemon.service: Killing process 4712 (go-librespot) with signal SIGKILL. Dec 05 11:17:55 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 11:17:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:17:55 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:17:55 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:17:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:17:56 volumio go-librespot[4758]: go-librespot daemon starting... Dec 05 11:17:56 volumio sudo[4755]: pam_unix(sudo:session): session closed for user root Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="app state loaded" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=info msg="zeroconf server listening on port 38789" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="obtained new client token: AAC8jTsAKalPvcyPt36pkTcintzDnszE2oOQgaMPTYjdFi285cyKMqJHWnCY2YCmYF6DlhIlH0DMi7PlC7o58UO47mmRAsAAThlUiaNGRUS1IMwIFbx5awBQeLv7ZqSLKwcOThvr9RRdFjLErgKX9qDo0ERvVL+5seAEB5ri6AZFcOk2uwItIgfWqnYH8F6GG8Y/LmiA0vHkMSRIdDPYO/OQValtQu+LC8mafeCDEHZj6olYKPqM9V4O8LM=" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="completed keyexchange" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="completed challenge" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=info msg="authenticated AP" username="31************************je" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=info msg="authenticated Login5" username="31************************je" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="initializing zeroconf session" username="31************************je" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="dealer connection opened" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=trace msg="starting accesspoint recv loop" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=trace msg="starting dealer recv loop" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=trace msg="received accesspoint ping" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="received connection id: ZTBiYTFjYmEtNGZl...MjM4OEEwRkVDOQ==" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=trace msg="received accesspoint pong ack" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="update volume requested to 65535/65535" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 05 11:17:56 volumio go-librespot[4759]: time="2025-12-05T11:17:56+01:00" level=trace msg="emitting websocket event: volume" Dec 05 11:17:58 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:17:58 volumio go-librespot[4759]: time="2025-12-05T11:17:58+01:00" level=debug msg="new websocket client" Dec 05 11:17:58 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:17:59 volumio volumio[1127]: info: go-librespot daemon successfully initialized Dec 05 11:18:01 volumio volumio[1127]: info: Getting Spotify volume Dec 05 11:18:02 volumio volumio[1127]: info: Spotify volume: 100 Dec 05 11:18:02 volumio volumio[1127]: 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 05 11:18:02 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:18:02 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:18:02 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:18:02 volumio go-librespot[4759]: time="2025-12-05T11:18:02+01:00" level=debug msg="new websocket client" Dec 05 11:18:02 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:18:05 volumio volumio[1127]: info: Getting Spotify volume Dec 05 11:18:05 volumio volumio[1127]: info: Spotify volume: 100 Dec 05 11:18:05 volumio volumio[1127]: 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 05 11:18:05 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:18:05 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:18:07 volumio nmbd[1026]: [2025/12/05 11:18:07.232417, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 05 11:18:07 volumio nmbd[1026]: Packet send failed to 192.168.211.255(138) ERRNO=Network is unreachable Dec 05 11:18:26 volumio go-librespot[4759]: time="2025-12-05T11:18:26+01:00" level=trace msg="sent dealer ping" Dec 05 11:18:26 volumio go-librespot[4759]: time="2025-12-05T11:18:26+01:00" level=trace msg="received dealer pong" Dec 05 11:18:40 volumio volumio[1127]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 05 11:18:40 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 05 11:18:40 volumio volumio[1127]: info: Creating Spotify config file Dec 05 11:18:40 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 11:18:40 volumio volumio[1127]: info: Spotify config file written Dec 05 11:18:40 volumio sudo[4849]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 11:18:40 volumio sudo[4849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:18:40 volumio systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories... Dec 05 11:18:40 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 11:18:40 volumio systemd[1]: go-librespot-daemon.service: Killing process 4765 (go-librespot) with signal SIGKILL. Dec 05 11:18:40 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 11:18:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:40 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:18:40 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:18:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:40 volumio go-librespot[4853]: go-librespot daemon starting... Dec 05 11:18:40 volumio sudo[4849]: pam_unix(sudo:session): session closed for user root Dec 05 11:18:40 volumio systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully. Dec 05 11:18:40 volumio systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories. Dec 05 11:18:40 volumio go-librespot[4854]: time="2025-12-05T11:18:40+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 11:18:40 volumio go-librespot[4854]: time="2025-12-05T11:18:40+01:00" level=debug msg="app state loaded" Dec 05 11:18:40 volumio go-librespot[4854]: time="2025-12-05T11:18:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 11:18:40 volumio systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully. Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+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 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+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 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+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 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=info msg="zeroconf server listening on port 36163" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="obtained new client token: AABtMGRNIhCCupI21o/jiOaUY6B9T8xxHotgqKPBGV04HN30ge2JTesXDjOW038q4xBayUpy+g/F+4caxzqfb7853eMZ5S7RnNoFQZeBRKeT6zVMOegeNeqYInYlmLIBbR5zuNvFBGyKWuUG34ROnm1fGfWMEZOjYApsnKADxkPXryh6EQ6P0e4fqdcQbmQK56LkatuxQ1jk2j0+iSrumiD54/L81W3F/Oe5zYCFUfUT5CSKSq9XLLpV" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="completed keyexchange" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="completed challenge" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=info msg="authenticated AP" username="31************************je" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=info msg="authenticated Login5" username="31************************je" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="initializing zeroconf session" username="31************************je" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="dealer connection opened" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=trace msg="starting accesspoint recv loop" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=trace msg="starting dealer recv loop" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=trace msg="received accesspoint ping" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="received connection id: YTIyMGE2ZTMtN2U4...NzdFRDIwNTQ4MA==" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=trace msg="received accesspoint pong ack" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="update volume requested to 65535/65535" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 05 11:18:41 volumio go-librespot[4854]: time="2025-12-05T11:18:41+01:00" level=trace msg="emitting websocket event: volume" Dec 05 11:18:42 volumio volumio[1127]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 05 11:18:42 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 05 11:18:42 volumio volumio[1127]: info: Creating Spotify config file Dec 05 11:18:42 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 11:18:42 volumio volumio[1127]: info: Spotify config file written Dec 05 11:18:42 volumio sudo[4862]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 11:18:42 volumio sudo[4862]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:18:42 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 11:18:42 volumio systemd[1]: go-librespot-daemon.service: Killing process 4860 (go-librespot) with signal SIGKILL. Dec 05 11:18:42 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 11:18:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:42 volumio sudo[4862]: pam_unix(sudo:session): session closed for user root Dec 05 11:18:42 volumio go-librespot[4864]: go-librespot daemon starting... Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=debug msg="app state loaded" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=info msg="zeroconf server listening on port 43977" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=debug msg="obtained new client token: AAAKmF5gO7AhvFeHfhP2dmHNvkPu1jzRR8fIjAsVB6vgjvhINBXJl1HsWunQfHs8AwkXEy53rZsProG//No+BVvaM2YWgJEq7NqjlDNDXovRPmtHI0oj2uAKuYaIle6TSrlR1dPNU8EzSu6gfYpRM6QV1jsfoXNkJqJGQDxwUMmINtxyb7MB4QAAo/x131nzfOy2EvgZKtRUPpoJpWMgW5qSIyHf3VjzLeSLN1q1ITiWeUGtw9YHu4R7iBo=" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=debug msg="completed keyexchange" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=debug msg="completed challenge" Dec 05 11:18:42 volumio go-librespot[4865]: time="2025-12-05T11:18:42+01:00" level=info msg="authenticated AP" username="31************************je" Dec 05 11:18:42 volumio volumio[1127]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 05 11:18:42 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 05 11:18:42 volumio volumio[1127]: info: Creating Spotify config file Dec 05 11:18:42 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 11:18:42 volumio volumio[1127]: info: Spotify config file written Dec 05 11:18:42 volumio sudo[4873]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 11:18:42 volumio sudo[4873]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:18:42 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 11:18:42 volumio systemd[1]: go-librespot-daemon.service: Killing process 4869 (go-librespot) with signal SIGKILL. Dec 05 11:18:42 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 11:18:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:43 volumio go-librespot[4875]: go-librespot daemon starting... Dec 05 11:18:43 volumio sudo[4873]: pam_unix(sudo:session): session closed for user root Dec 05 11:18:43 volumio go-librespot[4876]: time="2025-12-05T11:18:43+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 11:18:43 volumio go-librespot[4876]: time="2025-12-05T11:18:43+01:00" level=debug msg="app state loaded" Dec 05 11:18:43 volumio go-librespot[4876]: time="2025-12-05T11:18:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 11:18:43 volumio volumio[1127]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 05 11:18:43 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 05 11:18:43 volumio volumio[1127]: info: Creating Spotify config file Dec 05 11:18:43 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 11:18:43 volumio volumio[1127]: info: Spotify config file written Dec 05 11:18:43 volumio sudo[4883]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 11:18:43 volumio sudo[4883]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:18:43 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 11:18:43 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 11:18:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:43 volumio go-librespot[4885]: go-librespot daemon starting... Dec 05 11:18:43 volumio sudo[4883]: pam_unix(sudo:session): session closed for user root Dec 05 11:18:43 volumio go-librespot[4887]: time="2025-12-05T11:18:43+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 11:18:43 volumio go-librespot[4887]: time="2025-12-05T11:18:43+01:00" level=debug msg="app state loaded" Dec 05 11:18:43 volumio go-librespot[4887]: time="2025-12-05T11:18:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 11:18:43 volumio volumio[1127]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 05 11:18:43 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 05 11:18:43 volumio volumio[1127]: info: Creating Spotify config file Dec 05 11:18:43 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 11:18:43 volumio volumio[1127]: info: Spotify config file written Dec 05 11:18:43 volumio sudo[4894]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 11:18:43 volumio sudo[4894]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:18:43 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 11:18:43 volumio systemd[1]: go-librespot-daemon.service: Killing process 4892 (go-librespot) with signal SIGKILL. Dec 05 11:18:43 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 11:18:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:43 volumio go-librespot[4896]: go-librespot daemon starting... Dec 05 11:18:43 volumio sudo[4894]: pam_unix(sudo:session): session closed for user root Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="app state loaded" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=info msg="zeroconf server listening on port 33165" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="obtained new client token: AADBsFILi/4M7M/fkgnaTltePlgVKoCP/DesluJyBwnyKXdkZqnHHriubH2YMybDd7yLDTqLv6iJ0kDYcfy4BNdryFbGv4iHbnnxm/CVR4LkTsyhcz0OY12wrekUry4igI0XIQchyflxbbcA+8+ZAxzz/RuXb18jFrTCybZcz2OL2KH/fpWZRy6cg+rbeO0gmcjCYKoS14ghtXYhuoNWxueSIP+aPmwOlQLwZ1HKWFOuMFcfrOX+i1nRPLo=" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="completed keyexchange" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="completed challenge" Dec 05 11:18:43 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="new websocket client" Dec 05 11:18:43 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:18:43 volumio volumio[1127]: info: go-librespot daemon successfully initialized Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=info msg="authenticated AP" username="31************************je" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=info msg="authenticated Login5" username="31************************je" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="initializing zeroconf session" username="31************************je" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="dealer connection opened" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=trace msg="starting accesspoint recv loop" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=trace msg="starting dealer recv loop" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=trace msg="received accesspoint ping" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=debug msg="received connection id: Yjc2NDRmYzctMTg5...M0EzNUU5Q0U1RQ==" Dec 05 11:18:43 volumio go-librespot[4897]: time="2025-12-05T11:18:43+01:00" level=trace msg="received accesspoint pong ack" Dec 05 11:18:44 volumio go-librespot[4897]: time="2025-12-05T11:18:44+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 05 11:18:44 volumio go-librespot[4897]: time="2025-12-05T11:18:44+01:00" level=debug msg="update volume requested to 65535/65535" Dec 05 11:18:44 volumio go-librespot[4897]: time="2025-12-05T11:18:44+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 05 11:18:44 volumio go-librespot[4897]: time="2025-12-05T11:18:44+01:00" level=trace msg="emitting websocket event: volume" Dec 05 11:18:44 volumio volumio[1127]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Dec 05 11:18:44 volumio volumio[1127]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Dec 05 11:18:44 volumio volumio[1127]: info: Setting Volumio Volume from Spotify: 100 Dec 05 11:18:44 volumio volumio[1127]: info: VolumeController::SetAlsaVolume100 Dec 05 11:18:44 volumio volumio[1127]: info: CoreStateMachine::pushState Dec 05 11:18:44 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:18:44 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 05 11:18:44 volumio volumio[1127]: info: CoreCommandRouter::volumioPushState Dec 05 11:18:45 volumio volumio[1127]: info: go-librespot daemon successfully initialized Dec 05 11:18:46 volumio volumio[1127]: info: go-librespot daemon successfully initialized Dec 05 11:18:46 volumio volumio[1127]: info: go-librespot daemon successfully initialized Dec 05 11:18:46 volumio volumio[1127]: info: go-librespot daemon successfully initialized Dec 05 11:18:46 volumio volumio[1127]: info: Getting Spotify volume Dec 05 11:18:46 volumio volumio[1127]: info: Spotify volume: 100 Dec 05 11:18:46 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:18:46 volumio volumio[1127]: 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 05 11:18:46 volumio go-librespot[4897]: time="2025-12-05T11:18:46+01:00" level=debug msg="new websocket client" Dec 05 11:18:46 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:18:46 volumio volumio[1127]: info: CoreCommandRouter::volumioGetState Dec 05 11:18:46 volumio volumio[1127]: info: CorePlayQueue::getTrack 2 Dec 05 11:18:48 volumio volumio[1127]: info: CALLMETHOD: music_service spop logout Dec 05 11:18:48 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: spop , logout Dec 05 11:18:48 volumio volumio[1127]: info: Deleting Spotify credentials File Dec 05 11:18:48 volumio volumio[1127]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Dec 05 11:18:48 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 05 11:18:48 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:18:48 volumio go-librespot[4897]: time="2025-12-05T11:18:48+01:00" level=debug msg="new websocket client" Dec 05 11:18:48 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:18:49 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:18:49 volumio go-librespot[4897]: time="2025-12-05T11:18:49+01:00" level=debug msg="new websocket client" Dec 05 11:18:49 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:18:49 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:18:49 volumio go-librespot[4897]: time="2025-12-05T11:18:49+01:00" level=debug msg="new websocket client" Dec 05 11:18:49 volumio volumio[1127]: info: Connection to go-librespot Websocket established Dec 05 11:18:49 volumio volumio[1127]: info: Creating Spotify config file Dec 05 11:18:49 volumio volumio[1127]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 11:18:49 volumio volumio[1127]: info: Spotify config file written Dec 05 11:18:49 volumio sudo[4921]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 11:18:49 volumio sudo[4921]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 11:18:49 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 11:18:49 volumio systemd[1]: go-librespot-daemon.service: Killing process 4899 (go-librespot) with signal SIGKILL. Dec 05 11:18:49 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:18:49 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 11:18:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:49 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:18:49 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:18:49 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:18:49 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Dec 05 11:18:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Dec 05 11:18:49 volumio volumio[1127]: info: Connection to go-librespot Websocket closed Dec 05 11:18:49 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Dec 05 11:18:49 volumio sudo[4921]: pam_unix(sudo:session): session closed for user root Dec 05 11:18:49 volumio volumio[1127]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Dec 05 11:18:49 volumio volumio[1127]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Dec 05 11:18:49 volumio volumio[1127]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Dec 05 11:18:49 volumio volumio[1127]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Dec 05 11:18:49 volumio volumio[1127]: followed by "systemctl start go-librespot-daemon.service" again. Dec 05 11:18:49 volumio volumio[1127]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Dec 05 11:18:49 volumio volumio[1127]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Dec 05 11:18:49 volumio volumio[1127]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Dec 05 11:18:49 volumio volumio[1127]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Dec 05 11:18:49 volumio volumio[1127]: followed by "systemctl start go-librespot-daemon.service" again. Dec 05 11:18:49 volumio volumio[1127]: info: Initializing connection to go-librespot Websocket Dec 05 11:18:49 volumio volumio[1127]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 05 11:18:49 volumio volumio[1127]: info: Getting Spotify volume Dec 05 11:18:49 volumio volumio[1127]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 05 11:18:49 volumio volumio[1127]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 05 11:18:49 volumio volumio[1127]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 05 11:18:49 volumio volumio[1127]: errno: -111, Dec 05 11:18:49 volumio volumio[1127]: code: 'ECONNREFUSED', Dec 05 11:18:49 volumio volumio[1127]: syscall: 'connect', Dec 05 11:18:49 volumio volumio[1127]: address: '127.0.0.1', Dec 05 11:18:49 volumio volumio[1127]: port: 9879, Dec 05 11:18:49 volumio volumio[1127]: response: undefined Dec 05 11:18:49 volumio volumio[1127]: } Dec 05 11:18:49 volumio volumio[1127]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 05 11:18:50 volumio sudo[4938]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-05 11:17' Dec 05 11:18:50 volumio sudo[4938]: 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="3a3cfe435f8bb2bc94a920662e91a4ef35bc8e7c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="8bcc10c3dbcbcb349e9887dc0527d54876b32688" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Dec 2 11:51:19 UTC 2025" VOLUMIO_VERSION="4.072" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e5001581b220b096097cf8f46a54d4f1"