Dec 09 23:04:06 volumio go-librespot[2722]: time="2025-12-09T23:04:06+02:00" level=debug msg="fetched chunk 11/14, size: 524288" uri="spotify:track:7ikhNuvUr9kH4aefmajeqi" Dec 09 23:04:19 volumio go-librespot[2722]: time="2025-12-09T23:04:19+02:00" level=debug msg="fetched chunk 12/14, size: 524288" uri="spotify:track:7ikhNuvUr9kH4aefmajeqi" Dec 09 23:04:22 volumio go-librespot[2722]: time="2025-12-09T23:04:22+02:00" level=trace msg="received accesspoint ping" Dec 09 23:04:22 volumio go-librespot[2722]: time="2025-12-09T23:04:22+02:00" level=trace msg="received accesspoint pong ack" Dec 09 23:04:22 volumio go-librespot[2722]: time="2025-12-09T23:04:22+02:00" level=trace msg="sent dealer ping" Dec 09 23:04:22 volumio go-librespot[2722]: time="2025-12-09T23:04:22+02:00" level=trace msg="received dealer pong" Dec 09 23:04:30 volumio go-librespot[2722]: time="2025-12-09T23:04:30+02:00" level=debug msg="fetched chunk 13/14, size: 524288" uri="spotify:track:7ikhNuvUr9kH4aefmajeqi" Dec 09 23:04:31 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 09 23:04:37 volumio ntpd[828]: PROTO: 31.14.41.138 unlink local addr 192.168.0.127 -> Dec 09 23:04:41 volumio go-librespot[2722]: time="2025-12-09T23:04:41+02:00" level=debug msg="fetched chunk 14/14, size: 292440" uri="spotify:track:7ikhNuvUr9kH4aefmajeqi" Dec 09 23:04:42 volumio kernel: usb 1-1.3: new full-speed USB device number 6 using dwc_otg Dec 09 23:04:42 volumio kernel: usb 1-1.3: New USB device found, idVendor=17ef, idProduct=60ea, bcdDevice= 0.00 Dec 09 23:04:42 volumio kernel: usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Dec 09 23:04:42 volumio kernel: usb 1-1.3: Product: Thinkpad X1 ANC Headphones USB Dec 09 23:04:42 volumio kernel: usb 1-1.3: Manufacturer: Lenovo Dec 09 23:04:42 volumio kernel: input: Lenovo Thinkpad X1 ANC Headphones USB Consumer Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.3/0003:17EF:60EA.0001/input/input1 Dec 09 23:04:42 volumio kernel: input: Lenovo Thinkpad X1 ANC Headphones USB as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.3/0003:17EF:60EA.0001/input/input2 Dec 09 23:04:42 volumio kernel: hid-generic 0003:17EF:60EA.0001: input,hiddev96,hidraw0: USB HID v1.11 Device [Lenovo Thinkpad X1 ANC Headphones USB] on usb-3f980000.usb-1.3/input3 Dec 09 23:04:42 volumio kernel: usb 1-1.3: Warning! Unlikely big volume range (=18944), cval->res is probably wrong. Dec 09 23:04:42 volumio kernel: usb 1-1.3: [2] FU [PCM Playback Volume] ch = 2, val = -18944/0/1 Dec 09 23:04:42 volumio kernel: usb 1-1.3: Warning! Unlikely big volume range (=18944), cval->res is probably wrong. Dec 09 23:04:42 volumio kernel: usb 1-1.3: [6] FU [Headset Capture Volume] ch = 2, val = -18944/0/1 Dec 09 23:04:42 volumio kernel: usbcore: registered new interface driver snd-usb-audio Dec 09 23:04:42 volumio (udev-worker)[4504]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Dec 09 23:04:42 volumio volumio[1215]: info: No valid Plugin REST Endpoint Dec 09 23:04:43 volumio volumio[1215]: info: Dec 09 23:04:43 volumio volumio[1215]: ---------------------------- USB Audio Device Attached Dec 09 23:04:43 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Dec 09 23:04:43 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 09 23:04:43 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 09 23:04:43 volumio systemd[1]: setdatetime-helper.service: Consumed 1.789s CPU time. Dec 09 23:04:50 volumio sudo[4548]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 23:04:50 volumio sudo[4548]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:04:50 volumio sudo[4548]: pam_unix(sudo:session): session closed for user root Dec 09 23:04:50 volumio sudo[4550]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 23:04:50 volumio sudo[4550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:04:50 volumio sudo[4550]: pam_unix(sudo:session): session closed for user root Dec 09 23:04:50 volumio volumio[1215]: verbose: New Socket.io Connection to 192.168.0.127 from 192.168.0.189 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/26.0.1 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 5 Dec 09 23:04:50 volumio volumio[1215]: verbose: New Socket.io Connection to 192.168.0.127 from 192.168.0.189 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/26.0.1 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 6 Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::volumioGetVisibleSources Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::volumioGetQueue Dec 09 23:04:50 volumio volumio[1215]: info: CoreStateMachine::getQueue Dec 09 23:04:50 volumio volumio[1215]: info: CorePlayQueue::getQueue Dec 09 23:04:50 volumio volumio[1215]: info: Listing playlists Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 09 23:04:50 volumio volumio[1215]: info: Received Get System Info Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 23:04:50 volumio volumio[1215]: info: Discovery: Getting this device information Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 09 23:04:50 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 09 23:04:52 volumio go-librespot[2722]: time="2025-12-09T23:04:52+02:00" level=trace msg="sent dealer ping" Dec 09 23:04:52 volumio go-librespot[2722]: time="2025-12-09T23:04:52+02:00" level=trace msg="received dealer pong" Dec 09 23:04:52 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 09 23:04:52 volumio volumio[1215]: info: Received Get System Info Dec 09 23:04:52 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 09 23:04:52 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 23:04:52 volumio volumio[1215]: info: Discovery: Getting this device information Dec 09 23:04:52 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:52 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 23:04:52 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 09 23:04:52 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 09 23:04:56 volumio sudo[4572]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 23:04:56 volumio sudo[4572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:04:56 volumio sudo[4572]: pam_unix(sudo:session): session closed for user root Dec 09 23:04:56 volumio sudo[4574]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 23:04:56 volumio sudo[4574]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:04:56 volumio sudo[4574]: pam_unix(sudo:session): session closed for user root Dec 09 23:04:56 volumio volumio[1215]: verbose: New Socket.io Connection to 192.168.0.127 from 192.168.0.189 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 26_0_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/143.0.7499.92 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 7 Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::volumioGetVisibleSources Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 09 23:04:56 volumio volumio[1215]: info: Received Get System Info Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 23:04:56 volumio volumio[1215]: info: Discovery: Getting this device information Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:56 volumio volumio[1215]: info: Listing playlists Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 09 23:04:56 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 09 23:04:58 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 09 23:04:58 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 09 23:04:58 volumio volumio[1215]: info: Received Get System Info Dec 09 23:04:58 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 09 23:04:58 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 23:04:58 volumio volumio[1215]: info: Discovery: Getting this device information Dec 09 23:04:58 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:58 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 23:04:59 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 09 23:04:59 volumio volumio[1215]: info: Received Get System Info Dec 09 23:04:59 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 09 23:04:59 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 23:04:59 volumio volumio[1215]: info: Discovery: Getting this device information Dec 09 23:04:59 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:04:59 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 23:05:00 volumio go-librespot[2722]: time="2025-12-09T23:05:00+02:00" level=debug msg="prefetching next track" uri="spotify:track:45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:00 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 09 23:05:00 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 09 23:05:00 volumio go-librespot[2722]: time="2025-12-09T23:05:00+02:00" level=debug msg="selected format OGG_VORBIS_320 (3b85774d5e160e0babaaff669409181c8465faa3)" uri="spotify:track:45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:00 volumio go-librespot[2722]: time="2025-12-09T23:05:00+02:00" level=debug msg="requested aes key for file 3b85774d5e160e0babaaff669409181c8465faa3, gid: 45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:00 volumio go-librespot[2722]: time="2025-12-09T23:05:00+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:01 volumio go-librespot[2722]: time="2025-12-09T23:05:01+02:00" level=debug msg="fetched first chunk of 19, total size is 9573305 bytes" uri="spotify:track:45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:01 volumio go-librespot[2722]: time="2025-12-09T23:05:01+02:00" level=info msg="prefetched track \"O să fie bine\" (duration: 229236ms)" uri="spotify:track:45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:01 volumio go-librespot[2722]: time="2025-12-09T23:05:01+02:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:01 volumio go-librespot[2722]: time="2025-12-09T23:05:01+02:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:01 volumio go-librespot[2722]: time="2025-12-09T23:05:01+02:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:45CGWu4GcaVmgXcW7KocgM" Dec 09 23:05:04 volumio volumio[1215]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 09 23:05:06 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 09 23:05:10 volumio volumio[1215]: info: Received OAUTH Data Dec 09 23:05:10 volumio volumio[1215]: info: Executing Spotify Oauth Login Dec 09 23:05:10 volumio volumio[1215]: info: Saving Spotify Refresh Token Dec 09 23:05:10 volumio volumio[1215]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 09 23:05:10 volumio volumio[1215]: SPOTIFY: BQCYqZustp3s-71gVWR-_Hn-RiXcfU5ziaVuwvEb9eU-YtHwpCdAn49xzib54nTLRJcHseBRW3_xz2zGHeD5--tn7yMQERC47uG6k8aIriQP1u3nhFML-GadIBfuUpivKewfogOOcxK08i5yY2uSJD-lewT4xfOvM1unTUKG0PDD356PSvmwJvowj0voih7VfDi1giaHvk5O3dirahxxQVBgtJKGvoizK2YTPHKhwBCS9X65BuJ_PpQJ3g6Mmur7bzFEljkEpprkh5vAfIUfF8ODJvPooX03X8IQ Dec 09 23:05:10 volumio volumio[1215]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 09 23:05:10 volumio volumio[1215]: info: New Spotify access token = BQCYqZustp3s-71gVWR-_Hn-RiXcfU5ziaVuwvEb9eU-YtHwpCdAn49xzib54nTLRJcHseBRW3_xz2zGHeD5--tn7yMQERC47uG6k8aIriQP1u3nhFML-GadIBfuUpivKewfogOOcxK08i5yY2uSJD-lewT4xfOvM1unTUKG0PDD356PSvmwJvowj0voih7VfDi1giaHvk5O3dirahxxQVBgtJKGvoizK2YTPHKhwBCS9X65BuJ_PpQJ3g6Mmur7bzFEljkEpprkh5vAfIUfF8ODJvPooX03X8IQ Dec 09 23:05:10 volumio volumio[1215]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 09 23:05:11 volumio sudo[4598]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 23:05:11 volumio sudo[4598]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:05:11 volumio sudo[4598]: pam_unix(sudo:session): session closed for user root Dec 09 23:05:11 volumio sudo[4600]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 23:05:11 volumio sudo[4600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:05:11 volumio sudo[4600]: pam_unix(sudo:session): session closed for user root Dec 09 23:05:11 volumio volumio[1215]: verbose: New Socket.io Connection to 192.168.0.127 from 192.168.0.189 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 26_0_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/143.0.7499.92 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 6 Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::volumioGetVisibleSources Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 09 23:05:11 volumio volumio[1215]: info: Received Get System Info Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 23:05:11 volumio volumio[1215]: info: Discovery: Getting this device information Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:05:11 volumio volumio[1215]: info: Listing playlists Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 09 23:05:11 volumio volumio[1215]: SPOTIFY: User informations: {"country":"RO","display_name":"paulielciu","email":"paulielciu@gmail.com","explicit_content":{"filter_enabled":true,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/paulielciu"},"followers":{"href":null,"total":4},"href":"https://api.spotify.com/v1/users/paulielciu","id":"paulielciu","images":[],"product":"premium","type":"user","uri":"spotify:user:paulielciu"} Dec 09 23:05:11 volumio volumio[1215]: info: Creating Spotify config file Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 09 23:05:11 volumio volumio[1215]: info: Spotify config file written Dec 09 23:05:11 volumio sudo[4606]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 09 23:05:11 volumio sudo[4606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:05:11 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 09 23:05:11 volumio systemd[1]: go-librespot-daemon.service: Killing process 2728 (go-librespot) with signal SIGKILL. Dec 09 23:05:11 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 09 23:05:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 23:05:11 volumio systemd[1]: go-librespot-daemon.service: Consumed 22.926s CPU time. Dec 09 23:05:11 volumio volumio[1215]: info: Connection to go-librespot Websocket closed Dec 09 23:05:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 23:05:11 volumio sudo[4606]: pam_unix(sudo:session): session closed for user root Dec 09 23:05:11 volumio go-librespot[4609]: go-librespot daemon starting... Dec 09 23:05:11 volumio volumio[1215]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 09 23:05:11 volumio volumio[1215]: SPOTIFY: BQDPla0ERZT9BfOCGyc7wAXqGxU7plmLRXQPJ9QuZZBdR0ASUS5vUQjj4BKKblkfYZ9caXMvgCPW2W9olRLRjfXcPhvj95LewFDBweE74G7XAHTcwvXzU_qg173adb2KHADGB110UrtJnwirYycQ1pi4aQTAMBvQqG0B9ZegUZos1Ko5zp6ejOauJigSQ64fpb2pqXq_4g0LUwz3QzC4EpooumGiHAUURglZ2I3hZAJ4dEyEYn09pFTEk4eFIzbjd06RkJHk2vb8MkDHmCxLbM2AXL7DiKsv8LEf Dec 09 23:05:11 volumio volumio[1215]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 09 23:05:11 volumio volumio[1215]: info: New Spotify access token = BQDPla0ERZT9BfOCGyc7wAXqGxU7plmLRXQPJ9QuZZBdR0ASUS5vUQjj4BKKblkfYZ9caXMvgCPW2W9olRLRjfXcPhvj95LewFDBweE74G7XAHTcwvXzU_qg173adb2KHADGB110UrtJnwirYycQ1pi4aQTAMBvQqG0B9ZegUZos1Ko5zp6ejOauJigSQ64fpb2pqXq_4g0LUwz3QzC4EpooumGiHAUURglZ2I3hZAJ4dEyEYn09pFTEk4eFIzbjd06RkJHk2vb8MkDHmCxLbM2AXL7DiKsv8LEf Dec 09 23:05:11 volumio volumio[1215]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 09 23:05:11 volumio go-librespot[4610]: time="2025-12-09T23:05:11+02:00" level=info msg="running go-librespot 0.4.0" Dec 09 23:05:11 volumio go-librespot[4610]: time="2025-12-09T23:05:11+02:00" level=debug msg="app state loaded" Dec 09 23:05:11 volumio go-librespot[4610]: time="2025-12-09T23:05:11+02:00" level=debug msg="stored credentials not found" Dec 09 23:05:11 volumio go-librespot[4610]: time="2025-12-09T23:05:11+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 23:05:11 volumio volumio[1215]: SPOTIFY: User informations: {"country":"RO","display_name":"paulielciu","email":"paulielciu@gmail.com","explicit_content":{"filter_enabled":true,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/paulielciu"},"followers":{"href":null,"total":4},"href":"https://api.spotify.com/v1/users/paulielciu","id":"paulielciu","images":[],"product":"premium","type":"user","uri":"spotify:user:paulielciu"} Dec 09 23:05:11 volumio volumio[1215]: info: Spotify Successfully logged in Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 23:05:11 volumio volumio[1215]: info: [1765314311865] CoreMusicLibrary::Adding element Spotify Dec 09 23:05:11 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 23:05:11 volumio volumio[1215]: Cannot find translation for source Spotify Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=info msg="zeroconf server listening on port 45561" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="obtained new client token: AADIzsTUnVm5143sB+8L70MgaZKv+zwNcN3jK81ZK5FGFLBlMH3vDLXapOOzEYyYHifeTon4VxC8Sxvz7WlzANxa75Z83bINdCtGvJ8z+JR/Oj9vj/U7fsU61lYDbwF9mcbke7VIZJ7vhyElM76wW1E/k6/2CKPXLQs72G/ibSVcexD+9C9wwsRO7A+WdN//J7fhAtk1LsTq5GfgavoslCwLp9UtHDejM9e4WbOOiwDZeFpM8xUTWC8d" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="completed keyexchange" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="completed challenge" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=info msg="authenticated AP" username="pa******iu" Dec 09 23:05:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=info msg="authenticated Login5" username="pa******iu" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="stored credentials" username="pa******iu" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="initializing zeroconf session" username="pa******iu" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="dealer connection opened" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=trace msg="starting accesspoint recv loop" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=trace msg="starting dealer recv loop" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=trace msg="received accesspoint ping" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 09 23:05:12 volumio go-librespot[4610]: time="2025-12-09T23:05:12+02:00" level=debug msg="received connection id: MWFhMTFjMmYtYTYx...MDcwNjA0QUJBMQ==" Dec 09 23:05:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 09 23:05:12 volumio volumio[1215]: info: Received Get System Info Dec 09 23:05:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 09 23:05:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 23:05:12 volumio volumio[1215]: info: Discovery: Getting this device information Dec 09 23:05:12 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:05:12 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 23:05:13 volumio go-librespot[4610]: time="2025-12-09T23:05:13+02:00" level=debug msg="put connect state because NEW_DEVICE" Dec 09 23:05:13 volumio go-librespot[4610]: time="2025-12-09T23:05:13+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 09 23:05:13 volumio go-librespot[4610]: time="2025-12-09T23:05:13+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 09 23:05:13 volumio go-librespot[4610]: time="2025-12-09T23:05:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 09 23:05:13 volumio go-librespot[4610]: time="2025-12-09T23:05:13+02:00" level=trace msg="received accesspoint pong ack" Dec 09 23:05:13 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 09 23:05:13 volumio volumio[1215]: info: Received Get System Info Dec 09 23:05:13 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 09 23:05:13 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 23:05:13 volumio volumio[1215]: info: Discovery: Getting this device information Dec 09 23:05:13 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:05:13 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 23:05:14 volumio volumio[1215]: info: Initializing connection to go-librespot Websocket Dec 09 23:05:14 volumio go-librespot[4610]: time="2025-12-09T23:05:14+02:00" level=debug msg="new websocket client" Dec 09 23:05:14 volumio volumio[1215]: info: Connection to go-librespot Websocket established Dec 09 23:05:14 volumio volumio[1215]: info: go-librespot daemon successfully initialized Dec 09 23:05:17 volumio volumio[1215]: info: Getting Spotify volume Dec 09 23:05:17 volumio volumio[1215]: info: Spotify volume: 100 Dec 09 23:05:17 volumio volumio[1215]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 09 23:05:17 volumio volumio[1215]: info: Initializing connection to go-librespot Websocket Dec 09 23:05:17 volumio go-librespot[4610]: time="2025-12-09T23:05:17+02:00" level=debug msg="new websocket client" Dec 09 23:05:17 volumio volumio[1215]: info: Connection to go-librespot Websocket established Dec 09 23:05:17 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:05:17 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 09 23:05:17 volumio volumio[1215]: SPOTIFY: SPOTIFY VOLUME 100 Dec 09 23:05:17 volumio volumio[1215]: SPOTIFY: VOLUMIO VOLUME 86 Dec 09 23:05:17 volumio volumio[1215]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 09 23:05:17 volumio volumio[1215]: info: Setting Spotify Volume from Volumio: 86 Dec 09 23:05:18 volumio volumio[1215]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 09 23:05:18 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 09 23:05:18 volumio volumio[1215]: info: Creating Spotify config file Dec 09 23:05:18 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 23:05:18 volumio volumio[1215]: info: Spotify config file written Dec 09 23:05:18 volumio sudo[4634]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 09 23:05:18 volumio sudo[4634]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:05:18 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 09 23:05:18 volumio systemd[1]: go-librespot-daemon.service: Killing process 4616 (go-librespot) with signal SIGKILL. Dec 09 23:05:18 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 09 23:05:18 volumio volumio[1215]: info: Connection to go-librespot Websocket closed Dec 09 23:05:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 23:05:18 volumio volumio[1215]: info: Connection to go-librespot Websocket closed Dec 09 23:05:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 23:05:18 volumio go-librespot[4637]: go-librespot daemon starting... Dec 09 23:05:18 volumio sudo[4634]: pam_unix(sudo:session): session closed for user root Dec 09 23:05:18 volumio go-librespot[4638]: time="2025-12-09T23:05:18+02:00" level=info msg="running go-librespot 0.4.0" Dec 09 23:05:18 volumio go-librespot[4638]: time="2025-12-09T23:05:18+02:00" level=debug msg="app state loaded" Dec 09 23:05:18 volumio go-librespot[4638]: time="2025-12-09T23:05:18+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 23:05:18 volumio go-librespot[4638]: time="2025-12-09T23:05:18+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 09 23:05:18 volumio go-librespot[4638]: time="2025-12-09T23:05:18+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 09 23:05:18 volumio go-librespot[4638]: time="2025-12-09T23:05:18+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=info msg="zeroconf server listening on port 46875" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="obtained new client token: AAB6+suQFrmyKeoPcaadl7sCbWamXeSgReYaIDKPS2M07UP8BbBzgj05FvZ2AMfmSC55AA7XSl3t6PRH2q2vVoTTacLmIkBgph8nOCSrVKwVuJ6w/WdhYZSvNp3UIzT2vID61Z77qt6NxxFknKmY8zrPEssqW9wtCdva9kwNtzgYi3E8o5aT4nN3WiTMnOnw55jWnDQ9QhrecQ1dRQAACLa1YfOAobO8rpCrTZko+RCJ3ebnb7fVwg==" Dec 09 23:05:19 volumio volumio[1215]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Dec 09 23:05:19 volumio volumio[1215]: info: Sending Spotify command with payload to local API: /player/volume Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="completed keyexchange" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="completed challenge" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=info msg="authenticated AP" username="pa******iu" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=info msg="authenticated Login5" username="pa******iu" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="initializing zeroconf session" username="pa******iu" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="dealer connection opened" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=trace msg="starting accesspoint recv loop" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=trace msg="starting dealer recv loop" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="update volume requested to 56360/65535" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=trace msg="received accesspoint ping" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="received connection id: MGZhMjI4ZDgtNWQz...QkY1RTkyQTBBRg==" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=trace msg="received accesspoint pong ack" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="put connect state because NEW_DEVICE" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 09 23:05:19 volumio go-librespot[4638]: time="2025-12-09T23:05:19+02:00" level=trace msg="emitting websocket event: volume" Dec 09 23:05:20 volumio volumio[1215]: info: Getting Spotify volume Dec 09 23:05:20 volumio volumio[1215]: info: Spotify volume: 86 Dec 09 23:05:20 volumio volumio[1215]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 09 23:05:20 volumio volumio[1215]: info: CoreCommandRouter::volumioGetState Dec 09 23:05:20 volumio volumio[1215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 09 23:05:21 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 09 23:05:21 volumio volumio[1215]: info: Initializing connection to go-librespot Websocket Dec 09 23:05:21 volumio go-librespot[4638]: time="2025-12-09T23:05:21+02:00" level=debug msg="new websocket client" Dec 09 23:05:21 volumio volumio[1215]: info: Connection to go-librespot Websocket established Dec 09 23:05:21 volumio volumio[1215]: info: go-librespot daemon successfully initialized Dec 09 23:05:22 volumio volumio[1215]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 09 23:05:22 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 09 23:05:22 volumio volumio[1215]: info: Creating Spotify config file Dec 09 23:05:22 volumio volumio[1215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 23:05:22 volumio volumio[1215]: info: Spotify config file written Dec 09 23:05:22 volumio sudo[4647]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 09 23:05:22 volumio sudo[4647]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:05:22 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 09 23:05:22 volumio systemd[1]: go-librespot-daemon.service: Killing process 4642 (go-librespot) with signal SIGKILL. Dec 09 23:05:22 volumio volumio[1215]: info: Connection to go-librespot Websocket closed Dec 09 23:05:22 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 09 23:05:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 23:05:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 23:05:22 volumio go-librespot[4649]: go-librespot daemon starting... Dec 09 23:05:22 volumio sudo[4647]: pam_unix(sudo:session): session closed for user root Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=info msg="running go-librespot 0.4.0" Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=debug msg="app state loaded" Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=info msg="zeroconf server listening on port 35761" Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=debug msg="obtained new client token: AAAfxh4kxBNc92xpVL7RKeJe8EN+SX7BUFfVDCwVpDgyFrejuGS2DfGKIMDA5honK0tVhL7XRRAwMkGMYgAM6MTt3A+lbeKptx3RlDoaXj5HJ/ULeMFOIWs+kFPQme4QY/D2BxCRF4EHz8DyW98mJJrvn59fDLSyxVNDN9ud9Iq/Labn/QovZmN5TjlruQIwO98Ql852j5psKOO5D5Q0/tb+TLeM95ETjt+i94cYjlSworQxxu+rjVkP" Dec 09 23:05:22 volumio go-librespot[4650]: time="2025-12-09T23:05:22+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 09 23:05:23 volumio go-librespot[4650]: time="2025-12-09T23:05:23+02:00" level=debug msg="completed keyexchange" Dec 09 23:05:23 volumio go-librespot[4650]: time="2025-12-09T23:05:23+02:00" level=debug msg="completed challenge" Dec 09 23:05:23 volumio go-librespot[4650]: time="2025-12-09T23:05:23+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 23:05:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 23:05:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 23:05:24 volumio volumio[1215]: info: Getting Spotify volume Dec 09 23:05:24 volumio volumio[1215]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 23:05:24 volumio volumio[1215]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 23:05:24 volumio volumio[1215]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 09 23:05:24 volumio volumio[1215]: errno: -111, Dec 09 23:05:24 volumio volumio[1215]: code: 'ECONNREFUSED', Dec 09 23:05:24 volumio volumio[1215]: syscall: 'connect', Dec 09 23:05:24 volumio volumio[1215]: address: '127.0.0.1', Dec 09 23:05:24 volumio volumio[1215]: port: 9879, Dec 09 23:05:24 volumio volumio[1215]: response: undefined Dec 09 23:05:24 volumio volumio[1215]: } Dec 09 23:05:24 volumio volumio[1215]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 23:05:26 volumio sudo[4685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 23:04' Dec 09 23:05:26 volumio sudo[4685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 23:05:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 09 23:05:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. 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"