Dec 16 09:44:29 volumio sudo[4571]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 16 09:44:29 volumio sudo[4571]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:44:29 volumio sudo[4571]: pam_unix(sudo:session): session closed for user root Dec 16 09:44:29 volumio sudo[4573]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 16 09:44:29 volumio sudo[4573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:44:29 volumio sudo[4573]: pam_unix(sudo:session): session closed for user root Dec 16 09:44:29 volumio volumio[1115]: verbose: New Socket.io Connection to 192.168.100.111 from 192.168.100.112 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 Dec 16 09:44:29 volumio sudo[4578]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 16 09:44:29 volumio sudo[4578]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:44:29 volumio sudo[4580]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 16 09:44:29 volumio sudo[4580]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:44:29 volumio sudo[4578]: pam_unix(sudo:session): session closed for user root Dec 16 09:44:29 volumio sudo[4580]: pam_unix(sudo:session): session closed for user root Dec 16 09:44:29 volumio volumio[1115]: verbose: New Socket.io Connection to 192.168.100.111 from 192.168.100.112 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Dec 16 09:44:29 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 16 09:44:29 volumio volumio[1115]: info: CoreCommandRouter::volumioGetVisibleSources Dec 16 09:44:29 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 09:44:29 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:29 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:29 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 16 09:44:30 volumio volumio[1115]: info: Received Get System Info Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:44:30 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:30 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:30 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:30 volumio volumio[1115]: info: Listing playlists Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 16 09:44:30 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:30 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:31 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 16 09:44:31 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 09:44:31 volumio volumio[1115]: info: Received Get System Info Dec 16 09:44:31 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:44:31 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:44:31 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:44:31 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:31 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:31 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:44:32 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 16 09:44:32 volumio volumio[1115]: info: MyVolumio login type: Token Dec 16 09:44:32 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 09:44:32 volumio volumio[1115]: info: Received Get System Info Dec 16 09:44:32 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:44:32 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:44:32 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:44:32 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:32 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:32 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:44:32 volumio volumio[1115]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 16 09:44:32 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 16 09:44:32 volumio volumio[1115]: info: MyVolumio login type: Token Dec 16 09:44:33 volumio volumio[1115]: info: MyVolumio token set successfully Dec 16 09:44:33 volumio volumio[1115]: info: MYVOLUMIO: Adding device Dec 16 09:44:33 volumio volumio[1115]: info: MYVOLUMIO: Evaluating Server Dec 16 09:44:33 volumio volumio[1115]: info: MyVolumio status changed Dec 16 09:44:33 volumio volumio[1115]: info: Streaming services startup Dec 16 09:44:33 volumio volumio[1115]: info: Starting Streaming Daemon Dec 16 09:44:33 volumio volumio[1115]: info: Removing browser output: myVolumio user plan is not superstar Dec 16 09:44:33 volumio volumio[1115]: info: Removing audio output: Dec 16 09:44:33 volumio volumio[1115]: info: Stoppping Tunnel 1 Dec 16 09:44:33 volumio sudo[4606]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 16 09:44:33 volumio sudo[4606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:44:33 volumio sudo[4608]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 16 09:44:33 volumio sudo[4608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:44:33 volumio sudo[4606]: pam_unix(sudo:session): session closed for user root Dec 16 09:44:33 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 16 09:44:33 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 16 09:44:33 volumio volumio[1115]: error: Cannot start Volumio Streaming Daemon Dec 16 09:44:33 volumio volumio[1115]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 16 09:44:33 volumio volumio[1115]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 16 09:44:33 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 16 09:44:33 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 16 09:44:33 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 16 09:44:33 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 16 09:44:33 volumio sudo[4608]: pam_unix(sudo:session): session closed for user root Dec 16 09:44:33 volumio volumio[1115]: info: Remote SSH Stopped Dec 16 09:44:33 volumio volumio[1115]: info: Setting Geolocation for MyVolumio to eu6 Dec 16 09:44:33 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:33 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:33 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:34 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 09:44:34 volumio volumio[1115]: info: Received Get System Info Dec 16 09:44:34 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:44:34 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:44:34 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:44:34 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:34 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:34 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:44:34 volumio volumio[1115]: info: Updating MyVolumio device info Dec 16 09:44:34 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:34 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:34 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:35 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 09:44:35 volumio volumio[1115]: info: Received Get System Info Dec 16 09:44:35 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:44:35 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:44:35 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:44:35 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:35 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:35 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:44:35 volumio ntpd[891]: PROTO: 195.133.18.24 unlink local addr 192.168.100.111 -> Dec 16 09:44:36 volumio volumio[1115]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 16 09:44:36 volumio volumio[1115]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 16 09:44:37 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: wizard , setOnboardingWizardFalse Dec 16 09:44:39 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 16 09:44:40 volumio volumio[1115]: info: MYVOLUMIO: Adding device Dec 16 09:44:40 volumio volumio[1115]: info: MYVOLUMIO: Evaluating Server Dec 16 09:44:41 volumio volumio[1115]: info: CoreCommandRouter::Close All Modals sent Dec 16 09:44:41 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: appearance , setTOSAccepted Dec 16 09:44:42 volumio volumio[1115]: info: Setting Geolocation for MyVolumio to eu6 Dec 16 09:44:42 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:42 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:42 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:43 volumio volumio[1115]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 16 09:44:43 volumio volumio[1115]: info: Updating MyVolumio device info Dec 16 09:44:43 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:43 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:43 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 09:44:43 volumio ntpd[891]: PROTO: 162.159.200.123 unlink local addr 192.168.100.111 -> Dec 16 09:44:43 volumio volumio[1115]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 16 09:44:45 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 09:44:45 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 16 09:44:46 volumio ntpd[891]: PROTO: 93.99.104.53 unlink local addr 192.168.100.111 -> Dec 16 09:44:48 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 16 09:44:48 volumio volumio[1115]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 16 09:44:48 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 16 09:44:48 volumio volumio[1115]: info: Received Get System Version Dec 16 09:44:48 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 16 09:44:48 volumio volumio[1115]: info: Received Get System Info Dec 16 09:44:48 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:44:48 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:44:48 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:44:48 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:44:48 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:44:48 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:44:54 volumio volumio[1115]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf Dec 16 09:44:57 volumio volumio[1115]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf Dec 16 09:44:57 volumio volumio[1115]: info: Folder /tmp/plugins removed Dec 16 09:44:57 volumio volumio[1115]: info: Check plugin dependencies Dec 16 09:44:57 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 16 09:44:57 volumio volumio[1115]: info: Checking if plugin already exists Dec 16 09:44:57 volumio volumio[1115]: info: Rename folder Dec 16 09:44:57 volumio volumio[1115]: info: Folder /tmp/downloaded_plugin.zip removed Dec 16 09:44:57 volumio volumio[1115]: info: Move to category Dec 16 09:44:57 volumio volumio[1115]: info: Checking if install.sh is present Dec 16 09:44:57 volumio volumio[1115]: info: Executing install.sh Dec 16 09:44:58 volumio sudo[4714]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/music_service/spop/install.sh Dec 16 09:44:58 volumio sudo[4714]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:44:58 volumio volumio[1115]: info: Installing Go-librespot Dec 16 09:44:58 volumio volumio[1115]: info: Checking old vollibrespot installs Dec 16 09:44:58 volumio systemd[1]: Reloading. Dec 16 09:44:59 volumio volumio[1115]: info: Downloading daemon Dec 16 09:45:02 volumio volumio[1115]: info: Creating directories Dec 16 09:45:02 volumio volumio[1115]: info: Creating data directory Dec 16 09:45:02 volumio volumio[1115]: info: Creating Start Script Dec 16 09:45:02 volumio systemd[1]: Reloading. Dec 16 09:45:04 volumio sudo[4714]: pam_unix(sudo:session): session closed for user root Dec 16 09:45:04 volumio volumio[1115]: Plugin install end detected on script Dec 16 09:45:04 volumio volumio[1115]: info: Install script completed Dec 16 09:45:04 volumio volumio[1115]: info: Adding reference to registry Dec 16 09:45:04 volumio volumio[1115]: info: Done installing plugin. Dec 16 09:45:04 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 09:45:04 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 16 09:45:04 volumio volumio[1115]: info: Folder /tmp/plugins removed Dec 16 09:45:04 volumio volumio[1115]: info: Folder /tmp/downloaded_plugin.zip removed Dec 16 09:45:04 volumio volumio[1115]: info: Folder /data/temp removed Dec 16 09:45:07 volumio volumio[1115]: info: Enabling plugin spop Dec 16 09:45:07 volumio volumio[1115]: info: Loading plugin "spop"... Dec 16 09:45:09 volumio volumio[1115]: info: PLUGIN START: spop Dec 16 09:45:09 volumio volumio[1115]: info: Creating Spotify config file Dec 16 09:45:09 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 09:45:09 volumio volumio[1115]: info: Done. Dec 16 09:45:09 volumio volumio[1115]: info: Spotify config file written Dec 16 09:45:09 volumio volumio[1115]: info: No need to fix Spotify hosts Dec 16 09:45:09 volumio sudo[4794]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 09:45:09 volumio sudo[4794]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:45:09 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 16 09:45:09 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 16 09:45:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 09:45:09 volumio go-librespot[4796]: go-librespot daemon starting... Dec 16 09:45:09 volumio sudo[4794]: pam_unix(sudo:session): session closed for user root Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=info msg="running go-librespot 0.4.0" Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=debug msg="no app state found" Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=debug msg="stored credentials not found" Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=info msg="generated new device id: 9f470cea7b4ef2d60b36d9c8c253e278acfe2f5f" Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 16 09:45:09 volumio go-librespot[4797]: time="2025-12-16T09:45:09+01:00" level=info msg="zeroconf server listening on port 37087" Dec 16 09:45:12 volumio volumio[1115]: info: go-librespot daemon successfully initialized Dec 16 09:45:14 volumio volumio[1115]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 16 09:45:15 volumio volumio[1115]: info: Initializing connection to go-librespot Websocket Dec 16 09:45:15 volumio go-librespot[4797]: time="2025-12-16T09:45:15+01:00" level=debug msg="new websocket client" Dec 16 09:45:15 volumio volumio[1115]: info: Connection to go-librespot Websocket established Dec 16 09:45:17 volumio volumio[1115]: info: Received OAUTH Data Dec 16 09:45:17 volumio volumio[1115]: info: Executing Spotify Oauth Login Dec 16 09:45:17 volumio volumio[1115]: info: Saving Spotify Refresh Token Dec 16 09:45:17 volumio sudo[4820]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 16 09:45:17 volumio sudo[4820]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:45:17 volumio sudo[4822]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 16 09:45:17 volumio sudo[4822]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:45:17 volumio sudo[4820]: pam_unix(sudo:session): session closed for user root Dec 16 09:45:17 volumio sudo[4822]: pam_unix(sudo:session): session closed for user root Dec 16 09:45:17 volumio volumio[1115]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 16 09:45:17 volumio volumio[1115]: SPOTIFY: BQCKh8Pcbri3R8htEMsoAJU_n5RxP6LtWp7LP7-j5XfZFJCq-WcrqCB_ZzI60f9wU9Dp8QCD9y-3g-LatqiM2Wb56PBNRVIks--7sQIBflukvIQZyAnp5EijPyv-Bl7t4JU2VkLLFQR1oGrdCADASeMH4RqU9_4i7cFBItKxGv4PvB96H-BIg2QdEcgkFGsVX1bR-Amz9okvljx20o9Hn_VctFuzhxKuMAI1tPOT3rdZ8w4n59JF20cXLSvSv9VQBo15KxhX8zJeEIrGTUj4Q0tknwXkevOFRSp2mw Dec 16 09:45:17 volumio volumio[1115]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 16 09:45:17 volumio volumio[1115]: info: New Spotify access token = BQCKh8Pcbri3R8htEMsoAJU_n5RxP6LtWp7LP7-j5XfZFJCq-WcrqCB_ZzI60f9wU9Dp8QCD9y-3g-LatqiM2Wb56PBNRVIks--7sQIBflukvIQZyAnp5EijPyv-Bl7t4JU2VkLLFQR1oGrdCADASeMH4RqU9_4i7cFBItKxGv4PvB96H-BIg2QdEcgkFGsVX1bR-Amz9okvljx20o9Hn_VctFuzhxKuMAI1tPOT3rdZ8w4n59JF20cXLSvSv9VQBo15KxhX8zJeEIrGTUj4Q0tknwXkevOFRSp2mw Dec 16 09:45:17 volumio volumio[1115]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 16 09:45:17 volumio volumio[1115]: verbose: New Socket.io Connection to 192.168.100.111 from 192.168.100.112 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::volumioGetVisibleSources Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:45:17 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 16 09:45:17 volumio volumio[1115]: info: Received Get System Info Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:45:17 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:45:17 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:45:17 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:45:17 volumio volumio[1115]: info: Listing playlists Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 16 09:45:17 volumio volumio[1115]: SPOTIFY: User informations: {"country":"CZ","display_name":"Vojta Talášek","email":"vojtech.talasek@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11125033288"},"followers":{"href":null,"total":16},"href":"https://api.spotify.com/v1/users/11125033288","id":"11125033288","images":[{"height":300,"url":"https://scontent-fra5-2.xx.fbcdn.net/v/t1.6435-1/76198297_10220416547829304_3118522203973353472_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=109&ccb=1-7&_nc_sid=79bf43&_nc_ohc=FwkQzKyUX1YQ7kNvwG9K575&_nc_oc=AdmP8Fg4kQIvte3GpYoMoR1E2q6B-01r0phfgoBtGWc-IqanqbouYMq87H0Wf_t7foc1bYjpCMM1gFdDwRKO9rq2&_nc_zt=24&_nc_ht=scontent-fra5-2.xx&edm=AP4hL3IEAAAA&_nc_gid=nS677ppENAHogvFf5ZCexQ&_nc_tpa=Q5bMBQGuYRg2Hi5mM0t36oc-KhEjeVrDhYKqYrMv8IE6ezIkY4-SzfmMwMY03yz8zxqGVf7VNHEc&oh=00_AfmPB5j6ox86lO67sLqTw_-8Gpt4iGopDTOaPSDXiDBSaQ&oe=6967EA14","width":300},{"height":64,"url":"https://scontent-fra5-2.xx.fbcdn.net/v/t1.6435-1/76198297_10220416547829304_3118522203973353472_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=109&ccb=1-7&_nc_sid=28885b&_nc_ohc=FwkQzKyUX1YQ7kNvwG9K575&_nc_oc=AdmP8Fg4kQIvte3GpYoMoR1E2q6B-01r0phfgoBtGWc-IqanqbouYMq87H0Wf_t7foc1bYjpCMM1gFdDwRKO9rq2&_nc_zt=24&_nc_ht=scontent-fra5-2.xx&edm=AP4hL3IEAAAA&_nc_gid=nS677ppENAHogvFf5ZCexQ&_nc_tpa=Q5bMBQGd4EPPdT2wwyTnBK50r_NV8QXSGeMJoVeBlOHsjiWyElmHqhucm08Aqoreqb6mIBPf4IIa&oh=00_Afn96bTyOGymc33bxhhP4WyC47gV9iUARwhiWi2GD0krWA&oe=6967EA14","width":64}],"product":"premium","type":"user","uri":"spotify:user:11125033288"} Dec 16 09:45:17 volumio volumio[1115]: info: Creating Spotify config file Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 09:45:17 volumio volumio[1115]: info: Spotify config file written Dec 16 09:45:17 volumio sudo[4827]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 09:45:17 volumio sudo[4827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 16 09:45:17 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 16 09:45:17 volumio systemd[1]: go-librespot-daemon.service: Killing process 4803 (go-librespot) with signal SIGKILL. Dec 16 09:45:17 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 16 09:45:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 16 09:45:17 volumio volumio[1115]: info: Connection to go-librespot Websocket closed Dec 16 09:45:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 09:45:17 volumio go-librespot[4829]: go-librespot daemon starting... Dec 16 09:45:17 volumio sudo[4827]: pam_unix(sudo:session): session closed for user root Dec 16 09:45:17 volumio volumio[1115]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 16 09:45:17 volumio volumio[1115]: SPOTIFY: BQBc9vFHDv7hycjG75W8b84kxHzDiLXYNzbFKBP0IaN9j2ZbGQC88HyMTnDwA-2VftuuIIP6lUxR6Cm9WwnA_RExCtji32kAWeRHW2pppnIFYRGVuOkj5veZGRmuMwlx8MNSBpcurXV3LKhZsYh-OIT5Fnnn-LgwvyiiwR-i77dSbHb2kQEr3ElPxue26EZpCwGkNL1G92PsxyIhwSPmPpLQgXCBCOtkkL3HsHcryFu6KvtqMRNozsEdsMqASvL0-cRX-BY_2JRHxMkiws9HnXJOtwgt-fz715IsRg Dec 16 09:45:17 volumio volumio[1115]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 16 09:45:17 volumio volumio[1115]: info: New Spotify access token = BQBc9vFHDv7hycjG75W8b84kxHzDiLXYNzbFKBP0IaN9j2ZbGQC88HyMTnDwA-2VftuuIIP6lUxR6Cm9WwnA_RExCtji32kAWeRHW2pppnIFYRGVuOkj5veZGRmuMwlx8MNSBpcurXV3LKhZsYh-OIT5Fnnn-LgwvyiiwR-i77dSbHb2kQEr3ElPxue26EZpCwGkNL1G92PsxyIhwSPmPpLQgXCBCOtkkL3HsHcryFu6KvtqMRNozsEdsMqASvL0-cRX-BY_2JRHxMkiws9HnXJOtwgt-fz715IsRg Dec 16 09:45:17 volumio volumio[1115]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 16 09:45:17 volumio go-librespot[4830]: time="2025-12-16T09:45:17+01:00" level=info msg="running go-librespot 0.4.0" Dec 16 09:45:17 volumio go-librespot[4830]: time="2025-12-16T09:45:17+01:00" level=debug msg="app state loaded" Dec 16 09:45:17 volumio go-librespot[4830]: time="2025-12-16T09:45:17+01:00" level=debug msg="stored credentials not found" Dec 16 09:45:17 volumio go-librespot[4830]: time="2025-12-16T09:45:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 09:45:17 volumio volumio[1115]: SPOTIFY: User informations: {"country":"CZ","display_name":"Vojta Talášek","email":"vojtech.talasek@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11125033288"},"followers":{"href":null,"total":16},"href":"https://api.spotify.com/v1/users/11125033288","id":"11125033288","images":[{"height":300,"url":"https://scontent-fra5-2.xx.fbcdn.net/v/t1.6435-1/76198297_10220416547829304_3118522203973353472_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=109&ccb=1-7&_nc_sid=79bf43&_nc_ohc=FwkQzKyUX1YQ7kNvwG9K575&_nc_oc=AdmP8Fg4kQIvte3GpYoMoR1E2q6B-01r0phfgoBtGWc-IqanqbouYMq87H0Wf_t7foc1bYjpCMM1gFdDwRKO9rq2&_nc_zt=24&_nc_ht=scontent-fra5-2.xx&edm=AP4hL3IEAAAA&_nc_gid=nS677ppENAHogvFf5ZCexQ&_nc_tpa=Q5bMBQGuYRg2Hi5mM0t36oc-KhEjeVrDhYKqYrMv8IE6ezIkY4-SzfmMwMY03yz8zxqGVf7VNHEc&oh=00_AfmPB5j6ox86lO67sLqTw_-8Gpt4iGopDTOaPSDXiDBSaQ&oe=6967EA14","width":300},{"height":64,"url":"https://scontent-fra5-2.xx.fbcdn.net/v/t1.6435-1/76198297_10220416547829304_3118522203973353472_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=109&ccb=1-7&_nc_sid=28885b&_nc_ohc=FwkQzKyUX1YQ7kNvwG9K575&_nc_oc=AdmP8Fg4kQIvte3GpYoMoR1E2q6B-01r0phfgoBtGWc-IqanqbouYMq87H0Wf_t7foc1bYjpCMM1gFdDwRKO9rq2&_nc_zt=24&_nc_ht=scontent-fra5-2.xx&edm=AP4hL3IEAAAA&_nc_gid=nS677ppENAHogvFf5ZCexQ&_nc_tpa=Q5bMBQGd4EPPdT2wwyTnBK50r_NV8QXSGeMJoVeBlOHsjiWyElmHqhucm08Aqoreqb6mIBPf4IIa&oh=00_Afn96bTyOGymc33bxhhP4WyC47gV9iUARwhiWi2GD0krWA&oe=6967EA14","width":64}],"product":"premium","type":"user","uri":"spotify:user:11125033288"} Dec 16 09:45:17 volumio volumio[1115]: info: Spotify Successfully logged in Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 16 09:45:17 volumio volumio[1115]: info: [1765874717787] CoreMusicLibrary::Adding element Spotify Dec 16 09:45:17 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 16 09:45:17 volumio volumio[1115]: Cannot find translation for source Spotify Dec 16 09:45:17 volumio go-librespot[4830]: time="2025-12-16T09:45:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 16 09:45:17 volumio go-librespot[4830]: time="2025-12-16T09:45:17+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 16 09:45:17 volumio go-librespot[4830]: time="2025-12-16T09:45:17+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 16 09:45:17 volumio go-librespot[4830]: time="2025-12-16T09:45:17+01:00" level=info msg="zeroconf server listening on port 39361" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="obtained new client token: AADbkKJzhjVvBN4eJVOBw2xYCCLjjOoCRTGQbdjL3mD3pWS8RjtYGTn+1IdTWq7bS91HqebLhZNsIrhH/RiUb5Y3nZMpOMnJYVEy6YeW7Yg5jWf1zZbVjzOMObzIGzBS/OCNcSGN+Vx4/5tvb0S6bJimqxD+ejxLErsLZrgOmaBrfpSQomXwsYjMEj04k1ITXS0IjMbsL+OVK1+mQCvTpzamXtJ6NIgsizI5tGEhJVnBfIvPgKKSweqZ" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="completed keyexchange" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="completed challenge" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=info msg="authenticated AP" username="11*******88" Dec 16 09:45:18 volumio volumio[1115]: info: Getting Spotify volume Dec 16 09:45:18 volumio volumio[1115]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=info msg="authenticated Login5" username="11*******88" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="stored credentials" username="11*******88" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="initializing zeroconf session" username="11*******88" Dec 16 09:45:18 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:45:18 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:45:18 volumio volumio[1115]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 16 09:45:18 volumio volumio[1115]: SPOTIFY: SPOTIFY VOLUME undefined Dec 16 09:45:18 volumio volumio[1115]: SPOTIFY: VOLUMIO VOLUME 86 Dec 16 09:45:18 volumio volumio[1115]: info: Aligning Spotify Volume to Volumio Volume Dec 16 09:45:18 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:45:18 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:45:18 volumio volumio[1115]: info: Setting Spotify Volume from Volumio: 86 Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="dealer connection opened" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=trace msg="starting accesspoint recv loop" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=trace msg="starting dealer recv loop" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=trace msg="received accesspoint ping" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 16 09:45:18 volumio volumio[1115]: info: Spotify volume: 100 Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="received connection id: ZTg3Yzg3MzYtYjE1...QkJGMjIzMTEzNQ==" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=trace msg="received accesspoint pong ack" Dec 16 09:45:18 volumio go-librespot[4830]: time="2025-12-16T09:45:18+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 16 09:45:18 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 09:45:19 volumio volumio[1115]: info: Received Get System Info Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:45:19 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:45:19 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 09:45:19 volumio volumio[1115]: info: Received Get System Info Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 16 09:45:19 volumio volumio[1115]: info: Discovery: Getting this device information Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:45:19 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:45:19 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 16 09:45:19 volumio volumio[1115]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Dec 16 09:45:19 volumio volumio[1115]: info: Sending Spotify command with payload to local API: /player/volume Dec 16 09:45:19 volumio go-librespot[4830]: time="2025-12-16T09:45:19+01:00" level=debug msg="update volume requested to 56360/65535" Dec 16 09:45:20 volumio go-librespot[4830]: time="2025-12-16T09:45:20+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 16 09:45:20 volumio go-librespot[4830]: time="2025-12-16T09:45:20+01:00" level=trace msg="emitting websocket event: volume" Dec 16 09:45:20 volumio volumio[1115]: info: Initializing connection to go-librespot Websocket Dec 16 09:45:20 volumio go-librespot[4830]: time="2025-12-16T09:45:20+01:00" level=debug msg="new websocket client" Dec 16 09:45:20 volumio volumio[1115]: info: Connection to go-librespot Websocket established Dec 16 09:45:20 volumio volumio[1115]: info: go-librespot daemon successfully initialized Dec 16 09:45:23 volumio volumio[1115]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 16 09:45:23 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 16 09:45:23 volumio volumio[1115]: info: Creating Spotify config file Dec 16 09:45:23 volumio volumio[1115]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 09:45:23 volumio volumio[1115]: info: Spotify config file written Dec 16 09:45:23 volumio sudo[4852]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 09:45:23 volumio sudo[4852]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 09:45:23 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 16 09:45:23 volumio systemd[1]: go-librespot-daemon.service: Killing process 4836 (go-librespot) with signal SIGKILL. Dec 16 09:45:23 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 16 09:45:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 16 09:45:23 volumio volumio[1115]: info: Connection to go-librespot Websocket closed Dec 16 09:45:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 09:45:23 volumio go-librespot[4854]: go-librespot daemon starting... Dec 16 09:45:23 volumio sudo[4852]: pam_unix(sudo:session): session closed for user root Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=info msg="running go-librespot 0.4.0" Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=debug msg="app state loaded" Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=info msg="zeroconf server listening on port 43711" Dec 16 09:45:23 volumio volumio[1115]: info: Getting Spotify volume Dec 16 09:45:23 volumio volumio[1115]: 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 16 09:45:23 volumio volumio[1115]: info: CoreCommandRouter::volumioGetState Dec 16 09:45:23 volumio volumio[1115]: info: CorePlayQueue::getTrack 0 Dec 16 09:45:23 volumio volumio[1115]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 16 09:45:23 volumio volumio[1115]: SPOTIFY: SPOTIFY VOLUME 100 Dec 16 09:45:23 volumio volumio[1115]: SPOTIFY: VOLUMIO VOLUME 86 Dec 16 09:45:23 volumio volumio[1115]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 16 09:45:23 volumio volumio[1115]: info: Setting Spotify Volume from Volumio: 86 Dec 16 09:45:23 volumio volumio[1115]: info: Initializing connection to go-librespot Websocket Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=debug msg="obtained new client token: AADGq5Qj1lGJcOjm0QsNNwl+Vp1EwWqVDOnOlP4A0IbyrFx60JR231bOEUYQx2XAfA3kTH51jbj3z/8O7iCtsZy4+t/bp4VxWxYnMQC1sKMEH74c4kttFIr+h4+7zJs1bVsmDPXUZeyJjUAoX5LJ2wFqauiaB4VPApuuF5w/e+58l0lGvfx5z2G6AkPsxiJLRKdfsxPzap/hL6+T0l7rYtx/6CsdFDA00IJvAk0RiOT7Kqea9zvMgsfxA04=" Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=debug msg="new websocket client" Dec 16 09:45:23 volumio volumio[1115]: info: Connection to go-librespot Websocket established Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 16 09:45:23 volumio go-librespot[4855]: time="2025-12-16T09:45:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 16 09:45:23 volumio volumio[1115]: info: Connection to go-librespot Websocket closed Dec 16 09:45:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 16 09:45:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 16 09:45:23 volumio volumio[1115]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 16 09:45:23 volumio volumio[1115]: Error: socket hang up Dec 16 09:45:23 volumio volumio[1115]: at connResetException (node:internal/errors:720:14) Dec 16 09:45:23 volumio volumio[1115]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 16 09:45:23 volumio volumio[1115]: at Socket.emit (node:events:526:35) Dec 16 09:45:23 volumio volumio[1115]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 16 09:45:23 volumio volumio[1115]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 16 09:45:23 volumio volumio[1115]: code: 'ECONNRESET', Dec 16 09:45:23 volumio volumio[1115]: response: undefined Dec 16 09:45:23 volumio volumio[1115]: } Dec 16 09:45:23 volumio volumio[1115]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 16 09:45:24 volumio sudo[4877]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-16 09:44' Dec 16 09:45:24 volumio sudo[4877]: 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="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"