Jan 10 23:15:19 volumio go-librespot[1983]: time="2026-01-10T23:15:19-05:00" level=trace msg="received accesspoint ping" Jan 10 23:15:19 volumio go-librespot[1983]: time="2026-01-10T23:15:19-05:00" level=trace msg="received accesspoint pong ack" Jan 10 23:15:19 volumio go-librespot[1983]: time="2026-01-10T23:15:19-05:00" level=trace msg="sent dealer ping" Jan 10 23:15:19 volumio go-librespot[1983]: time="2026-01-10T23:15:19-05:00" level=trace msg="received dealer pong" Jan 10 23:15:49 volumio go-librespot[1983]: time="2026-01-10T23:15:49-05:00" level=trace msg="sent dealer ping" Jan 10 23:15:49 volumio go-librespot[1983]: time="2026-01-10T23:15:49-05:00" level=trace msg="received dealer pong" Jan 10 23:15:56 volumio volumio[1421]: info: Received OAUTH Data Jan 10 23:15:56 volumio volumio[1421]: info: Executing Spotify Oauth Login Jan 10 23:15:56 volumio volumio[1421]: info: Saving Spotify Refresh Token Jan 10 23:15:56 volumio volumio[1421]: info: New Spotify access tokenBQAVYwQUgG... Jan 10 23:15:56 volumio volumio[1421]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 10 23:15:56 volumio volumio[1421]: SPOTIFY: User informations: {"country":"US","display_name":"JDCMicro","email":"johnc@jdcmicro.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/thr8sy7e8ml3c01ryoo8pwy2s"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/thr8sy7e8ml3c01ryoo8pwy2s","id":"thr8sy7e8ml3c01ryoo8pwy2s","images":[],"product":"premium","type":"user","uri":"spotify:user:thr8sy7e8ml3c01ryoo8pwy2s"} Jan 10 23:15:56 volumio volumio[1421]: info: Creating Spotify config file Jan 10 23:15:56 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:15:56 volumio volumio[1421]: info: Spotify config file written Jan 10 23:15:56 volumio sudo[4353]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:15:56 volumio sudo[4353]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:15:56 volumio systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories... Jan 10 23:15:57 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:15:57 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:15:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:15:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:15:57 volumio sudo[4353]: pam_unix(sudo:session): session closed for user root Jan 10 23:15:57 volumio volumio[1421]: info: Connection to go-librespot Websocket closed Jan 10 23:15:57 volumio go-librespot[4358]: go-librespot daemon starting... Jan 10 23:15:57 volumio volumio[1421]: info: New Spotify access tokenBQA8FjW8NH... Jan 10 23:15:57 volumio volumio[1421]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="app state loaded" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:15:57 volumio systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully. Jan 10 23:15:57 volumio systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories. Jan 10 23:15:57 volumio systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully. Jan 10 23:15:57 volumio volumio[1421]: SPOTIFY: User informations: {"country":"US","display_name":"JDCMicro","email":"johnc@jdcmicro.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/thr8sy7e8ml3c01ryoo8pwy2s"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/thr8sy7e8ml3c01ryoo8pwy2s","id":"thr8sy7e8ml3c01ryoo8pwy2s","images":[],"product":"premium","type":"user","uri":"spotify:user:thr8sy7e8ml3c01ryoo8pwy2s"} Jan 10 23:15:57 volumio volumio[1421]: info: Spotify Successfully logged in Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:15:57 volumio volumio[1421]: info: [1768104957333] CoreMusicLibrary::Adding element Spotify Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:15:57 volumio volumio[1421]: Cannot find translation for source Spotify Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 23:15:57 volumio sudo[4371]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:15:57 volumio sudo[4371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:15:57 volumio sudo[4369]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:15:57 volumio sudo[4369]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=info msg="zeroconf server listening on port 33615" Jan 10 23:15:57 volumio sudo[4369]: pam_unix(sudo:session): session closed for user root Jan 10 23:15:57 volumio sudo[4371]: pam_unix(sudo:session): session closed for user root Jan 10 23:15:57 volumio volumio[1421]: verbose: New Socket.io Connection to 192.168.1.65 from 192.168.1.99 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/26.1 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 8 Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::volumioGetVisibleSources Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:15:57 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 10 23:15:57 volumio volumio[1421]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jan 10 23:15:57 volumio volumio[1421]: info: Received Get System Info Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 10 23:15:57 volumio volumio[1421]: info: Discovery: Getting this device information Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:15:57 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:15:57 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:15:57 volumio volumio[1421]: info: Listing playlists Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="obtained new client token: AAC80XuXFr+j2/YlUNCcCE3EexSBpbA+iClvt36UJjoXbYvIRhogPpawdBABqHF9A3zrreRfzUvAA7ObkU8NP9aO8ItrT67YN92a/jTG3gJ3BaP147gvOg8EKa2D94k1iZhYwmYCslEyuY/bf1sDK7F+zmtDRVdPsrHasqlx0eZCSIgtMLhZwnKn5JVhQKItYSmWOtypyYc7ezV+FCDD8opjgBM/kHXzWywevRLv3JX695NFAc0jnpD2VPU=" Jan 10 23:15:57 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="completed keyexchange" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="completed challenge" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=info msg="authenticated AP" username="th*********************2s" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=info msg="authenticated Login5" username="th*********************2s" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="initializing zeroconf session" username="th*********************2s" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="dealer connection opened" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=trace msg="starting accesspoint recv loop" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=trace msg="starting dealer recv loop" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=trace msg="received accesspoint ping" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=debug msg="received connection id: ZGI1NzA0ZTktMjg2...QkIyNTU1MTI2Qw==" Jan 10 23:15:57 volumio go-librespot[4359]: time="2026-01-10T23:15:57-05:00" level=trace msg="received accesspoint pong ack" Jan 10 23:15:58 volumio go-librespot[4359]: time="2026-01-10T23:15:58-05:00" level=debug msg="put connect state because NEW_DEVICE" Jan 10 23:15:58 volumio go-librespot[4359]: time="2026-01-10T23:15:58-05:00" level=debug msg="update volume requested to 17039/65535" Jan 10 23:15:58 volumio go-librespot[4359]: time="2026-01-10T23:15:58-05:00" level=debug msg="put connect state because VOLUME_CHANGED" Jan 10 23:15:58 volumio go-librespot[4359]: time="2026-01-10T23:15:58-05:00" level=trace msg="emitting websocket event: volume" Jan 10 23:15:59 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 10 23:15:59 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 10 23:15:59 volumio volumio[1421]: info: Received Get System Info Jan 10 23:15:59 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 10 23:15:59 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 10 23:15:59 volumio volumio[1421]: info: Discovery: Getting this device information Jan 10 23:15:59 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:15:59 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:15:59 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 10 23:15:59 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 10 23:16:00 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:00 volumio go-librespot[4359]: time="2026-01-10T23:16:00-05:00" level=debug msg="new websocket client" Jan 10 23:16:00 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:00 volumio volumio[1421]: info: go-librespot daemon successfully initialized Jan 10 23:16:02 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 10 23:16:02 volumio volumio[1421]: info: Received Get System Info Jan 10 23:16:02 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 10 23:16:02 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 10 23:16:02 volumio volumio[1421]: info: Discovery: Getting this device information Jan 10 23:16:02 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:02 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:02 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 10 23:16:03 volumio volumio[1421]: info: Getting Spotify volume Jan 10 23:16:03 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:03 volumio volumio[1421]: info: Spotify volume: 26 Jan 10 23:16:03 volumio go-librespot[4359]: time="2026-01-10T23:16:03-05:00" level=debug msg="new websocket client" Jan 10 23:16:03 volumio volumio[1421]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 10 23:16:03 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:03 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:03 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:05 volumio volumio[1421]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 10 23:16:05 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 10 23:16:05 volumio volumio[1421]: info: Creating Spotify config file Jan 10 23:16:05 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:16:05 volumio volumio[1421]: info: Spotify config file written Jan 10 23:16:05 volumio sudo[4392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:16:05 volumio sudo[4392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:16:05 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:16:05 volumio systemd[1]: go-librespot-daemon.service: Killing process 4363 (go-librespot) with signal SIGKILL. Jan 10 23:16:05 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:16:05 volumio volumio[1421]: info: Connection to go-librespot Websocket closed Jan 10 23:16:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:05 volumio volumio[1421]: info: Connection to go-librespot Websocket closed Jan 10 23:16:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:06 volumio go-librespot[4395]: go-librespot daemon starting... Jan 10 23:16:06 volumio sudo[4392]: pam_unix(sudo:session): session closed for user root Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="app state loaded" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:16:06 volumio volumio[1421]: info: Getting Spotify volume Jan 10 23:16:06 volumio volumio[1421]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 10 23:16:06 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:06 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=info msg="zeroconf server listening on port 39233" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="obtained new client token: AAALJuRaKEpk1gTEl+ATFcgMOOgaZv8BNWZDSdxJE1YmbkcRpCsLcg/WiU8p6cWnpbi+hnpY8kCQetqDd/03afE6Mk1er6k5/H7vak7pZxny87ZKoOq5TPzZtxiwA/Zf1y6Pd8Vr3qH/3RMgXohP+vDZCNOpBDFBQQHBD8SkTEzPzdFNlGGCI4QQ8gIfJDOps4yz9E/JL4j24G7KPu3b+S6TsSJvihkrE1UYSDCRmhKaS4bXjdB2HThT9zg=" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="completed keyexchange" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="completed challenge" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=info msg="authenticated AP" username="th*********************2s" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=info msg="authenticated Login5" username="th*********************2s" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="initializing zeroconf session" username="th*********************2s" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="dealer connection opened" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=trace msg="starting accesspoint recv loop" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=trace msg="starting dealer recv loop" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=trace msg="received accesspoint ping" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 10 23:16:06 volumio volumio[1421]: info: Spotify volume: 100 Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="received connection id: Zjc2NzMwODgtNTI1...RUJCMzREMUVBQw==" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=trace msg="received accesspoint pong ack" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="put connect state because NEW_DEVICE" Jan 10 23:16:06 volumio go-librespot[4396]: time="2026-01-10T23:16:06-05:00" level=debug msg="update volume requested to 17039/65535" Jan 10 23:16:07 volumio go-librespot[4396]: time="2026-01-10T23:16:07-05:00" level=debug msg="put connect state because VOLUME_CHANGED" Jan 10 23:16:07 volumio go-librespot[4396]: time="2026-01-10T23:16:07-05:00" level=trace msg="emitting websocket event: volume" Jan 10 23:16:07 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 10 23:16:09 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:09 volumio go-librespot[4396]: time="2026-01-10T23:16:09-05:00" level=debug msg="new websocket client" Jan 10 23:16:09 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:09 volumio volumio[1421]: info: go-librespot daemon successfully initialized Jan 10 23:16:09 volumio volumio[1421]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 10 23:16:09 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 10 23:16:09 volumio volumio[1421]: info: Creating Spotify config file Jan 10 23:16:09 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:16:09 volumio volumio[1421]: info: Spotify config file written Jan 10 23:16:09 volumio sudo[4408]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:16:09 volumio sudo[4408]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:16:09 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:16:09 volumio systemd[1]: go-librespot-daemon.service: Killing process 4397 (go-librespot) with signal SIGKILL. Jan 10 23:16:09 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:16:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:09 volumio volumio[1421]: info: Connection to go-librespot Websocket closed Jan 10 23:16:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:09 volumio sudo[4408]: pam_unix(sudo:session): session closed for user root Jan 10 23:16:09 volumio go-librespot[4410]: go-librespot daemon starting... Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="app state loaded" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=info msg="zeroconf server listening on port 38837" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="obtained new client token: AAAQgvTcLmTJl1+zZp4e7R05QZGvDJoR3cvzqPQ6SsPTaU0fGhpuevr7ExC8oE6LFDqOTotvDJq9SMlAjL0CB1GdbWaJ54SmNYQhVHKvBSumOTTG4Kb9TyfOSKIgrX7spXNeRoTlqSANulzIv9SLljR2vXkBNj4oc39ocqXJudnIDEmQ9jhOmixwuve7BLUC9sMKdO/47iVQxd65shuW3UBvI5MJoNw+NlQ8zcQFXA5DJrHa1c7FvFN/yBk=" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="completed keyexchange" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="completed challenge" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=info msg="authenticated AP" username="th*********************2s" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=info msg="authenticated Login5" username="th*********************2s" Jan 10 23:16:09 volumio go-librespot[4411]: time="2026-01-10T23:16:09-05:00" level=debug msg="initializing zeroconf session" username="th*********************2s" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="dealer connection opened" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=trace msg="starting accesspoint recv loop" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=trace msg="starting dealer recv loop" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=trace msg="received accesspoint ping" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="received connection id: NTFlMDM4OGUtM2Jm...QUMxQzY2NzhGQQ==" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=trace msg="received accesspoint pong ack" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="put connect state because NEW_DEVICE" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="update volume requested to 17039/65535" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=debug msg="put connect state because VOLUME_CHANGED" Jan 10 23:16:10 volumio go-librespot[4411]: time="2026-01-10T23:16:10-05:00" level=trace msg="emitting websocket event: volume" Jan 10 23:16:10 volumio volumio[1421]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 10 23:16:10 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 10 23:16:10 volumio volumio[1421]: info: Creating Spotify config file Jan 10 23:16:10 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:16:10 volumio volumio[1421]: info: Spotify config file written Jan 10 23:16:10 volumio sudo[4421]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:16:10 volumio sudo[4421]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:16:10 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:16:10 volumio systemd[1]: go-librespot-daemon.service: Killing process 4415 (go-librespot) with signal SIGKILL. Jan 10 23:16:10 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:16:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:10 volumio go-librespot[4423]: go-librespot daemon starting... Jan 10 23:16:10 volumio sudo[4421]: pam_unix(sudo:session): session closed for user root Jan 10 23:16:10 volumio go-librespot[4424]: time="2026-01-10T23:16:10-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:16:10 volumio go-librespot[4424]: time="2026-01-10T23:16:10-05:00" level=debug msg="app state loaded" Jan 10 23:16:10 volumio go-librespot[4424]: time="2026-01-10T23:16:10-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:16:10 volumio go-librespot[4424]: time="2026-01-10T23:16:10-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 23:16:10 volumio go-librespot[4424]: time="2026-01-10T23:16:10-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 23:16:10 volumio go-librespot[4424]: time="2026-01-10T23:16:10-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 23:16:10 volumio go-librespot[4424]: time="2026-01-10T23:16:10-05:00" level=info msg="zeroconf server listening on port 33127" Jan 10 23:16:10 volumio go-librespot[4424]: time="2026-01-10T23:16:10-05:00" level=debug msg="obtained new client token: AAA6tBR4P5j80sWiqP4lMCHzzl6sHOE+e+APNACg0tTY2C28Lvoi/Paw3CUcbrY6J3tol84xGuskNRZlAYWZgGcfQXO5RnscaswI2Bf49YOMNkUdS7y3ZXpkE7bIqMTZQU9n0Xq3nJNQFd0/luW77tBeGm46RIDv0zkLun4srduRV2U5R46FcFpuUt5KFf5o0a7Qct5m+cP7uyXgp1zGQ4NhB+O8vV3B2uPZ0O0hXAWDVf6s0lTiw6IlSCI=" Jan 10 23:16:11 volumio go-librespot[4424]: time="2026-01-10T23:16:11-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:16:11 volumio go-librespot[4424]: time="2026-01-10T23:16:11-05:00" level=debug msg="completed keyexchange" Jan 10 23:16:11 volumio go-librespot[4424]: time="2026-01-10T23:16:11-05:00" level=debug msg="completed challenge" Jan 10 23:16:11 volumio volumio[1421]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 10 23:16:11 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 10 23:16:11 volumio volumio[1421]: info: Creating Spotify config file Jan 10 23:16:11 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:16:11 volumio volumio[1421]: info: Spotify config file written Jan 10 23:16:11 volumio sudo[4434]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:16:11 volumio sudo[4434]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:16:11 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:16:11 volumio systemd[1]: go-librespot-daemon.service: Killing process 4426 (go-librespot) with signal SIGKILL. Jan 10 23:16:11 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:16:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:11 volumio go-librespot[4436]: go-librespot daemon starting... Jan 10 23:16:11 volumio sudo[4434]: pam_unix(sudo:session): session closed for user root Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=debug msg="app state loaded" Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=info msg="zeroconf server listening on port 40039" Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=debug msg="obtained new client token: AAA9g+KNd0+FAzsuVnHQ8w8Eg2CRXlkoTKF3aPbTv3nfiiMVY9x2Ud6mUdOuyBv4+ndSfrImFAidfl5uPHN3MtTl8CyegToZSbjBwthYg+o/EZWZ295p0CkKzOmLrN1umw/IVDzSZXae2myvPv39t5035LpfVOlamZW1vwVHgJO82mzBl/nQG+tiU+GY/sBfBpJqKpHeYDYvWFmWRBrLTn/KlWJDHN4s/txTpzQrvK07JXfkxZPsns+6Htg=" Jan 10 23:16:11 volumio go-librespot[4437]: time="2026-01-10T23:16:11-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:16:12 volumio volumio[1421]: info: Getting Spotify volume Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="completed keyexchange" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="completed challenge" Jan 10 23:16:12 volumio volumio[1421]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 10 23:16:12 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:12 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:12 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="new websocket client" Jan 10 23:16:12 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=info msg="authenticated AP" username="th*********************2s" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=info msg="authenticated Login5" username="th*********************2s" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="initializing zeroconf session" username="th*********************2s" Jan 10 23:16:12 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="new websocket client" Jan 10 23:16:12 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="dealer connection opened" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=trace msg="starting accesspoint recv loop" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=trace msg="starting dealer recv loop" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=trace msg="received accesspoint ping" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 10 23:16:12 volumio volumio[1421]: info: Spotify volume: 100 Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="received connection id: NGNmMzNmYzMtZjJj...RjZFQUZBNkExMA==" Jan 10 23:16:12 volumio volumio[1421]: info: go-librespot daemon successfully initialized Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=trace msg="received accesspoint pong ack" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="put connect state because NEW_DEVICE" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="update volume requested to 17039/65535" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=debug msg="put connect state because VOLUME_CHANGED" Jan 10 23:16:12 volumio go-librespot[4437]: time="2026-01-10T23:16:12-05:00" level=trace msg="emitting websocket event: volume" Jan 10 23:16:12 volumio volumio[1421]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Jan 10 23:16:12 volumio volumio[1421]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Jan 10 23:16:12 volumio volumio[1421]: info: Setting Volumio Volume from Spotify: 26 Jan 10 23:16:12 volumio volumio[1421]: info: VolumeController::SetAlsaVolume26 Jan 10 23:16:12 volumio volumio[1421]: info: CoreStateMachine::pushState Jan 10 23:16:12 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:12 volumio volumio[1421]: info: CoreCommandRouter::volumioPushState Jan 10 23:16:12 volumio volumio[1421]: info: MRS: Pushing multiroomSync output update for this device Jan 10 23:16:12 volumio volumio[1421]: info: MRS: Pushing multiroomSync output Jan 10 23:16:12 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:12 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:12 volumio volumio[1421]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Jan 10 23:16:12 volumio volumio[1421]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Jan 10 23:16:13 volumio volumio[1421]: info: go-librespot daemon successfully initialized Jan 10 23:16:14 volumio volumio[1421]: info: go-librespot daemon successfully initialized Jan 10 23:16:15 volumio volumio[1421]: info: Getting Spotify volume Jan 10 23:16:15 volumio volumio[1421]: info: Spotify volume: 26 Jan 10 23:16:15 volumio volumio[1421]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 10 23:16:15 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:15 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:15 volumio volumio[1421]: info: Getting Spotify volume Jan 10 23:16:15 volumio volumio[1421]: info: Spotify volume: 26 Jan 10 23:16:15 volumio volumio[1421]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 10 23:16:15 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:15 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:15 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:15 volumio go-librespot[4437]: time="2026-01-10T23:16:15-05:00" level=debug msg="new websocket client" Jan 10 23:16:15 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:15 volumio volumio[1421]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 10 23:16:15 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 10 23:16:15 volumio volumio[1421]: info: Creating Spotify config file Jan 10 23:16:15 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:16:15 volumio volumio[1421]: info: Spotify config file written Jan 10 23:16:15 volumio sudo[4461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:16:15 volumio sudo[4461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:16:15 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:16:15 volumio systemd[1]: go-librespot-daemon.service: Killing process 4438 (go-librespot) with signal SIGKILL. Jan 10 23:16:15 volumio systemd[1]: go-librespot-daemon.service: Killing process 4443 (go-librespot) with signal SIGKILL. Jan 10 23:16:15 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:16:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:15 volumio volumio[1421]: info: Connection to go-librespot Websocket closed Jan 10 23:16:15 volumio volumio[1421]: info: Connection to go-librespot Websocket closed Jan 10 23:16:15 volumio volumio[1421]: info: Connection to go-librespot Websocket closed Jan 10 23:16:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:15 volumio go-librespot[4463]: go-librespot daemon starting... Jan 10 23:16:15 volumio sudo[4461]: pam_unix(sudo:session): session closed for user root Jan 10 23:16:15 volumio go-librespot[4464]: time="2026-01-10T23:16:15-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:16:15 volumio go-librespot[4464]: time="2026-01-10T23:16:15-05:00" level=debug msg="app state loaded" Jan 10 23:16:15 volumio go-librespot[4464]: time="2026-01-10T23:16:15-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:16:16 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 10 23:16:16 volumio volumio[1421]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jan 10 23:16:16 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jan 10 23:16:16 volumio volumio[1421]: info: Received Get System Version Jan 10 23:16:16 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:16:16 volumio volumio[1421]: info: Received Get System Info Jan 10 23:16:16 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 10 23:16:16 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 10 23:16:16 volumio volumio[1421]: info: Discovery: Getting this device information Jan 10 23:16:16 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:16 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:16 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 10 23:16:16 volumio go-librespot[4464]: time="2026-01-10T23:16:16-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 23:16:16 volumio go-librespot[4464]: time="2026-01-10T23:16:16-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 23:16:16 volumio go-librespot[4464]: time="2026-01-10T23:16:16-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 23:16:16 volumio go-librespot[4464]: time="2026-01-10T23:16:16-05:00" level=info msg="zeroconf server listening on port 43277" Jan 10 23:16:16 volumio go-librespot[4464]: time="2026-01-10T23:16:16-05:00" level=debug msg="obtained new client token: AABbdZlToc5Uq7Ebv9C5Zvbhts4i8o0OpBNJBLIDW3Yx0oefH5orOTErI3n3vyL0fyi4VgwkOX+XvaoukpS2Wb9+hACIEXkACk52u3UnXDe4+LSh76ld8sjG3I/KVy9pUchjC0ncjtvjZUsMA6dA2cGQfbBf+Tg1VN1GxybIBIjA/7D8H9jbLF6AZQSonPD09hw1spv11GFFrEAj0aW84NDyM4FvKP0+tWhWUnnDdXXXCi6d1K3h3VcW" Jan 10 23:16:16 volumio go-librespot[4464]: time="2026-01-10T23:16:16-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:16:16 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:16 volumio go-librespot[4464]: time="2026-01-10T23:16:16-05:00" level=debug msg="new websocket client" Jan 10 23:16:16 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:17 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:17 volumio go-librespot[4464]: time="2026-01-10T23:16:17-05:00" level=debug msg="new websocket client" Jan 10 23:16:17 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:18 volumio volumio[1421]: info: Getting Spotify volume Jan 10 23:16:18 volumio volumio[1421]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 10 23:16:18 volumio volumio[1421]: info: CoreCommandRouter::volumioGetState Jan 10 23:16:18 volumio volumio[1421]: info: CorePlayQueue::getTrack 0 Jan 10 23:16:18 volumio volumio[1421]: info: Initializing connection to go-librespot Websocket Jan 10 23:16:18 volumio go-librespot[4464]: time="2026-01-10T23:16:18-05:00" level=debug msg="new websocket client" Jan 10 23:16:18 volumio volumio[1421]: info: Connection to go-librespot Websocket established Jan 10 23:16:18 volumio volumio[1421]: info: go-librespot daemon successfully initialized Jan 10 23:16:19 volumio volumio[1421]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 10 23:16:19 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 10 23:16:19 volumio volumio[1421]: info: Creating Spotify config file Jan 10 23:16:19 volumio volumio[1421]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:16:19 volumio volumio[1421]: info: Spotify config file written Jan 10 23:16:19 volumio sudo[4479]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:16:19 volumio sudo[4479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:16:19 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:16:19 volumio systemd[1]: go-librespot-daemon.service: Killing process 4466 (go-librespot) with signal SIGKILL. Jan 10 23:16:19 volumio systemd[1]: go-librespot-daemon.service: Killing process 4470 (go-librespot) with signal SIGKILL. Jan 10 23:16:19 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:16:19 volumio volumio[1421]: info: Connection to go-librespot Websocket closed Jan 10 23:16:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:19 volumio volumio[1421]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:16:19 volumio volumio[1421]: Error: socket hang up Jan 10 23:16:19 volumio volumio[1421]: at connResetException (node:internal/errors:720:14) Jan 10 23:16:19 volumio volumio[1421]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 10 23:16:19 volumio volumio[1421]: at Socket.emit (node:events:526:35) Jan 10 23:16:19 volumio volumio[1421]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 10 23:16:19 volumio volumio[1421]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 10 23:16:19 volumio volumio[1421]: code: 'ECONNRESET', Jan 10 23:16:19 volumio volumio[1421]: response: undefined Jan 10 23:16:19 volumio volumio[1421]: } Jan 10 23:16:19 volumio volumio[1421]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:16:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:16:19 volumio go-librespot[4481]: go-librespot daemon starting... Jan 10 23:16:19 volumio sudo[4479]: pam_unix(sudo:session): session closed for user root Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="app state loaded" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=info msg="zeroconf server listening on port 40901" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="obtained new client token: AADs+rDQfO6YM44Svv6qSlRl3lLE0hPJT1++kJ/mZVj0sxBdMG0N4Fu04hApzwjrW9JplBK7Ylv/2P0Fr5o0HySliYsncD7HRyhslJ94BrvY1pWvYfjrBcao3WHA+l6nWveVpwxJukLhOXlbN6Tf/pgMbnkuTSdbbwuQe0OOyYPBSdTc+XPyQoB+IL6JQzBAXjxF11QZN20Inj3FHJKU2BLJYUBL31QbZcZO+SJQUUZ15amn8b1lxCSHFyc=" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="completed keyexchange" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="completed challenge" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=info msg="authenticated AP" username="th*********************2s" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=info msg="authenticated Login5" username="th*********************2s" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="initializing zeroconf session" username="th*********************2s" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="dealer connection opened" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=trace msg="starting accesspoint recv loop" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=trace msg="starting dealer recv loop" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=trace msg="received accesspoint ping" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 10 23:16:19 volumio go-librespot[4485]: time="2026-01-10T23:16:19-05:00" level=debug msg="received connection id: NmY2ZmJiZDctMjEw...RUY3ODlERTc0Mw==" Jan 10 23:16:20 volumio go-librespot[4485]: time="2026-01-10T23:16:20-05:00" level=trace msg="received accesspoint pong ack" Jan 10 23:16:20 volumio go-librespot[4485]: time="2026-01-10T23:16:20-05:00" level=debug msg="put connect state because NEW_DEVICE" Jan 10 23:16:20 volumio go-librespot[4485]: time="2026-01-10T23:16:20-05:00" level=debug msg="update volume requested to 17039/65535" Jan 10 23:16:20 volumio sudo[4505]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 23:15' Jan 10 23:16:20 volumio sudo[4505]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:16:20 volumio go-librespot[4485]: time="2026-01-10T23:16:20-05:00" level=debug msg="put connect state because VOLUME_CHANGED" Jan 10 23:16:20 volumio go-librespot[4485]: time="2026-01-10T23:16:20-05:00" level=trace msg="emitting websocket event: volume" 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"