Dec 29 23:08:06 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:06 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:06 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:06 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:06 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:06 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:11 volumio go-librespot[17623]: time="2025-12-29T23:08:11+02:00" level=trace msg="sent dealer ping" Dec 29 23:08:11 volumio go-librespot[17623]: time="2025-12-29T23:08:11+02:00" level=trace msg="received dealer pong" Dec 29 23:08:16 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:16 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:26 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:26 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:26 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:26 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:26 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:26 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:36 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:36 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:37 volumio volumio[1158]: info: [ytcr] (gZsz3AGj5i4) fetching player data using YTMUSIC client... Dec 29 23:08:38 volumio volumio[1158]: info: [ytcr] (Laužai) validating stream URL "https://rr1---sn-uxv-8ovs.googlevideo.com/videoplayback?expire=1767064117&ei=1e1SacjWH5_i6dsP9oK9yQo&ip=78.62.126.178&id=o-AMbqLvcxBNzKW5RBDbjzTCX9Ytng6iLnQtUp2g5YYFBN&itag=251&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&cps=244&met=1767042517%2C&mh=Vg&mm=31%2C29&mn=sn-uxv-8ovs%2Csn-f5f7lne6&ms=au%2Crdu&mv=m&mvi=1&pcm2cms=yes&pl=22&rms=au%2Cau&gcr=lt&initcwndbps=2857500&siu=1&bui=AYUSA3AO5QhqoFmHF5x4PPAvElZFAUBrp1NmpT_RvGwsnvWrR3ZCPlCWhVNDlYb2TVsA3wQL0w&spc=wH4QqyofUQIw2vJn9fQvc2FDi6saedTIPr1BgWauRAmw78fJ7FV7BkibMPEklrB7mwg&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=O90MfS8COncnN3ezLyQjzSgR&rqh=1&gir=yes&clen=2753588&dur=157.521&lmt=1761992780688066&mt=1767042120&fvip=5&keepalive=yes&fexp=51552689%2C51565116%2C51565682%2C51580968&c=WEB_REMIX&sefc=1&txp=5532534&n=WmCJ-PgEFNGf7A&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cxpc%2Cgcr%2Csiu%2Cbui%2Cspc%2Cvprv%2Csvpuc%2Cmime%2Cns%2Crqh%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=cps%2Cmet%2Cmh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpcm2cms%2Cpl%2Crms%2Cinitcwndbps&lsig=APaTxxMwRAIgRpbj62jNFcSUGRezUZWfSvHngEaBg3rPe-EK9TppoasCICH5cOIjg_vVqLprZSVCopjX6WhWPi6Gvq_PjRg_igoo&sig=AJfQdSswRgIhANDYrYaboiVJA3GBkAkFVeUvQnWYTE98E8pJlevkgr_vAiEAlcdrgOXDTcqK-FtRUPHXIor0pC-ecBdy19wfi5OMCaI%3D&pot=MlWx-BjJbLMA_rHGQu1GuUgWQzsAD7vLcnKgX0Sy21GW4VBJBkbvpxA-KO3NrfImiHDVDNhfqIM_418tAqt4aT9m1vHmyAQl3XdMHTGkraH0KPr4lh5T&cver=1.20250219.01.00"... Dec 29 23:08:38 volumio volumio[1158]: info: [ytcr] (Laužai) stream validated in 0.184s. Dec 29 23:08:38 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:38 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:38 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:38 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:38 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:38 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:38 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:38 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:41 volumio go-librespot[17623]: time="2025-12-29T23:08:41+02:00" level=trace msg="sent dealer ping" Dec 29 23:08:41 volumio go-librespot[17623]: time="2025-12-29T23:08:41+02:00" level=trace msg="received dealer pong" Dec 29 23:08:46 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:46 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:46 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:46 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:46 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:46 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:49 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:49 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:49 volumio volumio[1158]: info: Ignoring MPD Status Update Dec 29 23:08:49 volumio volumio[1158]: verbose: ControllerMpd::sendMpdCommand status Dec 29 23:08:49 volumio volumio[1158]: verbose: ControllerMpd::sendMpdCommand status Dec 29 23:08:49 volumio volumio[1158]: info: sendMpdCommand status took 0 milliseconds Dec 29 23:08:49 volumio volumio[1158]: info: sendMpdCommand status took 1 milliseconds Dec 29 23:08:49 volumio volumio[1158]: verbose: ControllerMpd::parseState Dec 29 23:08:49 volumio volumio[1158]: info: CorePlayQueue::getTrack 0 Dec 29 23:08:49 volumio volumio[1158]: verbose: ControllerMpd::parseState Dec 29 23:08:49 volumio volumio[1158]: info: CorePlayQueue::getTrack 0 Dec 29 23:08:52 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:52 volumio volumio[1158]: info: CoreCommandRouter::servicePushState Dec 29 23:08:52 volumio volumio[1158]: info: CoreStateMachine::pushState Dec 29 23:08:52 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 23:08:52 volumio volumio[1158]: info: CoreCommandRouter::volumioPushState Dec 29 23:08:52 volumio volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Dec 29 23:08:52 volumio volumio[1158]: info: MRS: Pushing multiroomSync output Dec 29 23:08:52 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:52 volumio volumio[1158]: info: MRS: Pushing multiroomSync output update for this device Dec 29 23:08:52 volumio volumio[1158]: info: MRS: Pushing multiroomSync output Dec 29 23:08:52 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:52 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 67 Dec 29 23:08:53 volumio volumio[1158]: info: Received OAUTH Data Dec 29 23:08:53 volumio volumio[1158]: info: Executing Spotify Oauth Login Dec 29 23:08:53 volumio volumio[1158]: info: Saving Spotify Refresh Token Dec 29 23:08:53 volumio sudo[22129]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 23:08:53 volumio sudo[22129]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:08:53 volumio sudo[22129]: pam_unix(sudo:session): session closed for user root Dec 29 23:08:53 volumio sudo[22131]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 23:08:53 volumio sudo[22131]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:08:53 volumio sudo[22131]: pam_unix(sudo:session): session closed for user root Dec 29 23:08:53 volumio volumio[1158]: verbose: New Socket.io Connection to 192.168.1.138 from 192.168.1.127 UA: Mozilla/5.0 (Linux; Android 16; SM-A556B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/143.0.7499.34 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Dec 29 23:08:53 volumio volumio[1158]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 23:08:53 volumio volumio[1158]: SPOTIFY: BQBJoT4HAevYJf1_OjW4eTKdTpQlZjf6orUxxNJRvzj6TYokWrN_y-6wrjFESSD2bK2HSkQ1Vcqccj8qa_8Rmoa2ahuNO_ari2_KJ99mc9BUCr_GPXH-ofrXZ0GZo0qPKq3r2SgKVPd_XDZ-3jCmUqvgU8vsxMgV5Y4fnxXGl4QFmdvbEDjsKh6-zg2QWGnJL-bw6fWyv4QeA49mVE1gNBet5-J2mqiNgHpTRNC8NKIs7xuUpS8YVGGGBvg6amTaRTXTcBNQtvyjRtDNUHguZukXaMEnQ74-PEWDmjb8FNOO-duU6i14VaruR6PU Dec 29 23:08:53 volumio volumio[1158]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 23:08:53 volumio volumio[1158]: info: New Spotify access token = BQBJoT4HAevYJf1_OjW4eTKdTpQlZjf6orUxxNJRvzj6TYokWrN_y-6wrjFESSD2bK2HSkQ1Vcqccj8qa_8Rmoa2ahuNO_ari2_KJ99mc9BUCr_GPXH-ofrXZ0GZo0qPKq3r2SgKVPd_XDZ-3jCmUqvgU8vsxMgV5Y4fnxXGl4QFmdvbEDjsKh6-zg2QWGnJL-bw6fWyv4QeA49mVE1gNBet5-J2mqiNgHpTRNC8NKIs7xuUpS8YVGGGBvg6amTaRTXTcBNQtvyjRtDNUHguZukXaMEnQ74-PEWDmjb8FNOO-duU6i14VaruR6PU Dec 29 23:08:53 volumio volumio[1158]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::volumioGetVisibleSources Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 29 23:08:53 volumio volumio[1158]: info: Received Get System Info Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 29 23:08:53 volumio volumio[1158]: info: Discovery: Getting this device information Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:53 volumio volumio[1158]: info: Listing playlists Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 29 23:08:53 volumio volumio[1158]: SPOTIFY: User informations: {"country":"LT","display_name":"Eligijus Ubis","email":"eligijusubis@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31uriava4qmjb56ip363f4gsfruq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31uriava4qmjb56ip363f4gsfruq","id":"31uriava4qmjb56ip363f4gsfruq","images":[],"product":"premium","type":"user","uri":"spotify:user:31uriava4qmjb56ip363f4gsfruq"} Dec 29 23:08:53 volumio volumio[1158]: info: Creating Spotify config file Dec 29 23:08:53 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 23:08:53 volumio volumio[1158]: info: Spotify config file written Dec 29 23:08:53 volumio sudo[22135]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 23:08:53 volumio sudo[22135]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:08:53 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 23:08:53 volumio systemd[1]: go-librespot-daemon.service: Killing process 17625 (go-librespot) with signal SIGKILL. Dec 29 23:08:53 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 23:08:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:08:53 volumio volumio[1158]: info: Connection to go-librespot Websocket closed Dec 29 23:08:53 volumio systemd[1]: go-librespot-daemon.service: Consumed 1.026s CPU time. Dec 29 23:08:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:08:53 volumio go-librespot[22137]: go-librespot daemon starting... Dec 29 23:08:53 volumio sudo[22135]: pam_unix(sudo:session): session closed for user root Dec 29 23:08:53 volumio go-librespot[22138]: time="2025-12-29T23:08:53+02:00" level=info msg="running go-librespot 0.4.0" Dec 29 23:08:53 volumio go-librespot[22138]: time="2025-12-29T23:08:53+02:00" level=debug msg="app state loaded" Dec 29 23:08:53 volumio go-librespot[22138]: time="2025-12-29T23:08:53+02:00" level=debug msg="stored credentials not found" Dec 29 23:08:53 volumio go-librespot[22138]: time="2025-12-29T23:08:53+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 23:08:54 volumio volumio[1158]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 23:08:54 volumio volumio[1158]: SPOTIFY: BQBSvxHlTnEkRD08i3_HOk9X8KEfJXrPVI0rsWFWfaKzxh4d47reEJJ-RoE6nzi9IVOHuquMejIrD4YAzSYW6KZ7tiUphmnEGgwBYgpSXm6BhQLp34RZD2hZTB1uThT6CdJXcsNU0hYrr0V_T0LSWkqaAyWIcpn9OUBQJ_8WtKwIxx7gkoDr_DXToRrxxzVGDDpzj6mgbJIfSq_AtZFfVR01yTL3rrpR6pxVaKrmpVnrnNS2HQQ5DBT0NHNFHYS-SPN9aK7QzvFEaSc6kr61q-K9mhDnaeN2SYnMmcz2C8q1riVmahSC3VtA3p9k Dec 29 23:08:54 volumio volumio[1158]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 29 23:08:54 volumio volumio[1158]: info: New Spotify access token = BQBSvxHlTnEkRD08i3_HOk9X8KEfJXrPVI0rsWFWfaKzxh4d47reEJJ-RoE6nzi9IVOHuquMejIrD4YAzSYW6KZ7tiUphmnEGgwBYgpSXm6BhQLp34RZD2hZTB1uThT6CdJXcsNU0hYrr0V_T0LSWkqaAyWIcpn9OUBQJ_8WtKwIxx7gkoDr_DXToRrxxzVGDDpzj6mgbJIfSq_AtZFfVR01yTL3rrpR6pxVaKrmpVnrnNS2HQQ5DBT0NHNFHYS-SPN9aK7QzvFEaSc6kr61q-K9mhDnaeN2SYnMmcz2C8q1riVmahSC3VtA3p9k Dec 29 23:08:54 volumio volumio[1158]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=info msg="zeroconf server listening on port 39477" Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=debug msg="obtained new client token: AABrDUt//gNlpty1KRdKYaa4Tlo7RZ9tzPyoQs6EPZUJdN0VM8+oQtzpiSHcdbceD8AJepvTd1YOhx8dWDqSdRTFRaEi0c1EPtV3ew3lYISE9ozMIvMallaQpkvIrsxqQvC+ErXUmJR9Db2P0qqEmyF9YMbukyD0w/fXu/YVFGzZwh5NjZn5bzrDGKDuRNahb2xm6rcxVrNxhsAMFBSSSCc2dLUTgsZm6dRXrWUNvXGzqVL5hnoPMEJ3Pw==" Dec 29 23:08:54 volumio volumio[1158]: SPOTIFY: User informations: {"country":"LT","display_name":"Eligijus Ubis","email":"eligijusubis@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31uriava4qmjb56ip363f4gsfruq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31uriava4qmjb56ip363f4gsfruq","id":"31uriava4qmjb56ip363f4gsfruq","images":[],"product":"premium","type":"user","uri":"spotify:user:31uriava4qmjb56ip363f4gsfruq"} Dec 29 23:08:54 volumio volumio[1158]: info: Spotify Successfully logged in Dec 29 23:08:54 volumio volumio[1158]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 23:08:54 volumio volumio[1158]: info: [1767042534632] CoreMusicLibrary::Adding element Spotify Dec 29 23:08:54 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 23:08:54 volumio volumio[1158]: Cannot find translation for source SoundCloud Dec 29 23:08:54 volumio volumio[1158]: Cannot find translation for source Podcast Dec 29 23:08:54 volumio volumio[1158]: Cannot find translation for source Spotify Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=debug msg="completed keyexchange" Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=debug msg="completed challenge" Dec 29 23:08:54 volumio go-librespot[22138]: time="2025-12-29T23:08:54+02:00" level=info msg="authenticated AP" username="31************************uq" Dec 29 23:08:55 volumio go-librespot[22138]: time="2025-12-29T23:08:55+02:00" level=info msg="authenticated Login5" username="31************************uq" Dec 29 23:08:55 volumio go-librespot[22138]: time="2025-12-29T23:08:55+02:00" level=debug msg="stored credentials" username="31************************uq" Dec 29 23:08:55 volumio go-librespot[22138]: time="2025-12-29T23:08:55+02:00" level=debug msg="initializing zeroconf session" username="31************************uq" Dec 29 23:08:55 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 29 23:08:55 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 29 23:08:55 volumio volumio[1158]: info: Received Get System Info Dec 29 23:08:55 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 29 23:08:55 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 29 23:08:55 volumio volumio[1158]: info: Discovery: Getting this device information Dec 29 23:08:55 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:55 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="dealer connection opened" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=trace msg="starting accesspoint recv loop" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=trace msg="starting dealer recv loop" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=trace msg="received accesspoint ping" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="received connection id: OWRhZTU5MjUtZGJj...NTI5NjlBNzNGOA==" Dec 29 23:08:56 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:56 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:56 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 29 23:08:56 volumio volumio[1158]: info: Received Get System Info Dec 29 23:08:56 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 29 23:08:56 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 29 23:08:56 volumio volumio[1158]: info: Discovery: Getting this device information Dec 29 23:08:56 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:56 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=trace msg="received accesspoint pong ack" Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="put connect state because NEW_DEVICE" Dec 29 23:08:56 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket Dec 29 23:08:56 volumio go-librespot[22138]: time="2025-12-29T23:08:56+02:00" level=debug msg="new websocket client" Dec 29 23:08:56 volumio volumio[1158]: info: Connection to go-librespot Websocket established Dec 29 23:08:56 volumio volumio[1158]: info: go-librespot daemon successfully initialized Dec 29 23:08:59 volumio volumio[1158]: info: Getting Spotify volume Dec 29 23:08:59 volumio volumio[1158]: info: Spotify volume: 100 Dec 29 23:08:59 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Dec 29 23:08:59 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket Dec 29 23:08:59 volumio go-librespot[22138]: time="2025-12-29T23:08:59+02:00" level=debug msg="new websocket client" Dec 29 23:08:59 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:08:59 volumio volumio[1158]: info: Connection to go-librespot Websocket established Dec 29 23:08:59 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 67 Dec 29 23:08:59 volumio volumio[1158]: SPOTIFY: SPOTIFY VOLUME 100 Dec 29 23:08:59 volumio volumio[1158]: SPOTIFY: VOLUMIO VOLUME 67 Dec 29 23:08:59 volumio volumio[1158]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 29 23:08:59 volumio volumio[1158]: info: Setting Spotify Volume from Volumio: 67 Dec 29 23:09:01 volumio volumio[1158]: SPOTIFY: SETTING SPOTIFY VOLUME 67 Dec 29 23:09:01 volumio volumio[1158]: info: Sending Spotify command with payload to local API: /player/volume Dec 29 23:09:01 volumio go-librespot[22138]: time="2025-12-29T23:09:01+02:00" level=debug msg="update volume requested to 43908/65535" Dec 29 23:09:01 volumio go-librespot[22138]: time="2025-12-29T23:09:01+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 29 23:09:01 volumio go-librespot[22138]: time="2025-12-29T23:09:01+02:00" level=trace msg="emitting websocket event: volume" Dec 29 23:09:01 volumio volumio[1158]: SPOTIFY: received: {"type":"volume","data":{"value":67,"max":100}} Dec 29 23:09:01 volumio volumio[1158]: SPOTIFY: RECEIVED SPOTIFY VOLUME 67 Dec 29 23:09:01 volumio volumio[1158]: SPOTIFY: received: {"type":"volume","data":{"value":67,"max":100}} Dec 29 23:09:01 volumio volumio[1158]: SPOTIFY: RECEIVED SPOTIFY VOLUME 67 Dec 29 23:09:02 volumio volumio[1158]: info: Getting Spotify volume Dec 29 23:09:02 volumio volumio[1158]: info: Spotify volume: 67 Dec 29 23:09:02 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Dec 29 23:09:02 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:02 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 67 Dec 29 23:09:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 29 23:09:06 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:06 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:06 volumio volumio[1158]: info: Listing playlists Dec 29 23:09:06 volumio volumio[1158]: info: Listing playlists Dec 29 23:09:06 volumio volumio[1158]: info: Listing playlists Dec 29 23:09:06 volumio volumio[1158]: info: Listing playlists Dec 29 23:09:07 volumio volumiossh-tunnel[21982]: Connection to eu10.myvolumio.org closed by remote host. Dec 29 23:09:07 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:07 volumio autossh[21979]: starting ssh (count 2) Dec 29 23:09:07 volumio autossh[21979]: ssh child pid is 22177 Dec 29 23:09:07 volumio volumiossh-tunnel[22177]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 29 23:09:07 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:07 volumio autossh[21979]: starting ssh (count 3) Dec 29 23:09:07 volumio autossh[21979]: ssh child pid is 22178 Dec 29 23:09:07 volumio volumiossh-tunnel[22178]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 29 23:09:07 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:07 volumio autossh[21979]: starting ssh (count 4) Dec 29 23:09:07 volumio autossh[21979]: ssh child pid is 22179 Dec 29 23:09:08 volumio volumiossh-tunnel[22179]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 29 23:09:08 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:08 volumio autossh[21979]: starting ssh (count 5) Dec 29 23:09:08 volumio autossh[21979]: ssh child pid is 22180 Dec 29 23:09:08 volumio volumiossh-tunnel[22180]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 29 23:09:08 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:08 volumio autossh[21979]: starting ssh (count 6) Dec 29 23:09:08 volumio autossh[21979]: ssh child pid is 22181 Dec 29 23:09:08 volumio volumiossh-tunnel[22181]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 29 23:09:08 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:08 volumio autossh[21979]: starting ssh (count 7) Dec 29 23:09:08 volumio autossh[21979]: ssh child pid is 22182 Dec 29 23:09:08 volumio volumiossh-tunnel[22182]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 29 23:09:08 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:10 volumio autossh[21979]: starting ssh (count 8) Dec 29 23:09:10 volumio autossh[21979]: ssh child pid is 22183 Dec 29 23:09:10 volumio volumiossh-tunnel[22183]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 29 23:09:10 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:11 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 29 23:09:11 volumio volumio[1158]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 29 23:09:11 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 29 23:09:11 volumio volumio[1158]: info: Received Get System Version Dec 29 23:09:11 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 23:09:11 volumio volumio[1158]: info: Received Get System Info Dec 29 23:09:11 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 29 23:09:11 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 29 23:09:11 volumio volumio[1158]: info: Discovery: Getting this device information Dec 29 23:09:11 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:11 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 29 23:09:16 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:16 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:17 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 29 23:09:17 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 29 23:09:17 volumio volumio[1158]: info: Creating Spotify config file Dec 29 23:09:17 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 23:09:17 volumio volumio[1158]: info: Spotify config file written Dec 29 23:09:17 volumio sudo[22202]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 23:09:17 volumio sudo[22202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:09:17 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 23:09:17 volumio volumio[1158]: info: Connection to go-librespot Websocket closed Dec 29 23:09:17 volumio volumio[1158]: info: Connection to go-librespot Websocket closed Dec 29 23:09:17 volumio systemd[1]: go-librespot-daemon.service: Killing process 22143 (go-librespot) with signal SIGKILL. Dec 29 23:09:17 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 23:09:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:17 volumio go-librespot[22204]: go-librespot daemon starting... Dec 29 23:09:17 volumio sudo[22202]: pam_unix(sudo:session): session closed for user root Dec 29 23:09:17 volumio go-librespot[22205]: time="2025-12-29T23:09:17+02:00" level=info msg="running go-librespot 0.4.0" Dec 29 23:09:17 volumio go-librespot[22205]: time="2025-12-29T23:09:17+02:00" level=debug msg="app state loaded" Dec 29 23:09:17 volumio go-librespot[22205]: time="2025-12-29T23:09:17+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 23:09:17 volumio go-librespot[22205]: time="2025-12-29T23:09:17+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 29 23:09:17 volumio go-librespot[22205]: time="2025-12-29T23:09:17+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 29 23:09:17 volumio go-librespot[22205]: time="2025-12-29T23:09:17+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 29 23:09:17 volumio go-librespot[22205]: time="2025-12-29T23:09:17+02:00" level=info msg="zeroconf server listening on port 45375" Dec 29 23:09:17 volumio go-librespot[22205]: time="2025-12-29T23:09:17+02:00" level=debug msg="obtained new client token: AAABsFRbuWbC8hBve9fMvXjZ+X6VPsdlLZ4EDu/ViX2pfAuaYbYseVTCPkjRr5E06yVmC3ALivfxoBgU5RYAspJ97RdjyeWDK5KqzSj7+7l6Z2i2kpL7xyUJ+IuU5ESF1P7vgJDYGR5yK1C3JKK5GMSZUFGSqGLfYPM9JH/XYQQy29u+312/mmuB59yLCLHgEMUn5ewy2P1uMtU2O7PP3I25wXW22Jtm0GLXVhZLa0h/K0ZElX/FvfvA0w==" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="completed keyexchange" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="completed challenge" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=info msg="authenticated AP" username="31************************uq" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=info msg="authenticated Login5" username="31************************uq" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="initializing zeroconf session" username="31************************uq" Dec 29 23:09:18 volumio autossh[21979]: starting ssh (count 9) Dec 29 23:09:18 volumio autossh[21979]: ssh child pid is 22213 Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="dealer connection opened" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=trace msg="starting accesspoint recv loop" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=trace msg="starting dealer recv loop" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=trace msg="received accesspoint ping" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="received connection id: YzY0YmI5ZjAtNGRi...MzQ3MUU5Q0ZGQQ==" Dec 29 23:09:18 volumio volumiossh-tunnel[22213]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 29 23:09:18 volumio autossh[21979]: ssh exited with error status 255; restarting ssh Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=trace msg="received accesspoint pong ack" Dec 29 23:09:18 volumio go-librespot[22205]: time="2025-12-29T23:09:18+02:00" level=debug msg="put connect state because NEW_DEVICE" Dec 29 23:09:20 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket Dec 29 23:09:20 volumio go-librespot[22205]: time="2025-12-29T23:09:20+02:00" level=debug msg="new websocket client" Dec 29 23:09:20 volumio volumio[1158]: info: Connection to go-librespot Websocket established Dec 29 23:09:20 volumio volumio[1158]: info: go-librespot daemon successfully initialized Dec 29 23:09:22 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 29 23:09:22 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 29 23:09:22 volumio volumio[1158]: info: Creating Spotify config file Dec 29 23:09:22 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 23:09:22 volumio volumio[1158]: info: Spotify config file written Dec 29 23:09:22 volumio sudo[22216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 23:09:22 volumio sudo[22216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:09:22 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 23:09:22 volumio systemd[1]: go-librespot-daemon.service: Killing process 22210 (go-librespot) with signal SIGKILL. Dec 29 23:09:22 volumio volumio[1158]: info: Connection to go-librespot Websocket closed Dec 29 23:09:22 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 23:09:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:22 volumio go-librespot[22218]: go-librespot daemon starting... Dec 29 23:09:22 volumio sudo[22216]: pam_unix(sudo:session): session closed for user root Dec 29 23:09:22 volumio go-librespot[22219]: time="2025-12-29T23:09:22+02:00" level=info msg="running go-librespot 0.4.0" Dec 29 23:09:22 volumio go-librespot[22219]: time="2025-12-29T23:09:22+02:00" level=debug msg="app state loaded" Dec 29 23:09:22 volumio go-librespot[22219]: time="2025-12-29T23:09:22+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=info msg="zeroconf server listening on port 40137" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="obtained new client token: AACWc/dJql/V+jVVRPFA4Qo2LBi+SUs0chf0dgsp5uYi4vvgHZNtxO0jq4ZdYstFpmS2e7R2Jx7MOAqPIiRttO/v0oQZxwMNjR6jNac6ecs099V18wEndRNwmg5L3iekIsNWXHTysrZb7EbRZ478+sMCEpbog/+ZvtPOCRdtMuTkmGkBbq0+eWguYl7OP3a+wuR+gd1g1fjJ4r+e6pJbJ+QLi6dhvnVhzN9jf1E9PGsrQ9JXr2d4SPc=" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="completed keyexchange" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="completed challenge" Dec 29 23:09:23 volumio volumio[1158]: info: Getting Spotify volume Dec 29 23:09:23 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 29 23:09:23 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:23 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 67 Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=info msg="authenticated AP" username="31************************uq" Dec 29 23:09:23 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="new websocket client" Dec 29 23:09:23 volumio volumio[1158]: info: Connection to go-librespot Websocket established Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=info msg="authenticated Login5" username="31************************uq" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="initializing zeroconf session" username="31************************uq" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="dealer connection opened" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=trace msg="starting accesspoint recv loop" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=trace msg="starting dealer recv loop" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=trace msg="received accesspoint ping" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 29 23:09:23 volumio volumio[1158]: info: Spotify volume: 100 Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=debug msg="received connection id: MjIxNWJkZTktZGM5...RjlBMDIxMzY1QQ==" Dec 29 23:09:23 volumio go-librespot[22219]: time="2025-12-29T23:09:23+02:00" level=trace msg="received accesspoint pong ack" Dec 29 23:09:24 volumio go-librespot[22219]: time="2025-12-29T23:09:24+02:00" level=debug msg="put connect state because NEW_DEVICE" Dec 29 23:09:25 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket Dec 29 23:09:25 volumio go-librespot[22219]: time="2025-12-29T23:09:25+02:00" level=debug msg="new websocket client" Dec 29 23:09:25 volumio volumio[1158]: info: Connection to go-librespot Websocket established Dec 29 23:09:25 volumio volumio[1158]: info: go-librespot daemon successfully initialized Dec 29 23:09:26 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:26 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:26 volumio volumio[1158]: info: Listing playlists Dec 29 23:09:26 volumio volumio[1158]: info: Listing playlists Dec 29 23:09:26 volumio volumio[1158]: info: Listing playlists Dec 29 23:09:26 volumio volumio[1158]: info: Listing playlists Dec 29 23:09:26 volumio volumio[1158]: info: Getting Spotify volume Dec 29 23:09:26 volumio volumio[1158]: info: Spotify volume: 100 Dec 29 23:09:26 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 29 23:09:26 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:26 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 67 Dec 29 23:09:26 volumio volumio[1158]: SPOTIFY: SPOTIFY VOLUME 100 Dec 29 23:09:26 volumio volumio[1158]: SPOTIFY: VOLUMIO VOLUME 67 Dec 29 23:09:26 volumio volumio[1158]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 29 23:09:26 volumio volumio[1158]: info: Setting Spotify Volume from Volumio: 67 Dec 29 23:09:28 volumio volumio[1158]: SPOTIFY: SETTING SPOTIFY VOLUME 67 Dec 29 23:09:28 volumio volumio[1158]: info: Sending Spotify command with payload to local API: /player/volume Dec 29 23:09:28 volumio go-librespot[22219]: time="2025-12-29T23:09:28+02:00" level=debug msg="update volume requested to 43908/65535" Dec 29 23:09:28 volumio go-librespot[22219]: time="2025-12-29T23:09:28+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 29 23:09:28 volumio go-librespot[22219]: time="2025-12-29T23:09:28+02:00" level=trace msg="emitting websocket event: volume" Dec 29 23:09:28 volumio volumio[1158]: SPOTIFY: received: {"type":"volume","data":{"value":67,"max":100}} Dec 29 23:09:28 volumio volumio[1158]: SPOTIFY: RECEIVED SPOTIFY VOLUME 67 Dec 29 23:09:28 volumio volumio[1158]: SPOTIFY: received: {"type":"volume","data":{"value":67,"max":100}} Dec 29 23:09:28 volumio volumio[1158]: SPOTIFY: RECEIVED SPOTIFY VOLUME 67 Dec 29 23:09:28 volumio volumio[1158]: info: Getting Spotify volume Dec 29 23:09:28 volumio volumio[1158]: info: Spotify volume: 67 Dec 29 23:09:28 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 29 23:09:28 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState Dec 29 23:09:28 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 67 Dec 29 23:09:28 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket Dec 29 23:09:28 volumio go-librespot[22219]: time="2025-12-29T23:09:28+02:00" level=debug msg="new websocket client" Dec 29 23:09:28 volumio volumio[1158]: info: Connection to go-librespot Websocket established Dec 29 23:09:30 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 29 23:09:30 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 29 23:09:30 volumio volumio[1158]: info: Creating Spotify config file Dec 29 23:09:30 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 23:09:30 volumio volumio[1158]: info: Spotify config file written Dec 29 23:09:30 volumio sudo[22243]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 23:09:30 volumio sudo[22243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:09:31 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 29 23:09:31 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 23:09:31 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 23:09:31 volumio volumio[1158]: info: Connection to go-librespot Websocket closed Dec 29 23:09:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:31 volumio volumio[1158]: info: Connection to go-librespot Websocket closed Dec 29 23:09:31 volumio volumio[1158]: info: Connection to go-librespot Websocket closed Dec 29 23:09:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:31 volumio sudo[22243]: pam_unix(sudo:session): session closed for user root Dec 29 23:09:31 volumio go-librespot[22248]: go-librespot daemon starting... Dec 29 23:09:31 volumio go-librespot[22252]: time="2025-12-29T23:09:31+02:00" level=info msg="running go-librespot 0.4.0" Dec 29 23:09:31 volumio go-librespot[22252]: time="2025-12-29T23:09:31+02:00" level=debug msg="app state loaded" Dec 29 23:09:31 volumio go-librespot[22252]: time="2025-12-29T23:09:31+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 23:09:31 volumio go-librespot[22252]: time="2025-12-29T23:09:31+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 29 23:09:31 volumio go-librespot[22252]: time="2025-12-29T23:09:31+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 29 23:09:31 volumio go-librespot[22252]: time="2025-12-29T23:09:31+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 29 23:09:31 volumio go-librespot[22252]: time="2025-12-29T23:09:31+02:00" level=info msg="zeroconf server listening on port 38899" Dec 29 23:09:31 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 29 23:09:31 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 29 23:09:31 volumio volumio[1158]: info: Creating Spotify config file Dec 29 23:09:31 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 23:09:31 volumio volumio[1158]: info: Spotify config file written Dec 29 23:09:31 volumio sudo[22271]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 23:09:31 volumio sudo[22271]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:09:31 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 23:09:31 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 23:09:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:31 volumio go-librespot[22273]: go-librespot daemon starting... Dec 29 23:09:31 volumio sudo[22271]: pam_unix(sudo:session): session closed for user root Dec 29 23:09:31 volumio go-librespot[22274]: time="2025-12-29T23:09:31+02:00" level=info msg="running go-librespot 0.4.0" Dec 29 23:09:31 volumio go-librespot[22274]: time="2025-12-29T23:09:31+02:00" level=debug msg="app state loaded" Dec 29 23:09:31 volumio go-librespot[22274]: time="2025-12-29T23:09:31+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 23:09:31 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 29 23:09:31 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 29 23:09:31 volumio volumio[1158]: info: Creating Spotify config file Dec 29 23:09:31 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 23:09:31 volumio volumio[1158]: info: Spotify config file written Dec 29 23:09:31 volumio sudo[22281]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 23:09:31 volumio sudo[22281]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:09:31 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 23:09:31 volumio systemd[1]: go-librespot-daemon.service: Killing process 22279 (go-librespot) with signal SIGKILL. Dec 29 23:09:31 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 23:09:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 23:09:31 volumio sudo[22281]: pam_unix(sudo:session): session closed for user root Dec 29 23:09:31 volumio go-librespot[22283]: go-librespot daemon starting... Dec 29 23:09:31 volumio volumio[1158]: info: Getting Spotify volume Dec 29 23:09:31 volumio volumio[1158]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 23:09:31 volumio volumio[1158]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 29 23:09:31 volumio volumio[1158]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 29 23:09:31 volumio volumio[1158]: errno: -111, Dec 29 23:09:31 volumio volumio[1158]: code: 'ECONNREFUSED', Dec 29 23:09:31 volumio volumio[1158]: syscall: 'connect', Dec 29 23:09:31 volumio volumio[1158]: address: '127.0.0.1', Dec 29 23:09:31 volumio volumio[1158]: port: 9879, Dec 29 23:09:31 volumio volumio[1158]: response: undefined Dec 29 23:09:31 volumio volumio[1158]: } Dec 29 23:09:31 volumio volumio[1158]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 23:09:31 volumio go-librespot[22284]: time="2025-12-29T23:09:31+02:00" level=info msg="running go-librespot 0.4.0" Dec 29 23:09:31 volumio go-librespot[22284]: time="2025-12-29T23:09:31+02:00" level=debug msg="app state loaded" Dec 29 23:09:31 volumio go-librespot[22284]: time="2025-12-29T23:09:31+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 23:09:32 volumio go-librespot[22284]: time="2025-12-29T23:09:32+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 29 23:09:32 volumio go-librespot[22284]: time="2025-12-29T23:09:32+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 29 23:09:32 volumio go-librespot[22284]: time="2025-12-29T23:09:32+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 29 23:09:32 volumio go-librespot[22284]: time="2025-12-29T23:09:32+02:00" level=info msg="zeroconf server listening on port 42673" Dec 29 23:09:32 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 29 23:09:32 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 29 23:09:32 volumio sudo[22314]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-29 23:08' Dec 29 23:09:32 volumio sudo[22314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 23:09:32 volumio go-librespot[22284]: time="2025-12-29T23:09:32+02:00" level=debug msg="obtained new client token: AADUgHBakpE/sC9Hna8kAkUFDZsbAyOuOCrLI6VMDi16J7YNCW5wVQX3SXHPvn5G9E8ziUIuOCqsqJD/xjOBgsyJvjvi2Wxr20b0t0f14LMvU1zlmI5sS03QMPGp8wW5AtRkisXRrb6Hz8OypH6cSRVm86SP5hycSpK6bSCS417MpgwHH1eEm315mBvfVoWbPFTBRQgZI5TwexmLgnsE+CR7tczISnw64OToDl2Q5VmTcWrN/kd5orA=" 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"