Dec 05 16:21:27 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 05 16:21:27 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 05 16:21:33 volumio volumio[1210]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 05 16:22:20 volumio volumio[1210]: info: Received OAUTH Data Dec 05 16:22:20 volumio volumio[1210]: info: Executing Spotify Oauth Login Dec 05 16:22:20 volumio volumio[1210]: info: Saving Spotify Refresh Token Dec 05 16:22:20 volumio volumio[1210]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 05 16:22:20 volumio volumio[1210]: SPOTIFY: BQANeq6iQt8XIkAgTPV4IEbY3it4SzdLHWaRTSNoCH74ij52VWdChihS8C-V_VK8jHe-15Sw-NwbXqqOwWE_-sH_25EbbLHTc6bs5OMgDXoRt8jsfNzEg6nS-RxKYsHjd29n25T69cx9ct1q8B_ySib4vZ8v2TAALk72bCGOVC0pOIK4znOJT9HEd44JIxnrr4oQPpeA6AExYtiUDAhnoYsMc0ZoQTG0UID1cXsBS7TtrS2CVgtJjahPMAWC6hOXFif9FN_DiilNUb2l3OGY8zAfYFFELh4xTgOX26tU4evS5bsjCzDlwHULYqoc Dec 05 16:22:20 volumio volumio[1210]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 05 16:22:20 volumio volumio[1210]: info: New Spotify access token = BQANeq6iQt8XIkAgTPV4IEbY3it4SzdLHWaRTSNoCH74ij52VWdChihS8C-V_VK8jHe-15Sw-NwbXqqOwWE_-sH_25EbbLHTc6bs5OMgDXoRt8jsfNzEg6nS-RxKYsHjd29n25T69cx9ct1q8B_ySib4vZ8v2TAALk72bCGOVC0pOIK4znOJT9HEd44JIxnrr4oQPpeA6AExYtiUDAhnoYsMc0ZoQTG0UID1cXsBS7TtrS2CVgtJjahPMAWC6hOXFif9FN_DiilNUb2l3OGY8zAfYFFELh4xTgOX26tU4evS5bsjCzDlwHULYqoc Dec 05 16:22:20 volumio volumio[1210]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 05 16:22:21 volumio sudo[18457]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 05 16:22:21 volumio volumio[1210]: SPOTIFY: User informations: {"country":"NL","display_name":"Leo Blok","email":"leo_blok@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31yrecalpd2jcfpeoxmmaimqhlf4"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/31yrecalpd2jcfpeoxmmaimqhlf4","id":"31yrecalpd2jcfpeoxmmaimqhlf4","images":[{"height":300,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=2381843008535059&height=300&width=300&ext=1767519965&hash=AT-4Lkzrb7NGNGiAl3pQIe9E","width":300},{"height":64,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=2381843008535059&height=50&width=50&ext=1767519965&hash=AT8xKE60Gd0MN72WmEHWuTa4","width":64}],"product":"premium","type":"user","uri":"spotify:user:31yrecalpd2jcfpeoxmmaimqhlf4"} Dec 05 16:22:21 volumio sudo[18457]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 16:22:21 volumio volumio[1210]: info: Creating Spotify config file Dec 05 16:22:21 volumio sudo[18457]: pam_unix(sudo:session): session closed for user root Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 16:22:21 volumio sudo[18459]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 05 16:22:21 volumio sudo[18459]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 16:22:21 volumio sudo[18459]: pam_unix(sudo:session): session closed for user root Dec 05 16:22:21 volumio volumio[1210]: info: Spotify config file written Dec 05 16:22:21 volumio sudo[18464]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 16:22:21 volumio sudo[18464]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 16:22:21 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 16:22:21 volumio volumio[1210]: verbose: New Socket.io Connection to 192.168.2.29 from 192.168.2.19 UA: Mozilla/5.0 (Linux; Android 13; SM-G781B Build/TP1A.220624.014; 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 16:22:21 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 16:22:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 16:22:21 volumio volumio[1210]: info: Connection to go-librespot Websocket closed Dec 05 16:22:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 16:22:21 volumio sudo[18464]: pam_unix(sudo:session): session closed for user root Dec 05 16:22:21 volumio volumio[1210]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 05 16:22:21 volumio volumio[1210]: SPOTIFY: BQB-lHvtCv2RcGpLF7fHcfGeX3c2GYj1I7WwVE7XAabKjQWeHfPJ18tX-EGwKozC7Pa6IOn44sv3NB0BvkKhY-xMlc6Lx8E84HBSgt7YH_Y-60-4hFR15oGo4NH3PJnJMEAxQ16cikaoKDap-lhvoCLf4pP94YRqgg3v5Yrx8BEjDvq9tPjCbWrJdqDuxjH0e5kPltbABzOlBhUdtpSum0HPeRiAbKv__vH1ufALhOhrQVgNGz3kM_Nk9Pf9obayOxuusgsxnCR2DJdFFOQpFATR-KxTyo-w6G0z9viAPcktrEsGGqGxMqXWObDP Dec 05 16:22:21 volumio volumio[1210]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 05 16:22:21 volumio volumio[1210]: info: New Spotify access token = BQB-lHvtCv2RcGpLF7fHcfGeX3c2GYj1I7WwVE7XAabKjQWeHfPJ18tX-EGwKozC7Pa6IOn44sv3NB0BvkKhY-xMlc6Lx8E84HBSgt7YH_Y-60-4hFR15oGo4NH3PJnJMEAxQ16cikaoKDap-lhvoCLf4pP94YRqgg3v5Yrx8BEjDvq9tPjCbWrJdqDuxjH0e5kPltbABzOlBhUdtpSum0HPeRiAbKv__vH1ufALhOhrQVgNGz3kM_Nk9Pf9obayOxuusgsxnCR2DJdFFOQpFATR-KxTyo-w6G0z9viAPcktrEsGGqGxMqXWObDP Dec 05 16:22:21 volumio volumio[1210]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 05 16:22:21 volumio go-librespot[18467]: go-librespot daemon starting... Dec 05 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+01:00" level=debug msg="app state loaded" Dec 05 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+01:00" level=debug msg="stored credentials not found" Dec 05 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 05 16:22:21 volumio volumio[1210]: SPOTIFY: User informations: {"country":"NL","display_name":"Leo Blok","email":"leo_blok@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31yrecalpd2jcfpeoxmmaimqhlf4"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/31yrecalpd2jcfpeoxmmaimqhlf4","id":"31yrecalpd2jcfpeoxmmaimqhlf4","images":[{"height":300,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=2381843008535059&height=300&width=300&ext=1767519965&hash=AT-4Lkzrb7NGNGiAl3pQIe9E","width":300},{"height":64,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=2381843008535059&height=50&width=50&ext=1767519965&hash=AT8xKE60Gd0MN72WmEHWuTa4","width":64}],"product":"premium","type":"user","uri":"spotify:user:31yrecalpd2jcfpeoxmmaimqhlf4"} Dec 05 16:22:21 volumio volumio[1210]: info: Spotify Successfully logged in Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 05 16:22:21 volumio volumio[1210]: info: [1764948141330] CoreMusicLibrary::Adding element Spotify Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 05 16:22:21 volumio volumio[1210]: Cannot find translation for source Spotify Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::volumioGetVisibleSources Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::volumioGetState Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 05 16:22:21 volumio volumio[1210]: info: Received Get System Info Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 05 16:22:21 volumio volumio[1210]: info: Discovery: Getting this device information Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::volumioGetState Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::volumioGetState Dec 05 16:22:21 volumio volumio[1210]: info: Listing playlists Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 05 16:22:21 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 05 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+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 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+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 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+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 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+01:00" level=info msg="zeroconf server listening on port 41815" Dec 05 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+01:00" level=debug msg="obtained new client token: AADBEkdEQ6kmas5TVMfTZ6729Unhe8kMccujUWkPvQLZb36Ojt4eDE4Ws2uwfVZqj2T+M35BIJ4xuMorzHDgFxTc0vyy+gNq+AiTe7aU5SciGx3rV0shyejQqiiB2sFViynV/2ulXVcTUXvp+V83pJimyUesLLJZyzj1dnCAaSvsD4WFDNs/4CLyr1FM0GhEBxeq5yFK5qPK5GuQ6YCUU++e6PvXaviPUpwUKOaRR76D0V0QH8JpkOw2Msg=" Dec 05 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 16:22:21 volumio go-librespot[18469]: time="2025-12-05T16:22:21+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: EOF" Dec 05 16:22:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 05 16:22:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 05 16:22:22 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 05 16:22:22 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 05 16:22:22 volumio volumio[1210]: info: Received Get System Info Dec 05 16:22:22 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 05 16:22:22 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 05 16:22:22 volumio volumio[1210]: info: Discovery: Getting this device information Dec 05 16:22:22 volumio volumio[1210]: info: CoreCommandRouter::volumioGetState Dec 05 16:22:22 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 05 16:22:23 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 05 16:22:23 volumio volumio[1210]: info: Received Get System Info Dec 05 16:22:23 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 05 16:22:23 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 05 16:22:23 volumio volumio[1210]: info: Discovery: Getting this device information Dec 05 16:22:23 volumio volumio[1210]: info: CoreCommandRouter::volumioGetState Dec 05 16:22:23 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 05 16:22:24 volumio volumio[1210]: info: Initializing connection to go-librespot Websocket Dec 05 16:22:24 volumio volumio[1210]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 05 16:22:24 volumio volumio[1210]: info: go-librespot daemon successfully initialized Dec 05 16:22:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 05 16:22:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 16:22:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 16:22:24 volumio go-librespot[18490]: go-librespot daemon starting... Dec 05 16:22:24 volumio go-librespot[18491]: time="2025-12-05T16:22:24+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 16:22:24 volumio go-librespot[18491]: time="2025-12-05T16:22:24+01:00" level=debug msg="app state loaded" Dec 05 16:22:24 volumio go-librespot[18491]: time="2025-12-05T16:22:24+01:00" level=debug msg="stored credentials not found" Dec 05 16:22:24 volumio go-librespot[18491]: time="2025-12-05T16:22:24+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+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 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+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 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+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 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=info msg="zeroconf server listening on port 42391" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="obtained new client token: AAD6a3jNq7cWksxZBGl6edgdmaRv7KembsNtJeeJ07UZB7fkVT/8s4yTeUTpl2grnlL3bPFnl4mi7+ArjYQnKvuLu6lMm/9QgtMYlUJw9LVIyQiSLZbwzt9nxxeUMGM8aUN5/gsTBcJPdCrM9Cjxl/Oh1QUSbpceabjUQZmU1QnYFKC89EEp2NDsGJNXCWG9fMuyblZPBxMeOL8KLpKDZ+GS8RR50esjYzzQbORNovJcx3f1kZnBDCLc" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="completed keyexchange" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="completed challenge" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=info msg="authenticated AP" username="31************************f4" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=info msg="authenticated Login5" username="31************************f4" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="stored credentials" username="31************************f4" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="initializing zeroconf session" username="31************************f4" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="dealer connection opened" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=trace msg="starting accesspoint recv loop" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=trace msg="starting dealer recv loop" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=trace msg="received accesspoint ping" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="received connection id: MWIxYWZkNTYtYjZh...RTgxODM4RjM1QQ==" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=trace msg="received accesspoint pong ack" Dec 05 16:22:25 volumio go-librespot[18491]: time="2025-12-05T16:22:25+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 05 16:22:27 volumio volumio[1210]: info: Initializing connection to go-librespot Websocket Dec 05 16:22:27 volumio go-librespot[18491]: time="2025-12-05T16:22:27+01:00" level=debug msg="new websocket client" Dec 05 16:22:27 volumio volumio[1210]: info: Connection to go-librespot Websocket established Dec 05 16:22:27 volumio volumio[1210]: info: Initializing connection to go-librespot Websocket Dec 05 16:22:27 volumio go-librespot[18491]: time="2025-12-05T16:22:27+01:00" level=debug msg="new websocket client" Dec 05 16:22:27 volumio volumio[1210]: info: Connection to go-librespot Websocket established Dec 05 16:22:30 volumio volumio[1210]: info: Getting Spotify volume Dec 05 16:22:30 volumio volumio[1210]: info: Spotify volume: 100 Dec 05 16:22:30 volumio volumio[1210]: 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 16:22:30 volumio volumio[1210]: info: CoreCommandRouter::volumioGetState Dec 05 16:22:30 volumio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Dec 05 16:22:30 volumio volumio[1210]: SPOTIFY: SPOTIFY VOLUME 100 Dec 05 16:22:30 volumio volumio[1210]: SPOTIFY: VOLUMIO VOLUME 44 Dec 05 16:22:30 volumio volumio[1210]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 05 16:22:30 volumio volumio[1210]: info: Setting Spotify Volume from Volumio: 44 Dec 05 16:22:30 volumio volumio[1210]: info: Getting Spotify volume Dec 05 16:22:30 volumio volumio[1210]: info: Spotify volume: 100 Dec 05 16:22:30 volumio volumio[1210]: 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 16:22:30 volumio volumio[1210]: info: CoreCommandRouter::volumioGetState Dec 05 16:22:30 volumio volumio[1210]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Dec 05 16:22:30 volumio volumio[1210]: SPOTIFY: SPOTIFY VOLUME 100 Dec 05 16:22:30 volumio volumio[1210]: SPOTIFY: VOLUMIO VOLUME 44 Dec 05 16:22:30 volumio volumio[1210]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 05 16:22:30 volumio volumio[1210]: info: Setting Spotify Volume from Volumio: 44 Dec 05 16:22:31 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 05 16:22:31 volumio volumio[1210]: SPOTIFY: SETTING SPOTIFY VOLUME 44 Dec 05 16:22:31 volumio volumio[1210]: info: Sending Spotify command with payload to local API: /player/volume Dec 05 16:22:31 volumio go-librespot[18491]: time="2025-12-05T16:22:31+01:00" level=debug msg="update volume requested to 28835/65535" Dec 05 16:22:31 volumio go-librespot[18491]: time="2025-12-05T16:22:31+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 05 16:22:31 volumio go-librespot[18491]: time="2025-12-05T16:22:31+01:00" level=trace msg="emitting websocket event: volume" Dec 05 16:22:31 volumio volumio[1210]: SPOTIFY: received: {"type":"volume","data":{"value":44,"max":100}} Dec 05 16:22:31 volumio volumio[1210]: SPOTIFY: RECEIVED SPOTIFY VOLUME 44 Dec 05 16:22:31 volumio volumio[1210]: SPOTIFY: received: {"type":"volume","data":{"value":44,"max":100}} Dec 05 16:22:31 volumio volumio[1210]: SPOTIFY: RECEIVED SPOTIFY VOLUME 44 Dec 05 16:22:31 volumio volumio[1210]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 05 16:22:31 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 05 16:22:31 volumio volumio[1210]: info: Creating Spotify config file Dec 05 16:22:31 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 16:22:31 volumio volumio[1210]: info: Spotify config file written Dec 05 16:22:31 volumio sudo[18527]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 16:22:31 volumio sudo[18527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 16:22:32 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 16:22:32 volumio systemd[1]: go-librespot-daemon.service: Killing process 18492 (go-librespot) with signal SIGKILL. Dec 05 16:22:32 volumio volumio[1210]: info: Connection to go-librespot Websocket closed Dec 05 16:22:32 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 16:22:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 16:22:32 volumio volumio[1210]: info: Connection to go-librespot Websocket closed Dec 05 16:22:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 16:22:32 volumio go-librespot[18529]: go-librespot daemon starting... Dec 05 16:22:32 volumio sudo[18527]: pam_unix(sudo:session): session closed for user root Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="app state loaded" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+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 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+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 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+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 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=info msg="zeroconf server listening on port 45461" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="obtained new client token: AACpnD9nzKx3wJEpTlOcVNPsJiu1n84juurblwoaEO8nhtvkgnIjMphUGA27TrTnc1e7oA3cLK6cofQw+ibdN+HhSE7ZiRZ5Pa4Y/Mb4a8zo1b/Dg3p/9qRTuB7wHeMsQ/r4T2mRdiTAh3Pkg/Et1D0Pg+xku/nKRyQJqcoVB7K6C2JPgvkcKnFu27SsUxA7VfRERQB0xbDjkRU3p5ZI5GbhXCzo6uYuow3L71khNd2aRTgj/V+ITGW1zkQ=" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="completed keyexchange" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="completed challenge" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=info msg="authenticated AP" username="31************************f4" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=info msg="authenticated Login5" username="31************************f4" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="initializing zeroconf session" username="31************************f4" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="dealer connection opened" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=trace msg="starting accesspoint recv loop" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=trace msg="starting dealer recv loop" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=trace msg="received accesspoint ping" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="received connection id: NWY4NGJlNTgtMTEz...QUYwMDY0MjMwNA==" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=trace msg="received accesspoint pong ack" Dec 05 16:22:32 volumio go-librespot[18530]: time="2025-12-05T16:22:32+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 05 16:22:35 volumio volumio[1210]: info: Initializing connection to go-librespot Websocket Dec 05 16:22:35 volumio go-librespot[18530]: time="2025-12-05T16:22:35+01:00" level=debug msg="new websocket client" Dec 05 16:22:35 volumio volumio[1210]: info: Connection to go-librespot Websocket established Dec 05 16:22:35 volumio volumio[1210]: info: go-librespot daemon successfully initialized Dec 05 16:22:36 volumio volumio[1210]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 05 16:22:36 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 05 16:22:36 volumio volumio[1210]: info: Creating Spotify config file Dec 05 16:22:36 volumio volumio[1210]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 05 16:22:36 volumio volumio[1210]: info: Spotify config file written Dec 05 16:22:36 volumio sudo[18561]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 05 16:22:36 volumio sudo[18561]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 05 16:22:36 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 05 16:22:36 volumio systemd[1]: go-librespot-daemon.service: Killing process 18535 (go-librespot) with signal SIGKILL. Dec 05 16:22:36 volumio volumio[1210]: info: Connection to go-librespot Websocket closed Dec 05 16:22:36 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 05 16:22:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 05 16:22:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 05 16:22:36 volumio go-librespot[18563]: go-librespot daemon starting... Dec 05 16:22:36 volumio sudo[18561]: pam_unix(sudo:session): session closed for user root Dec 05 16:22:36 volumio go-librespot[18564]: time="2025-12-05T16:22:36+01:00" level=info msg="running go-librespot 0.4.0" Dec 05 16:22:36 volumio go-librespot[18564]: time="2025-12-05T16:22:36+01:00" level=debug msg="app state loaded" Dec 05 16:22:36 volumio go-librespot[18564]: time="2025-12-05T16:22:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 05 16:22:37 volumio go-librespot[18564]: time="2025-12-05T16:22:37+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 16:22:37 volumio go-librespot[18564]: time="2025-12-05T16:22:37+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 16:22:37 volumio go-librespot[18564]: time="2025-12-05T16:22:37+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 16:22:37 volumio go-librespot[18564]: time="2025-12-05T16:22:37+01:00" level=info msg="zeroconf server listening on port 46329" Dec 05 16:22:37 volumio go-librespot[18564]: time="2025-12-05T16:22:37+01:00" level=debug msg="obtained new client token: AABeyE0wAgp6McphEQQJa8bUldDALBQrsALbOWLuWbINOizW0SRtXvubZ+HZM3PrF32NpCOevOsm9WgJBoYDpGbSROA1i6600lV5Yd/4B9qZF3VHEUX8r/ICu7sYCgV2S+LmhmgMTNes0NrlgIYDtSJVzVZa4IZGOf9dvmX+vUEL7F8vRaP+j2fLopl0zjgF8k9Cawj4q4n8Bipy+Mr3YfebWnVCtsBKNMj5veycpmGnzpZlrAJc1Iaa" Dec 05 16:22:37 volumio go-librespot[18564]: time="2025-12-05T16:22:37+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 05 16:22:37 volumio go-librespot[18564]: time="2025-12-05T16:22:37+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 05 16:22:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 05 16:22:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 05 16:22:38 volumio volumio[1210]: info: Getting Spotify volume Dec 05 16:22:38 volumio volumio[1210]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 05 16:22:38 volumio volumio[1210]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 05 16:22:38 volumio volumio[1210]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 05 16:22:38 volumio volumio[1210]: errno: -111, Dec 05 16:22:38 volumio volumio[1210]: code: 'ECONNREFUSED', Dec 05 16:22:38 volumio volumio[1210]: syscall: 'connect', Dec 05 16:22:38 volumio volumio[1210]: address: '127.0.0.1', Dec 05 16:22:38 volumio volumio[1210]: port: 9879, Dec 05 16:22:38 volumio volumio[1210]: response: undefined Dec 05 16:22:38 volumio volumio[1210]: } Dec 05 16:22:38 volumio volumio[1210]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 05 16:22:38 volumio sudo[18591]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-05 16:21' Dec 05 16:22:38 volumio sudo[18591]: 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"