Feb 23 22:25:52 office volumio[1876]: info: Received OAUTH Data Feb 23 22:25:52 office volumio[1876]: info: Executing Spotify Oauth Login Feb 23 22:25:52 office volumio[1876]: info: Saving Spotify Refresh Token Feb 23 22:25:53 office volumio[1876]: info: New Spotify access tokenBQAb5gNXVs... Feb 23 22:25:53 office volumio[1876]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 23 22:25:53 office sudo[4128]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 23 22:25:53 office sudo[4128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 23 22:25:53 office sudo[4128]: pam_unix(sudo:session): session closed for user root Feb 23 22:25:53 office sudo[4130]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 23 22:25:53 office sudo[4130]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 23 22:25:53 office sudo[4130]: pam_unix(sudo:session): session closed for user root Feb 23 22:25:53 office volumio[1876]: verbose: New Socket.io Connection to 192.168.1.77 from 192.168.1.62 UA: Mozilla/5.0 (Linux; Android 16; Pixel 10 Pro Build/BP4A.260205.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/144.0.7559.132 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 23 22:25:53 office volumio[1876]: SPOTIFY: User informations: {"country":"US","display_name":"Hector Perez","email":"hector-perez94@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/129480301"},"followers":{"href":null,"total":20},"href":"https://api.spotify.com/v1/users/129480301","id":"129480301","images":[{"height":300,"url":"https://scontent-sea5-1.xx.fbcdn.net/v/t1.6435-1/129279911_10224526759104460_4028181978316124058_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=107&ccb=1-7&_nc_sid=08baa4&_nc_ohc=6G5wXgkt6vsQ7kNvwGa-xxe&_nc_oc=AdlGkrI8qzaV7seQibpBoOoeMW8WJ6_8t59UPfNw7rRCH2VFd9StZYQaHpgqjA7cPF8zKQXY5vWzo3FLdf8Vkmd6&_nc_zt=24&_nc_ht=scontent-sea5-1.xx&edm=AP4hL3IEAAAA&_nc_gid=AikTi18QU3aJltRR-4v2Mw&_nc_tpa=Q5bMBQHuWCPuWHgCefEQV8TxEys7qMCQHPtkcZYKaudEgFDw87jIV5tH3mlYFSMUdcTVDxHiOZWW&oh=00_AfuXssQglpuboqLZUYbRzAzcurMXm6RTwm80XQnnv3BKAw&oe=69C48E61","width":300},{"height":64,"url":"https://scontent-sea5-1.xx.fbcdn.net/v/t1.6435-1/129279911_10224526759104460_4028181978316124058_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=107&ccb=1-7&_nc_sid=28885b&_nc_ohc=6G5wXgkt6vsQ7kNvwGa-xxe&_nc_oc=AdlGkrI8qzaV7seQibpBoOoeMW8WJ6_8t59UPfNw7rRCH2VFd9StZYQaHpgqjA7cPF8zKQXY5vWzo3FLdf8Vkmd6&_nc_zt=24&_nc_ht=scontent-sea5-1.xx&edm=AP4hL3IEAAAA&_nc_gid=AikTi18QU3aJltRR-4v2Mw&_nc_tpa=Q5bMBQEDD6s_Ephj8eLe6WV6ga8xaX0GpMr-LLfcYq3MZH8u8Q8--jQ0ViIfONISIM-g-_kbyFpq&oh=00_AfvPGWJoIr-4c8ZjBPmkUGxNSEZwycE92etlISkesrEGgg&oe=69C48E61","width":64}],"product":"premium","type":"user","uri":"spotify:user:129480301"} Feb 23 22:25:53 office volumio[1876]: info: Creating Spotify config file Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::volumioGetVisibleSources Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:25:53 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 23 22:25:53 office volumio[1876]: info: Received Get System Info Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 23 22:25:53 office volumio[1876]: info: Discovery: Getting this device information Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:25:53 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:25:53 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:25:53 office volumio[1876]: info: Listing playlists Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 23 22:25:53 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 23 22:25:53 office volumio[1876]: info: Spotify config file written Feb 23 22:25:53 office sudo[4137]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 23 22:25:53 office sudo[4137]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 23 22:25:53 office systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 23 22:25:53 office systemd[1]: go-librespot-daemon.service: Killing process 2293 (go-librespot) with signal SIGKILL. Feb 23 22:25:53 office systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 23 22:25:53 office systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:25:53 office systemd[1]: go-librespot-daemon.service: Consumed 1.065s CPU time. Feb 23 22:25:53 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:25:53 office systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:25:53 office go-librespot[4139]: go-librespot daemon starting... Feb 23 22:25:53 office sudo[4137]: pam_unix(sudo:session): session closed for user root Feb 23 22:25:53 office go-librespot[4140]: time="2026-02-23T22:25:53-08:00" level=info msg="running go-librespot 0.6.2" Feb 23 22:25:53 office go-librespot[4140]: time="2026-02-23T22:25:53-08:00" level=debug msg="app state loaded" Feb 23 22:25:53 office go-librespot[4140]: time="2026-02-23T22:25:53-08:00" level=debug msg="stored credentials not found" Feb 23 22:25:53 office go-librespot[4140]: time="2026-02-23T22:25:53-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 23 22:25:54 office volumio[1876]: info: New Spotify access tokenBQBsJ8qGGh... Feb 23 22:25:54 office volumio[1876]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 23 22:25:54 office volumio[1876]: SPOTIFY: User informations: {"country":"US","display_name":"Hector Perez","email":"hector-perez94@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/129480301"},"followers":{"href":null,"total":20},"href":"https://api.spotify.com/v1/users/129480301","id":"129480301","images":[{"height":300,"url":"https://scontent-sea5-1.xx.fbcdn.net/v/t1.6435-1/129279911_10224526759104460_4028181978316124058_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=107&ccb=1-7&_nc_sid=08baa4&_nc_ohc=6G5wXgkt6vsQ7kNvwGa-xxe&_nc_oc=AdlGkrI8qzaV7seQibpBoOoeMW8WJ6_8t59UPfNw7rRCH2VFd9StZYQaHpgqjA7cPF8zKQXY5vWzo3FLdf8Vkmd6&_nc_zt=24&_nc_ht=scontent-sea5-1.xx&edm=AP4hL3IEAAAA&_nc_gid=AikTi18QU3aJltRR-4v2Mw&_nc_tpa=Q5bMBQHuWCPuWHgCefEQV8TxEys7qMCQHPtkcZYKaudEgFDw87jIV5tH3mlYFSMUdcTVDxHiOZWW&oh=00_AfuXssQglpuboqLZUYbRzAzcurMXm6RTwm80XQnnv3BKAw&oe=69C48E61","width":300},{"height":64,"url":"https://scontent-sea5-1.xx.fbcdn.net/v/t1.6435-1/129279911_10224526759104460_4028181978316124058_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=107&ccb=1-7&_nc_sid=28885b&_nc_ohc=6G5wXgkt6vsQ7kNvwGa-xxe&_nc_oc=AdlGkrI8qzaV7seQibpBoOoeMW8WJ6_8t59UPfNw7rRCH2VFd9StZYQaHpgqjA7cPF8zKQXY5vWzo3FLdf8Vkmd6&_nc_zt=24&_nc_ht=scontent-sea5-1.xx&edm=AP4hL3IEAAAA&_nc_gid=AikTi18QU3aJltRR-4v2Mw&_nc_tpa=Q5bMBQEDD6s_Ephj8eLe6WV6ga8xaX0GpMr-LLfcYq3MZH8u8Q8--jQ0ViIfONISIM-g-_kbyFpq&oh=00_AfvPGWJoIr-4c8ZjBPmkUGxNSEZwycE92etlISkesrEGgg&oe=69C48E61","width":64}],"product":"premium","type":"user","uri":"spotify:user:129480301"} Feb 23 22:25:54 office volumio[1876]: info: Spotify Successfully logged in Feb 23 22:25:54 office volumio[1876]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 23 22:25:54 office volumio[1876]: info: [1771914354234] CoreMusicLibrary::Adding element Spotify Feb 23 22:25:54 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 23 22:25:54 office volumio[1876]: Cannot find translation for source Jellyfin Feb 23 22:25:54 office volumio[1876]: Cannot find translation for source Spotify Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=info msg="zeroconf server listening on port 36941" Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=debug msg="obtained new client token: AACzzEOemVOw4ayJ7J0799C2WG6Jbiv7vt5M1uFiLGwrCAQzUyoBMlWIfLKchvHeQPH05Fh5KU1UAyFrHuxvww/w12e4v+mKy85VRH5JrIo6rvjcYZUXFVwpsQAIZ9SAzbIf7TGYMM4Mhyg9dQWG1CYYbJH1QYeJ9JfjpwV0mUqO24LUdxWnT+/PYKTKGS8vzn8q+PRnMomAkMzuow2ET1g92GhfFA41nV8xI/C2JDCpqG4hFpo1AEE=" Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=debug msg="completed keyexchange" Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=debug msg="completed challenge" Feb 23 22:25:54 office go-librespot[4140]: time="2026-02-23T22:25:54-08:00" level=info msg="authenticated AP" username="12*****01" Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=info msg="authenticated Login5" username="12*****01" Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 23 22:25:55 office volumio[1876]: info: Received Get System Info Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 23 22:25:55 office volumio[1876]: info: Discovery: Getting this device information Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:25:55 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 23 22:25:55 office volumio[1876]: info: Received Get System Info Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 23 22:25:55 office volumio[1876]: info: Discovery: Getting this device information Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:25:55 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:25:55 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=debug msg="stored credentials" username="12*****01" Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=debug msg="initializing zeroconf session" username="12*****01" Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=debug msg="dealer connection opened" Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=trace msg="starting accesspoint recv loop" Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=trace msg="starting dealer recv loop" Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=trace msg="received accesspoint ping" Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 23 22:25:55 office go-librespot[4140]: time="2026-02-23T22:25:55-08:00" level=debug msg="received connection id: YTVkNTUyMzEtZDI5...N0NDNzVGN0JDQw==" Feb 23 22:25:56 office go-librespot[4140]: time="2026-02-23T22:25:56-08:00" level=debug msg="put connect state because NEW_DEVICE" Feb 23 22:25:56 office go-librespot[4140]: time="2026-02-23T22:25:56-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 23 22:25:56 office go-librespot[4140]: time="2026-02-23T22:25:56-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 23 22:25:56 office go-librespot[4140]: time="2026-02-23T22:25:56-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 23 22:25:56 office go-librespot[4140]: time="2026-02-23T22:25:56-08:00" level=trace msg="received accesspoint pong ack" Feb 23 22:25:56 office volumio[1876]: info: Initializing connection to go-librespot Websocket Feb 23 22:25:56 office go-librespot[4140]: time="2026-02-23T22:25:56-08:00" level=debug msg="new websocket client" Feb 23 22:25:56 office volumio[1876]: info: Connection to go-librespot Websocket established Feb 23 22:25:56 office volumio[1876]: info: go-librespot daemon successfully initialized Feb 23 22:25:59 office volumio[1876]: info: Getting Spotify volume Feb 23 22:25:59 office volumio[1876]: info: Spotify volume: 100 Feb 23 22:25:59 office volumio[1876]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 23 22:25:59 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:25:59 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:25:59 office volumio[1876]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Feb 23 22:25:59 office volumio[1876]: SPOTIFY: SPOTIFY VOLUME 100 Feb 23 22:25:59 office volumio[1876]: SPOTIFY: VOLUMIO VOLUME 86 Feb 23 22:25:59 office volumio[1876]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 23 22:25:59 office volumio[1876]: info: Setting Spotify Volume from Volumio: 86 Feb 23 22:25:59 office volumio[1876]: info: Initializing connection to go-librespot Websocket Feb 23 22:25:59 office go-librespot[4140]: time="2026-02-23T22:25:59-08:00" level=debug msg="new websocket client" Feb 23 22:25:59 office volumio[1876]: info: Connection to go-librespot Websocket established Feb 23 22:26:01 office volumio[1876]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Feb 23 22:26:01 office volumio[1876]: info: Sending Spotify command with payload to local API: /player/volume Feb 23 22:26:01 office go-librespot[4140]: time="2026-02-23T22:26:01-08:00" level=debug msg="update volume requested to 56360/65535" Feb 23 22:26:01 office go-librespot[4140]: time="2026-02-23T22:26:01-08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 23 22:26:01 office go-librespot[4140]: time="2026-02-23T22:26:01-08:00" level=trace msg="emitting websocket event: volume" Feb 23 22:26:01 office volumio[1876]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Feb 23 22:26:01 office volumio[1876]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Feb 23 22:26:01 office volumio[1876]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Feb 23 22:26:01 office volumio[1876]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Feb 23 22:26:02 office volumio[1876]: info: Getting Spotify volume Feb 23 22:26:02 office volumio[1876]: info: Spotify volume: 86 Feb 23 22:26:02 office volumio[1876]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 23 22:26:02 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:26:02 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:26:02 office volumio[1876]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Feb 23 22:26:03 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 23 22:26:11 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 23 22:26:11 office volumio[1876]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 23 22:26:11 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 23 22:26:11 office volumio[1876]: info: Received Get System Version Feb 23 22:26:11 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 23 22:26:11 office volumio[1876]: info: Received Get System Info Feb 23 22:26:11 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 23 22:26:11 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 23 22:26:11 office volumio[1876]: info: Discovery: Getting this device information Feb 23 22:26:11 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:26:11 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:26:11 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 23 22:26:21 office volumio[1876]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 23 22:26:21 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 23 22:26:21 office volumio[1876]: info: Creating Spotify config file Feb 23 22:26:21 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 23 22:26:21 office volumio[1876]: info: Spotify config file written Feb 23 22:26:21 office sudo[4194]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 23 22:26:21 office sudo[4194]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 23 22:26:21 office systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 23 22:26:21 office systemd[1]: go-librespot-daemon.service: Killing process 4146 (go-librespot) with signal SIGKILL. Feb 23 22:26:21 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:26:21 office systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 23 22:26:21 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:26:21 office systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:21 office systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:21 office go-librespot[4196]: go-librespot daemon starting... Feb 23 22:26:21 office sudo[4194]: pam_unix(sudo:session): session closed for user root Feb 23 22:26:21 office go-librespot[4197]: time="2026-02-23T22:26:21-08:00" level=info msg="running go-librespot 0.6.2" Feb 23 22:26:21 office go-librespot[4197]: time="2026-02-23T22:26:21-08:00" level=debug msg="app state loaded" Feb 23 22:26:21 office go-librespot[4197]: time="2026-02-23T22:26:21-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 23 22:26:21 office go-librespot[4197]: time="2026-02-23T22:26:21-08: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]" Feb 23 22:26:21 office go-librespot[4197]: time="2026-02-23T22:26:21-08: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]" Feb 23 22:26:21 office go-librespot[4197]: time="2026-02-23T22:26:21-08: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]" Feb 23 22:26:21 office go-librespot[4197]: time="2026-02-23T22:26:21-08:00" level=info msg="zeroconf server listening on port 45299" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="obtained new client token: AACnEz1vkSRpqjUy4zfOZKNZDHDncug3gQn6xKO3UMkp63z7E1cygfPI/1Huep/U3YanGjwFh6mf/Bm7XDalfukVyV+L5rtmewzHhYyof0WfF8tJ70/KWT3je90jLWCUtAYQVHAl1ga6OHKDZr7jrhaCMai0xiqjLTLyRZTzJ6cuwrehbqGtqndOIb3bQF5YHDtZDJw0w+5aGE4jhJxNRIwN5DQx+m+x3xrXZ+GdnFh9V7CTIFhu3Ho=" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="completed keyexchange" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="completed challenge" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=info msg="authenticated AP" username="12*****01" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=info msg="authenticated Login5" username="12*****01" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="initializing zeroconf session" username="12*****01" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="dealer connection opened" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=trace msg="starting accesspoint recv loop" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=trace msg="starting dealer recv loop" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=trace msg="received accesspoint ping" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=debug msg="received connection id: NzY3NTUxMjEtMmIz...QTJBRDQyODAwQw==" Feb 23 22:26:22 office go-librespot[4197]: time="2026-02-23T22:26:22-08:00" level=trace msg="received accesspoint pong ack" Feb 23 22:26:23 office go-librespot[4197]: time="2026-02-23T22:26:23-08:00" level=debug msg="put connect state because NEW_DEVICE" Feb 23 22:26:24 office volumio[1876]: info: Initializing connection to go-librespot Websocket Feb 23 22:26:24 office go-librespot[4197]: time="2026-02-23T22:26:24-08:00" level=debug msg="new websocket client" Feb 23 22:26:24 office volumio[1876]: info: Connection to go-librespot Websocket established Feb 23 22:26:24 office volumio[1876]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 23 22:26:24 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 23 22:26:24 office volumio[1876]: info: Creating Spotify config file Feb 23 22:26:24 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 23 22:26:24 office volumio[1876]: info: Spotify config file written Feb 23 22:26:24 office sudo[4208]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 23 22:26:24 office sudo[4208]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 23 22:26:24 office volumio[1876]: info: go-librespot daemon successfully initialized Feb 23 22:26:24 office systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 23 22:26:24 office systemd[1]: go-librespot-daemon.service: Killing process 4198 (go-librespot) with signal SIGKILL. Feb 23 22:26:24 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:26:24 office systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 23 22:26:24 office systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:24 office systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:24 office go-librespot[4210]: go-librespot daemon starting... Feb 23 22:26:24 office sudo[4208]: pam_unix(sudo:session): session closed for user root Feb 23 22:26:24 office go-librespot[4212]: time="2026-02-23T22:26:24-08:00" level=info msg="running go-librespot 0.6.2" Feb 23 22:26:24 office go-librespot[4212]: time="2026-02-23T22:26:24-08:00" level=debug msg="app state loaded" Feb 23 22:26:24 office go-librespot[4212]: time="2026-02-23T22:26:24-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08: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]" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08: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]" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08: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]" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=info msg="zeroconf server listening on port 39919" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="obtained new client token: AAALqd0S6TiUxRf7/rJbf5Lzz+mdBaGn48o5g/w0yt6cG8webetApr4Pue6f/OLEBTXoe97yLotwfmmEAb/Ekohjb3hoJ4QXfYdafok4letZLJxFOS2s+GKYjg8sVqAFySHtCBxtvJZvrHgbtYwfvr2gH4f7FJskOIg1GSmeWjqPWU4kvScvy4v7Rh0ZLCszjkxrY9NMo8wT/TOO4HAM1s3ps4Bjy+54wyYr38lyM8+jZHn67RW4" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="completed keyexchange" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="completed challenge" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=info msg="authenticated AP" username="12*****01" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=info msg="authenticated Login5" username="12*****01" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="initializing zeroconf session" username="12*****01" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="dealer connection opened" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=trace msg="starting accesspoint recv loop" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=trace msg="starting dealer recv loop" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=trace msg="received accesspoint ping" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=debug msg="received connection id: NzdjOWQ2NzktMWMy...OTA3RERCOUI2OA==" Feb 23 22:26:25 office go-librespot[4212]: time="2026-02-23T22:26:25-08:00" level=trace msg="received accesspoint pong ack" Feb 23 22:26:26 office volumio[1876]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 23 22:26:26 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 23 22:26:26 office volumio[1876]: info: Creating Spotify config file Feb 23 22:26:26 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 23 22:26:26 office volumio[1876]: info: Spotify config file written Feb 23 22:26:26 office go-librespot[4212]: time="2026-02-23T22:26:26-08:00" level=debug msg="put connect state because NEW_DEVICE" Feb 23 22:26:26 office sudo[4236]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 23 22:26:26 office sudo[4236]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 23 22:26:26 office systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 23 22:26:26 office systemd[1]: go-librespot-daemon.service: Killing process 4216 (go-librespot) with signal SIGKILL. Feb 23 22:26:26 office systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 23 22:26:26 office systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:26 office systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:26 office go-librespot[4238]: go-librespot daemon starting... Feb 23 22:26:26 office sudo[4236]: pam_unix(sudo:session): session closed for user root Feb 23 22:26:26 office go-librespot[4239]: time="2026-02-23T22:26:26-08:00" level=info msg="running go-librespot 0.6.2" Feb 23 22:26:26 office go-librespot[4239]: time="2026-02-23T22:26:26-08:00" level=debug msg="app state loaded" Feb 23 22:26:26 office go-librespot[4239]: time="2026-02-23T22:26:26-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 23 22:26:26 office go-librespot[4239]: time="2026-02-23T22:26:26-08: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]" Feb 23 22:26:26 office go-librespot[4239]: time="2026-02-23T22:26:26-08: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]" Feb 23 22:26:26 office go-librespot[4239]: time="2026-02-23T22:26:26-08: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]" Feb 23 22:26:26 office volumio[1876]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 23 22:26:26 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 23 22:26:26 office volumio[1876]: info: Creating Spotify config file Feb 23 22:26:26 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 23 22:26:26 office volumio[1876]: info: Spotify config file written Feb 23 22:26:26 office go-librespot[4239]: time="2026-02-23T22:26:26-08:00" level=info msg="zeroconf server listening on port 32991" Feb 23 22:26:26 office sudo[4249]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 23 22:26:26 office sudo[4249]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 23 22:26:27 office systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 23 22:26:27 office systemd[1]: go-librespot-daemon.service: Killing process 4243 (go-librespot) with signal SIGKILL. Feb 23 22:26:27 office systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 23 22:26:27 office systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:27 office systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:27 office sudo[4249]: pam_unix(sudo:session): session closed for user root Feb 23 22:26:27 office go-librespot[4251]: go-librespot daemon starting... Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08:00" level=info msg="running go-librespot 0.6.2" Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08:00" level=debug msg="app state loaded" Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 23 22:26:27 office volumio[1876]: info: Getting Spotify volume Feb 23 22:26:27 office volumio[1876]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 23 22:26:27 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:26:27 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:26:27 office volumio[1876]: info: Initializing connection to go-librespot Websocket Feb 23 22:26:27 office volumio[1876]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08:00" level=debug msg="new websocket client" Feb 23 22:26:27 office volumio[1876]: info: Connection to go-librespot Websocket established Feb 23 22:26:27 office volumio[1876]: info: Initializing connection to go-librespot Websocket Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08:00" level=debug msg="new websocket client" Feb 23 22:26:27 office volumio[1876]: info: Connection to go-librespot Websocket established Feb 23 22:26:27 office volumio[1876]: info: go-librespot daemon successfully initialized Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08: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]" Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08: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]" Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08: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]" Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08:00" level=info msg="zeroconf server listening on port 45699" Feb 23 22:26:27 office go-librespot[4252]: time="2026-02-23T22:26:27-08:00" level=debug msg="obtained new client token: AABKEKe+2EGIqKGZlt4OE5S2hUPpuSeOyyWwVepZnMRJdDizR+Qz0Dgdu0bp6e1j6dR0tGNFxna9PwZ7Pk41K4IfvV2K6L0trqU5Hh9F17OJ5KJj8KcY3af/3DHVeT7KApq9jtIk/+i+fpT0qx48Th4ot1EHKGYHL3EO71Yg2v6IV0VitHbqTjVJe8C71TSnrle5ksXUBn9OV6H+aPu0xEPoDXv4odL0qpVyXgme8A3SRNXoYTjFrIU=" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="connected to ap-guc3.spotify.com:443" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="completed keyexchange" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="completed challenge" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=info msg="authenticated AP" username="12*****01" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=info msg="authenticated Login5" username="12*****01" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="initializing zeroconf session" username="12*****01" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="dealer connection opened" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=trace msg="starting accesspoint recv loop" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=trace msg="starting dealer recv loop" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=trace msg="received accesspoint ping" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="received connection id: ZmQ5OWU3NjQtODBi...QkE5RDc4QkVBNQ==" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 23 22:26:28 office volumio[1876]: info: Spotify volume: 100 Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="put connect state because NEW_DEVICE" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 23 22:26:28 office go-librespot[4252]: time="2026-02-23T22:26:28-08:00" level=trace msg="received accesspoint pong ack" Feb 23 22:26:29 office volumio[1876]: info: go-librespot daemon successfully initialized Feb 23 22:26:30 office volumio[1876]: info: go-librespot daemon successfully initialized Feb 23 22:26:30 office volumio[1876]: info: Getting Spotify volume Feb 23 22:26:30 office volumio[1876]: info: Spotify volume: 100 Feb 23 22:26:30 office volumio[1876]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 23 22:26:30 office volumio[1876]: info: Getting Spotify volume Feb 23 22:26:30 office volumio[1876]: info: Spotify volume: 100 Feb 23 22:26:30 office volumio[1876]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Feb 23 22:26:30 office volumio[1876]: info: Initializing connection to go-librespot Websocket Feb 23 22:26:30 office go-librespot[4252]: time="2026-02-23T22:26:30-08:00" level=debug msg="new websocket client" Feb 23 22:26:30 office volumio[1876]: info: Connection to go-librespot Websocket established Feb 23 22:26:30 office volumio[1876]: info: CoreCommandRouter::volumioGetState Feb 23 22:26:30 office volumio[1876]: info: CorePlayQueue::getTrack 0 Feb 23 22:26:30 office volumio[1876]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Feb 23 22:26:30 office volumio[1876]: SPOTIFY: SPOTIFY VOLUME 100 Feb 23 22:26:30 office volumio[1876]: SPOTIFY: VOLUMIO VOLUME 86 Feb 23 22:26:30 office volumio[1876]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 23 22:26:30 office volumio[1876]: info: Setting Spotify Volume from Volumio: 86 Feb 23 22:26:32 office volumio[1876]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Feb 23 22:26:32 office volumio[1876]: info: Sending Spotify command with payload to local API: /player/volume Feb 23 22:26:32 office go-librespot[4252]: time="2026-02-23T22:26:32-08:00" level=debug msg="update volume requested to 56360/65535" Feb 23 22:26:32 office go-librespot[4252]: time="2026-02-23T22:26:32-08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 23 22:26:32 office go-librespot[4252]: time="2026-02-23T22:26:32-08:00" level=trace msg="emitting websocket event: volume" Feb 23 22:26:32 office volumio[1876]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Feb 23 22:26:32 office volumio[1876]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Feb 23 22:26:32 office volumio[1876]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Feb 23 22:26:32 office volumio[1876]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Feb 23 22:26:32 office volumio[1876]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Feb 23 22:26:32 office volumio[1876]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Feb 23 22:26:32 office volumio[1876]: info: Initializing connection to go-librespot Websocket Feb 23 22:26:32 office go-librespot[4252]: time="2026-02-23T22:26:32-08:00" level=debug msg="new websocket client" Feb 23 22:26:32 office volumio[1876]: info: Connection to go-librespot Websocket established Feb 23 22:26:33 office volumio[1876]: info: Initializing connection to go-librespot Websocket Feb 23 22:26:33 office go-librespot[4252]: time="2026-02-23T22:26:33-08:00" level=debug msg="new websocket client" Feb 23 22:26:33 office volumio[1876]: info: Connection to go-librespot Websocket established Feb 23 22:26:33 office volumio[1876]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 23 22:26:33 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 23 22:26:33 office volumio[1876]: info: Creating Spotify config file Feb 23 22:26:33 office volumio[1876]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 23 22:26:33 office volumio[1876]: info: Spotify config file written Feb 23 22:26:33 office sudo[4262]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 23 22:26:33 office sudo[4262]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 23 22:26:33 office systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 23 22:26:33 office systemd[1]: go-librespot-daemon.service: Killing process 4255 (go-librespot) with signal SIGKILL. Feb 23 22:26:33 office systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 23 22:26:33 office systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:33 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:26:33 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:26:33 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:26:33 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:26:33 office volumio[1876]: info: Connection to go-librespot Websocket closed Feb 23 22:26:33 office systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 23 22:26:33 office go-librespot[4264]: go-librespot daemon starting... Feb 23 22:26:33 office sudo[4262]: pam_unix(sudo:session): session closed for user root Feb 23 22:26:33 office go-librespot[4265]: time="2026-02-23T22:26:33-08:00" level=info msg="running go-librespot 0.6.2" Feb 23 22:26:33 office go-librespot[4265]: time="2026-02-23T22:26:33-08:00" level=debug msg="app state loaded" Feb 23 22:26:33 office volumio[1876]: info: Getting Spotify volume Feb 23 22:26:33 office volumio[1876]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 23 22:26:33 office go-librespot[4265]: time="2026-02-23T22:26:33-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 23 22:26:33 office volumio[1876]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 23 22:26:33 office volumio[1876]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 23 22:26:33 office volumio[1876]: errno: -111, Feb 23 22:26:33 office volumio[1876]: code: 'ECONNREFUSED', Feb 23 22:26:33 office volumio[1876]: syscall: 'connect', Feb 23 22:26:33 office volumio[1876]: address: '127.0.0.1', Feb 23 22:26:33 office volumio[1876]: port: 9879, Feb 23 22:26:33 office volumio[1876]: response: undefined Feb 23 22:26:33 office volumio[1876]: } Feb 23 22:26:33 office volumio[1876]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=info msg="zeroconf server listening on port 38435" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="obtained new client token: AAAPp8DIuxmR2SgZAWyiST7DYtKJyswgvJqA0ShGC37bG8kTj/ioWezn0O819qr62Cr5uroFfnEY7na0RUAmhT8rS7CkQlyo/uhmbgwfYoRlxr7YjzCLSHoIjupRN6R9OAnWD+vQxSGm3mizY12bjwfYJSG9XKBsbWxtmQFJS70DNM52voqg0eS1ijdVU2G/dm0HI18J8EyEMO4NTYY7IIM0rWnuMPq9XPqhgEVcT4LDNKJa3Fkb" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="connected to ap-guc3.spotify.com:443" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="completed keyexchange" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="completed challenge" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=info msg="authenticated AP" username="12*****01" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=info msg="authenticated Login5" username="12*****01" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="initializing zeroconf session" username="12*****01" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="dealer connection opened" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=trace msg="starting accesspoint recv loop" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=trace msg="starting dealer recv loop" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=trace msg="received accesspoint ping" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=debug msg="received connection id: NjUzNWYyNmItZTY0...NjNFQUVGQzEyNg==" Feb 23 22:26:34 office go-librespot[4265]: time="2026-02-23T22:26:34-08:00" level=trace msg="received accesspoint pong ack" Feb 23 22:26:35 office sudo[4302]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-23 22:25' Feb 23 22:26:35 office sudo[4302]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"