Sep 16 19:20:17 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 16 19:20:17 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 16 19:20:17 volumio volumio[1278]: info: Discovery: Getting this device information Sep 16 19:20:17 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:20:17 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:20:17 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 16 19:20:37 volumio volumio[1278]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 16 19:20:40 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 16 19:20:40 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Sep 16 19:20:42 volumio volumio[1278]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 16 19:20:47 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 16 19:20:47 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 16 19:20:47 volumio volumio[1278]: info: Discovery: Getting this device information Sep 16 19:20:47 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:20:47 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:20:47 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 16 19:20:56 volumio volumio[1278]: info: Received OAUTH Data Sep 16 19:20:56 volumio volumio[1278]: info: Executing Spotify Oauth Login Sep 16 19:20:56 volumio volumio[1278]: info: Saving Spotify Refresh Token Sep 16 19:20:56 volumio volumio[1278]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 16 19:20:56 volumio volumio[1278]: SPOTIFY: BQD0Iwr5JcdDD8rTqrhSTo_eu_NGhDXXLEoBp1vSWzhz3b2r5Qrbp-nUbWv6PEnjTC1raKbh5uZxZaA5LJRnMYFDJhfhmg0Ra49agYJhoL0z5_tfrbNqRRLKqd1rDrig5Zx_el2Co3PbDcB6Dl9F26ZfKAmYCnxfUYcNipxxAapYju7sUcxm_JP-MVfwIsw9YAmN55QSvRFd3lKEDmxoI49nMIgIwy8A32cVA2LVJz7mzE-4YZoJkTbaWftraz3bR25GQY6ZH6kPc33KkTuLtdp9i63rw42I Sep 16 19:20:56 volumio volumio[1278]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 16 19:20:56 volumio volumio[1278]: info: New Spotify access token = BQD0Iwr5JcdDD8rTqrhSTo_eu_NGhDXXLEoBp1vSWzhz3b2r5Qrbp-nUbWv6PEnjTC1raKbh5uZxZaA5LJRnMYFDJhfhmg0Ra49agYJhoL0z5_tfrbNqRRLKqd1rDrig5Zx_el2Co3PbDcB6Dl9F26ZfKAmYCnxfUYcNipxxAapYju7sUcxm_JP-MVfwIsw9YAmN55QSvRFd3lKEDmxoI49nMIgIwy8A32cVA2LVJz7mzE-4YZoJkTbaWftraz3bR25GQY6ZH6kPc33KkTuLtdp9i63rw42I Sep 16 19:20:56 volumio volumio[1278]: info: Spotify credentials grant success - running version from March 24, 2019 Sep 16 19:20:57 volumio sudo[4639]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 16 19:20:57 volumio sudo[4639]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:20:57 volumio sudo[4641]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 16 19:20:57 volumio sudo[4639]: pam_unix(sudo:session): session closed for user root Sep 16 19:20:57 volumio sudo[4641]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:20:57 volumio volumio[1278]: SPOTIFY: User informations: {"country":"IT","display_name":"Andrea","email":"andreabusso@outlook.it","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/settequattro74"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/settequattro74","id":"settequattro74","images":[],"product":"premium","type":"user","uri":"spotify:user:settequattro74"} Sep 16 19:20:57 volumio volumio[1278]: info: Creating Spotify config file Sep 16 19:20:57 volumio sudo[4641]: pam_unix(sudo:session): session closed for user root Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 16 19:20:57 volumio volumio[1278]: info: Spotify config file written Sep 16 19:20:57 volumio sudo[4646]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 16 19:20:57 volumio sudo[4646]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:20:57 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Sep 16 19:20:57 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 16 19:20:57 volumio volumio[1278]: info: Connection to go-librespot Websocket closed Sep 16 19:20:57 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 16 19:20:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:20:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:20:57 volumio sudo[4646]: pam_unix(sudo:session): session closed for user root Sep 16 19:20:57 volumio go-librespot[4651]: go-librespot daemon starting... Sep 16 19:20:57 volumio dbus-daemon[818]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.50' (uid=0 pid=4649 comm="timedatectl show --property=NTPSynchronized --valu") Sep 16 19:20:57 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Sep 16 19:20:57 volumio volumio[1278]: verbose: New Socket.io Connection to 192.168.100.65 from 192.168.100.53 UA: Mozilla/5.0 (Linux; Android 15; RMX3301 Build/AP3A.240617.008; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/139.0.7258.158 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=info msg="running go-librespot 0.3.2" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="app state loaded" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="stored credentials not found" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 16 19:20:57 volumio volumio[1278]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 16 19:20:57 volumio volumio[1278]: SPOTIFY: BQDGGCg22OxioaM6kS19BjM6T981C5a_3Zya7rpHM7IK97-uOpma6HSU69YC64eMWGcMXRiTpxlsbtyaTCOHimTgFy3zYZMJWFVnu8kgzEluGk7GBnTENghiRbKJH3Z0iVrYQ4mYf7mSHiENEUUkP58GmYlWAclNdynr9J5kMXExrFEkU8SUc9w1b7e99Mf-3ow0j6pu8US-afft7hoOOijZBow0IKQLvQGu7AkzgiN0ZvwdJSxnN_3OLuLJBNNt5O15FTin3d5mkTL8RNZiJy0e3vtakfCx Sep 16 19:20:57 volumio volumio[1278]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 16 19:20:57 volumio volumio[1278]: info: New Spotify access token = BQDGGCg22OxioaM6kS19BjM6T981C5a_3Zya7rpHM7IK97-uOpma6HSU69YC64eMWGcMXRiTpxlsbtyaTCOHimTgFy3zYZMJWFVnu8kgzEluGk7GBnTENghiRbKJH3Z0iVrYQ4mYf7mSHiENEUUkP58GmYlWAclNdynr9J5kMXExrFEkU8SUc9w1b7e99Mf-3ow0j6pu8US-afft7hoOOijZBow0IKQLvQGu7AkzgiN0ZvwdJSxnN_3OLuLJBNNt5O15FTin3d5mkTL8RNZiJy0e3vtakfCx Sep 16 19:20:57 volumio volumio[1278]: info: Spotify credentials grant success - running version from March 24, 2019 Sep 16 19:20:57 volumio volumio[1278]: SPOTIFY: User informations: {"country":"IT","display_name":"Andrea","email":"andreabusso@outlook.it","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/settequattro74"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/settequattro74","id":"settequattro74","images":[],"product":"premium","type":"user","uri":"spotify:user:settequattro74"} Sep 16 19:20:57 volumio volumio[1278]: info: Spotify Successfully logged in Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 16 19:20:57 volumio volumio[1278]: info: [1758043257493] CoreMusicLibrary::Adding element Spotify Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 16 19:20:57 volumio volumio[1278]: Cannot find translation for source Spotify Sep 16 19:20:57 volumio dbus-daemon[818]: [system] Successfully activated service 'org.freedesktop.timedate1' Sep 16 19:20:57 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Sep 16 19:20:57 volumio setdatetime-helper.sh[4648]: Time is not synchronized. Attempting to sync... Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02: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-gew1.spotify.com:80]" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=info msg="zeroconf server listening on port 42765" Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::volumioGetVisibleSources Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:20:57 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 16 19:20:57 volumio volumio[1278]: info: Received Get System Info Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 16 19:20:57 volumio volumio[1278]: info: Discovery: Getting this device information Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:20:57 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:20:57 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:20:57 volumio volumio[1278]: info: Listing playlists Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="obtained new client token: AAApcf04pnFeCZqm7gruAV0mKvj6Mv2bO1YOgxmA3JuOFBTNoVT+YlyWoAT1ZFJwBsJURRiaZiia6v6m8jjiF2wTpzRNSIj3rVgBW/D/ni46yvO3Un0FO0+y2DenLuae23B4u6X5zJq+uwXey3OigtlJvpKCwYer+KDjKryLXjktPAvRo+98yuJVQq7h6P3PNIOP0vqaffRVvJzcNwwSnJPZHL8q2MICtdvYWcGgxhiEu8ChWkM070mK" Sep 16 19:20:57 volumio sudo[4669]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Tue, 16 Sep 2025 17:20:57 GMT#015' Sep 16 19:20:57 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 16 19:20:57 volumio sudo[4669]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 16 19:20:57 volumio setdatetime-helper.sh[4670]: Tue Sep 16 19:20:57 CEST 2025 Sep 16 19:20:57 volumio systemd-journald[547]: Time jumped backwards, rotating. Sep 16 19:20:57 volumio setdatetime-helper.sh[4648]: Time synchronized successfully. Sep 16 19:20:57 volumio sudo[4669]: pam_unix(sudo:session): session closed for user root Sep 16 19:20:57 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Sep 16 19:20:57 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="completed keyexchange" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="completed challenge" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=info msg="authenticated AP" username="se**********74" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=info msg="authenticated Login5" username="se**********74" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="stored credentials" username="se**********74" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="initializing zeroconf session" username="se**********74" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="dealer connection opened" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=trace msg="starting accesspoint recv loop" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=trace msg="starting dealer recv loop" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=trace msg="received accesspoint ping" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="received connection id: NGM2NDdlYzEtMmVi...NjA5QTlENTcxMQ==" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=trace msg="received accesspoint pong ack" Sep 16 19:20:57 volumio go-librespot[4652]: time="2025-09-16T19:20:57+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 16 19:20:58 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 16 19:20:58 volumio volumio[1278]: info: Received Get System Info Sep 16 19:20:58 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 16 19:20:58 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 16 19:20:58 volumio volumio[1278]: info: Discovery: Getting this device information Sep 16 19:20:58 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:20:58 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:20:58 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 16 19:20:58 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Sep 16 19:20:59 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 16 19:20:59 volumio volumio[1278]: info: Received Get System Info Sep 16 19:20:59 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 16 19:20:59 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 16 19:20:59 volumio volumio[1278]: info: Discovery: Getting this device information Sep 16 19:20:59 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:20:59 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:20:59 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 16 19:20:59 volumio volumio[1278]: info: Initializing connection to go-librespot Websocket Sep 16 19:20:59 volumio go-librespot[4652]: time="2025-09-16T19:20:59+02:00" level=debug msg="new websocket client" Sep 16 19:20:59 volumio volumio[1278]: info: Connection to go-librespot Websocket established Sep 16 19:20:59 volumio volumio[1278]: info: go-librespot daemon successfully initialized Sep 16 19:21:02 volumio volumio[1278]: info: Getting Spotify volume Sep 16 19:21:02 volumio volumio[1278]: info: Initializing connection to go-librespot Websocket Sep 16 19:21:02 volumio volumio[1278]: info: Spotify volume: 100 Sep 16 19:21:02 volumio volumio[1278]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Sep 16 19:21:02 volumio go-librespot[4652]: time="2025-09-16T19:21:02+02:00" level=debug msg="new websocket client" Sep 16 19:21:02 volumio volumio[1278]: info: Connection to go-librespot Websocket established Sep 16 19:21:02 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:21:02 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:21:02 volumio volumio[1278]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 16 19:21:05 volumio volumio[1278]: info: Getting Spotify volume Sep 16 19:21:05 volumio volumio[1278]: info: Spotify volume: 100 Sep 16 19:21:05 volumio volumio[1278]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Sep 16 19:21:05 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:21:05 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:21:05 volumio volumio[1278]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 16 19:21:06 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Sep 16 19:21:08 volumio volumio[1278]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Sep 16 19:21:08 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Sep 16 19:21:08 volumio volumio[1278]: info: Creating Spotify config file Sep 16 19:21:08 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 16 19:21:08 volumio volumio[1278]: info: Spotify config file written Sep 16 19:21:08 volumio sudo[4699]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 16 19:21:08 volumio sudo[4699]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:21:08 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 16 19:21:08 volumio systemd[1]: go-librespot-daemon.service: Killing process 4661 (go-librespot) with signal SIGKILL. Sep 16 19:21:08 volumio volumio[1278]: info: Connection to go-librespot Websocket closed Sep 16 19:21:08 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 16 19:21:08 volumio volumio[1278]: info: Connection to go-librespot Websocket closed Sep 16 19:21:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:08 volumio go-librespot[4701]: go-librespot daemon starting... Sep 16 19:21:08 volumio sudo[4699]: pam_unix(sudo:session): session closed for user root Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=info msg="running go-librespot 0.3.2" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="app state loaded" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02: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]" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02: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]" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02: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]" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=info msg="zeroconf server listening on port 43443" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="obtained new client token: AAB/r68KbO8HppvjqSPkjhGWH8GQf+EI13ZOKWA0j3MGJAb9D2bt4SKYFHDgeqXekB1rrhJd6V3wqkwG6XIiank13VuDhS0xsBzY+hvhAWeW36WOM0/xIOnt4waT53fSX7j3lTAZt5/BFjFf/0vX2GjtLYTPbe6pR5nfF/wF/TmIhf5QkGAHyiExr4eUcPFVejjPU9WQpBuNeiYm1lTzT49T4pxJDPbf1vOLj87doWQwBP2O7D9A9g==" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="completed keyexchange" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="completed challenge" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=info msg="authenticated AP" username="se**********74" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=info msg="authenticated Login5" username="se**********74" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="initializing zeroconf session" username="se**********74" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="dealer connection opened" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=trace msg="starting accesspoint recv loop" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=trace msg="starting dealer recv loop" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=trace msg="received accesspoint ping" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="received connection id: NTM0NTM5MzYtNWQ1...QUIyNTlBRDhGMA==" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=trace msg="received accesspoint pong ack" Sep 16 19:21:08 volumio go-librespot[4702]: time="2025-09-16T19:21:08+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 16 19:21:10 volumio volumio[1278]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Sep 16 19:21:10 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Sep 16 19:21:10 volumio volumio[1278]: info: Creating Spotify config file Sep 16 19:21:10 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 16 19:21:10 volumio volumio[1278]: info: Spotify config file written Sep 16 19:21:10 volumio sudo[4728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 16 19:21:10 volumio sudo[4728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:21:10 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 16 19:21:10 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 16 19:21:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:10 volumio go-librespot[4731]: go-librespot daemon starting... Sep 16 19:21:10 volumio sudo[4728]: pam_unix(sudo:session): session closed for user root Sep 16 19:21:10 volumio go-librespot[4733]: time="2025-09-16T19:21:10+02:00" level=info msg="running go-librespot 0.3.2" Sep 16 19:21:10 volumio go-librespot[4733]: time="2025-09-16T19:21:10+02:00" level=debug msg="app state loaded" Sep 16 19:21:10 volumio go-librespot[4733]: time="2025-09-16T19:21:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 16 19:21:10 volumio go-librespot[4733]: time="2025-09-16T19:21:10+02: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]" Sep 16 19:21:10 volumio go-librespot[4733]: time="2025-09-16T19:21:10+02: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]" Sep 16 19:21:10 volumio go-librespot[4733]: time="2025-09-16T19:21:10+02: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]" Sep 16 19:21:10 volumio go-librespot[4733]: time="2025-09-16T19:21:10+02:00" level=info msg="zeroconf server listening on port 34227" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="obtained new client token: AAB1evtJxVjIJAFP6rkE4cRvmlh9t6MxhaOXfx2aE/zPGgyPQU0ErS8Rf4dmZ2uhLy8cH0ThF1I54KaLoOXtpNi0p50FfbjEYAaMmuVpebB+CtddLMVY5EeFhJF1ItIRmfug6L+xQ98BjgelYX64m1FaFh1bNNoQv6yb4GwXk20+rricTl8Eu8Ikb/SqSlxUv5aI+Ss7tp3UCkmmT1GPIa5DxmZ6yrlzmfdWW8Ewxtue1N4EahKKpvJq" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="completed keyexchange" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="completed challenge" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=info msg="authenticated AP" username="se**********74" Sep 16 19:21:11 volumio volumio[1278]: info: Initializing connection to go-librespot Websocket Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="new websocket client" Sep 16 19:21:11 volumio volumio[1278]: info: Connection to go-librespot Websocket established Sep 16 19:21:11 volumio volumio[1278]: info: go-librespot daemon successfully initialized Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=info msg="authenticated Login5" username="se**********74" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="initializing zeroconf session" username="se**********74" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="dealer connection opened" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=trace msg="starting accesspoint recv loop" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=trace msg="starting dealer recv loop" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=trace msg="received accesspoint ping" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="received connection id: Y2IwYzNiYzUtODM5...NzlCRkU5NkE2NQ==" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=trace msg="received accesspoint pong ack" Sep 16 19:21:11 volumio go-librespot[4733]: time="2025-09-16T19:21:11+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 16 19:21:13 volumio volumio[1278]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Sep 16 19:21:13 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Sep 16 19:21:13 volumio volumio[1278]: info: Creating Spotify config file Sep 16 19:21:13 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 16 19:21:13 volumio volumio[1278]: info: Spotify config file written Sep 16 19:21:13 volumio sudo[4748]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 16 19:21:13 volumio sudo[4748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:21:13 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 16 19:21:13 volumio volumio[1278]: info: Connection to go-librespot Websocket closed Sep 16 19:21:13 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 16 19:21:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:13 volumio go-librespot[4750]: go-librespot daemon starting... Sep 16 19:21:13 volumio sudo[4748]: pam_unix(sudo:session): session closed for user root Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=info msg="running go-librespot 0.3.2" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=debug msg="app state loaded" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=info msg="zeroconf server listening on port 34315" Sep 16 19:21:13 volumio volumio[1278]: info: go-librespot daemon successfully initialized Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=debug msg="obtained new client token: AABpZlv4yifjywFsT9UyYJD/jjSq1DtLqJIbY0Q9RzLQBo3TXXtn5CVzs2+1Ht8Mm5mVnKnG9LIbPm7CPA87BdA7rI8uwQA70LQoxl5g+NghrfbqWREXVSFc2rxDeIA124CAsvuVBx9gCNe3tqVFDdUJlT/xUHMh+0YTnq+quEXzJwKsDIfRgBqXd8omw+xeRVg5ESYXhUOpIoqM3URkcEM4/Lza53Lu9QyN0R1m7T3FyoE2rnr4wDMN" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=debug msg="completed keyexchange" Sep 16 19:21:13 volumio go-librespot[4751]: time="2025-09-16T19:21:13+02:00" level=debug msg="completed challenge" Sep 16 19:21:14 volumio go-librespot[4751]: time="2025-09-16T19:21:14+02:00" level=info msg="authenticated AP" username="se**********74" Sep 16 19:21:14 volumio volumio[1278]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Sep 16 19:21:14 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Sep 16 19:21:14 volumio volumio[1278]: info: Creating Spotify config file Sep 16 19:21:14 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 16 19:21:14 volumio volumio[1278]: info: Spotify config file written Sep 16 19:21:14 volumio sudo[4761]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 16 19:21:14 volumio sudo[4761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:21:14 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 16 19:21:14 volumio systemd[1]: go-librespot-daemon.service: Killing process 4753 (go-librespot) with signal SIGKILL. Sep 16 19:21:14 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 16 19:21:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:14 volumio go-librespot[4763]: go-librespot daemon starting... Sep 16 19:21:14 volumio sudo[4761]: pam_unix(sudo:session): session closed for user root Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02:00" level=info msg="running go-librespot 0.3.2" Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02:00" level=debug msg="app state loaded" Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 16 19:21:14 volumio volumio[1278]: info: Getting Spotify volume Sep 16 19:21:14 volumio volumio[1278]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02: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]" Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02: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]" Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02: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]" Sep 16 19:21:14 volumio volumio[1278]: info: Initializing connection to go-librespot Websocket Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02:00" level=info msg="zeroconf server listening on port 41595" Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02:00" level=debug msg="new websocket client" Sep 16 19:21:14 volumio volumio[1278]: info: CoreCommandRouter::volumioGetState Sep 16 19:21:14 volumio volumio[1278]: info: CorePlayQueue::getTrack 0 Sep 16 19:21:14 volumio volumio[1278]: info: Connection to go-librespot Websocket established Sep 16 19:21:14 volumio volumio[1278]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 16 19:21:14 volumio volumio[1278]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Sep 16 19:21:14 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Sep 16 19:21:14 volumio volumio[1278]: info: Creating Spotify config file Sep 16 19:21:14 volumio volumio[1278]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 16 19:21:14 volumio volumio[1278]: info: Spotify config file written Sep 16 19:21:14 volumio sudo[4773]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 16 19:21:14 volumio sudo[4773]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:21:14 volumio go-librespot[4764]: time="2025-09-16T19:21:14+02:00" level=debug msg="obtained new client token: AAB4cyv+zLe/UKZTEhWHTbu+6OSnPr8fTmhKXPsStsIu1eRbzcSf0yER+mbZePzvrvdD+sqMjenGEhUOdBqr+4MKfEwlNIBVlPEuOkL7JTuRzvRIagbHbXllQjGCoMfY10AJpKwesTMveOe7E0jDz2XC/WYb8MAzK/OpjSwKPTDQA2ExagEpJsl59lGzWh6NgLffNgU+gWgqHT3gVuDNyuFP/2635chnyloIzllOzkJV0I7J+hnjfQ==" Sep 16 19:21:14 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 16 19:21:14 volumio systemd[1]: go-librespot-daemon.service: Killing process 4769 (go-librespot) with signal SIGKILL. Sep 16 19:21:14 volumio volumio[1278]: info: Connection to go-librespot Websocket closed Sep 16 19:21:14 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 16 19:21:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:14 volumio volumio[1278]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 16 19:21:14 volumio volumio[1278]: Error: socket hang up Sep 16 19:21:14 volumio volumio[1278]: at connResetException (node:internal/errors:720:14) Sep 16 19:21:14 volumio volumio[1278]: at Socket.socketOnEnd (node:_http_client:519:23) Sep 16 19:21:14 volumio volumio[1278]: at Socket.emit (node:events:526:35) Sep 16 19:21:14 volumio volumio[1278]: at endReadableNT (node:internal/streams/readable:1376:12) Sep 16 19:21:14 volumio volumio[1278]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Sep 16 19:21:14 volumio volumio[1278]: code: 'ECONNRESET', Sep 16 19:21:14 volumio volumio[1278]: response: undefined Sep 16 19:21:14 volumio volumio[1278]: } Sep 16 19:21:14 volumio volumio[1278]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 16 19:21:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 16 19:21:14 volumio go-librespot[4775]: go-librespot daemon starting... Sep 16 19:21:14 volumio sudo[4773]: pam_unix(sudo:session): session closed for user root Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=info msg="running go-librespot 0.3.2" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="app state loaded" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02: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]" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02: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]" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02: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]" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=info msg="zeroconf server listening on port 44561" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="obtained new client token: AABT61Nv1/fllhIoihrQQR7Lvgztfwk/nwzP4g/VGvT8CdBUmVhxRqbL2aZ2ubDVXjU/l4f+7jMNH/ZdD/Z2hO4SsheEM6uOuGIVWNtYe8e5lydZ+i9Am/HFmIJKa5ovMFm7wgJNsKu33ZOKPa81T11UzKyNKfZ23tU8zN2ebaQj/Edkf7pgt1ly05u5aCY6vRfp9WVViCtQx9cz4A5MmvsxvsThcvctveG5eYYRHj8UcixeyXYR3m03" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="completed keyexchange" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="completed challenge" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=info msg="authenticated AP" username="se**********74" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=info msg="authenticated Login5" username="se**********74" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="initializing zeroconf session" username="se**********74" Sep 16 19:21:14 volumio sudo[4799]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-09-16 19:20' Sep 16 19:21:14 volumio sudo[4799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="dealer connection opened" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=trace msg="starting accesspoint recv loop" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=trace msg="starting dealer recv loop" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=trace msg="received accesspoint ping" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 16 19:21:14 volumio go-librespot[4778]: time="2025-09-16T19:21:14+02:00" level=debug msg="received connection id: YjkzZTYwMDAtYTE1...MkNENkM1NjFFMA==" PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="dfc7bb04e09bf2260691765a2340814af1fa2971" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="30d63a8c53d2826bd7f262e22b4e4511a4cc9d01" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Aug 30 07:07:32 UTC 2025" VOLUMIO_VERSION="4.022" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="9a5a1566f5c8d470330ec8a877815bcf"