-- Logs begin at Sun 2025-06-22 10:33:41 CEST, end at Sun 2025-06-22 10:41:16 CEST. -- Jun 22 10:40:00 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:00 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:02 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:02 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 61. Jun 22 10:40:02 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:02 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:02 volumio-egreat go-librespot[4770]: go-librespot daemon starting... Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=debug msg="app state loaded" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+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]" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+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]" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+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]" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=info msg="zeroconf server listening on port 33171" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=debug msg="obtained new client token: AABpciH+awt7iR5BFNbnyAEOtEqB8AVgXFTMt/Q+gj8Om3d6DSxb59wBDrHyLdyv5GrI6EuLFfdWMW8IF56kq+Wr/PofyZNYJlMrTXWx++afyjSe14mKT7NjMvCP+h0pgsWi8tPyHxefuUqxtZ8SJsS5xXEwsaS2VD3DOnslEJWX9zC2Y6was9YcKhwS/50nysu2l3/V+EjdLGjPNedFcGAzBHIr546rD+QXUFIrmMI+FN2DB9UKVnTh" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=debug msg="completed challenge" Jun 22 10:40:02 volumio-egreat go-librespot[4770]: time="2025-06-22T10:40:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:02 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:02 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:03 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 22 10:40:03 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:03 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:04 volumio-egreat volumio[2926]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/fusiondsp/volumio/buster/amd64 Jun 22 10:40:06 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:06 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 62. Jun 22 10:40:06 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:06 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:06 volumio-egreat go-librespot[4781]: go-librespot daemon starting... Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+02:00" level=debug msg="app state loaded" Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:06 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+02:00" level=debug msg="new websocket client" Jun 22 10:40:06 volumio-egreat volumio[2926]: info: Connection to go-librespot Websocket established Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+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]" Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+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]" Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+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]" Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+02:00" level=info msg="zeroconf server listening on port 41207" Jun 22 10:40:06 volumio-egreat volumio[2926]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/fusiondsp/volumio/buster/amd64 Jun 22 10:40:06 volumio-egreat volumio[2926]: info: FusionDsp - Stopping FusionDsp service Jun 22 10:40:06 volumio-egreat volumio[2926]: info: camilladsp stopping service pid 3611... Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+02:00" level=debug msg="obtained new client token: AACPmXsFaJM8mUFPSOoTrvgj+SFzKtkSUSY+0pRdRgWPYBMTIMPQvbWI+tHUtm8kAQjg4jrDF6nU3dcSsJO2n+BubRM+jTl7e7zDzCUzHD4rdPYcvrxf7v2WZBuI7OXr6BSqVLpNt+i1dFbkM4B/8F2U1ljMZr1Zh5Zu5neGCbHnDrmgFDfWfsD5G0bn+FpfBFA2Zse2pGKXNkW9ns/SCaaKwk7nan7HlKPS9HKguGEZYYs26GrzRaEl" Jun 22 10:40:06 volumio-egreat volumio[2926]: info: camilladsp service terminated, instance 1 Jun 22 10:40:06 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:06+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Jun 22 10:40:07 volumio-egreat sudo[4792]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop fusiondsp.service Jun 22 10:40:07 volumio-egreat sudo[4792]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:07 volumio-egreat systemd[1]: Stopping FusionDsp Daemon... Jun 22 10:40:07 volumio-egreat volumio[1949]: Backend configuration: Jun 22 10:40:07 volumio-egreat volumio[1949]: active_config: /data/configuration/audio_interface/fusiondsp/camilladsp.yml Jun 22 10:40:07 volumio-egreat volumio[1949]: active_config_txt: null Jun 22 10:40:07 volumio-egreat volumio[1949]: camilla_host: 127.0.0.1 Jun 22 10:40:07 volumio-egreat volumio[1949]: camilla_port: 9876 Jun 22 10:40:07 volumio-egreat volumio[1949]: coeff_dir: /data/INTERNAL/FusionDsp/filters Jun 22 10:40:07 volumio-egreat volumio[1949]: config_dir: /data/configuration/audio_interface/fusiondsp Jun 22 10:40:07 volumio-egreat volumio[1949]: default_config: /data/configuration/audio_interface/fusiondsp/camilladsp.yml Jun 22 10:40:07 volumio-egreat volumio[1949]: log_file: /tmp/camilladsp.log Jun 22 10:40:07 volumio-egreat volumio[1949]: on_get_active_config: null Jun 22 10:40:07 volumio-egreat volumio[1949]: on_set_active_config: null Jun 22 10:40:07 volumio-egreat volumio[1949]: port: 5011 Jun 22 10:40:07 volumio-egreat volumio[1949]: supported_capture_types: null Jun 22 10:40:07 volumio-egreat volumio[1949]: supported_playback_types: null Jun 22 10:40:07 volumio-egreat volumio[1949]: update_config_symlink: false Jun 22 10:40:07 volumio-egreat volumio[1949]: update_config_txt: false Jun 22 10:40:07 volumio-egreat volumio[1949]: ======== Running on http://0.0.0.0:5011 ======== Jun 22 10:40:07 volumio-egreat volumio[1949]: (Press CTRL+C to quit) Jun 22 10:40:07 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:07+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Jun 22 10:40:07 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:07+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:07 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:07+02:00" level=debug msg="completed challenge" Jun 22 10:40:07 volumio-egreat go-librespot[4781]: time="2025-06-22T10:40:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:07 volumio-egreat volumio[2926]: info: Connection to go-librespot Websocket closed Jun 22 10:40:07 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:07 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:07 volumio-egreat systemd[1]: fusiondsp.service: Succeeded. Jun 22 10:40:07 volumio-egreat systemd[1]: Stopped FusionDsp Daemon. Jun 22 10:40:07 volumio-egreat sudo[4792]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:07 volumio-egreat volumio[2926]: info: FusionDsp - Reporting Fusion DSP Disabled Jun 22 10:40:07 volumio-egreat volumio[2926]: info: Removing fusiondspeq DSP Signal Path Element Jun 22 10:40:07 volumio-egreat volumio[2926]: info: Check plugin dependencies Jun 22 10:40:07 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 22 10:40:07 volumio-egreat volumio[2926]: info: Rename folder Jun 22 10:40:07 volumio-egreat volumio[2926]: info: Folder /tmp/downloaded_plugin.zip removed Jun 22 10:40:07 volumio-egreat volumio[2926]: info: Move to category Jun 22 10:40:07 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-DISCONNECTED bssid=08:bf:b8:8e:9b:ac reason=0 locally_generated=1 Jun 22 10:40:07 volumio-egreat dhcpcd[1057]: wlan0: carrier lost Jun 22 10:40:07 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Jun 22 10:40:07 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=PL Jun 22 10:40:08 volumio-egreat avahi-daemon[829]: Withdrawing address record for 192.168.2.138 on wlan0. Jun 22 10:40:08 volumio-egreat avahi-daemon[829]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.138. Jun 22 10:40:08 volumio-egreat avahi-daemon[829]: Interface wlan0.IPv4 no longer relevant for mDNS. Jun 22 10:40:08 volumio-egreat wpa_supplicant[1135]: wlan0: Trying to associate with 08:bf:b8:8e:9b:ac (SSID='RBS-24' freq=2457 MHz) Jun 22 10:40:08 volumio-egreat dhcpcd[1057]: wlan0: deleting route to 192.168.2.0/24 Jun 22 10:40:08 volumio-egreat dhcpcd[1057]: wlan0: deleting default route via 192.168.2.1 Jun 22 10:40:08 volumio-egreat wpa_supplicant[1135]: wlan0: Associated with 08:bf:b8:8e:9b:ac Jun 22 10:40:08 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jun 22 10:40:08 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Jun 22 10:40:08 volumio-egreat wpa_supplicant[1135]: wlan0: WPA: Key negotiation completed with 08:bf:b8:8e:9b:ac [PTK=CCMP GTK=CCMP] Jun 22 10:40:08 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-CONNECTED - Connection to 08:bf:b8:8e:9b:ac completed [id=0 id_str=] Jun 22 10:40:08 volumio-egreat dhcpcd[1057]: wlan0: carrier acquired Jun 22 10:40:08 volumio-egreat dhcpcd[1057]: wlan0: IAID 09:01:29:36 Jun 22 10:40:08 volumio-egreat dhcpcd[1057]: wlan0: soliciting an IPv6 router Jun 22 10:40:08 volumio-egreat dhcpcd[1057]: wlan0: rebinding lease of 192.168.2.138 Jun 22 10:40:08 volumio-egreat dhcpcd[1057]: wlan0: probing address 192.168.2.138/24 Jun 22 10:40:09 volumio-egreat ntpd[4469]: Deleting interface #3 wlan0, 192.168.2.138#123, interface stats: received=118, sent=119, dropped=0, active_time=58 secs Jun 22 10:40:09 volumio-egreat ntpd[4469]: 46.175.224.7 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 194.146.251.100 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 162.159.200.123 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 185.94.68.57 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 149.156.70.60 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 91.212.242.20 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 194.146.251.102 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 89.161.47.136 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 212.127.95.218 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 193.70.94.182 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 162.159.200.1 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 194.110.5.11 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 195.46.37.22 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 193.59.134.156 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 46.174.178.150 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 212.127.78.21 local addr 192.168.2.138 -> Jun 22 10:40:09 volumio-egreat ntpd[4469]: 89.25.168.148 local addr 192.168.2.138 -> Jun 22 10:40:10 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:10 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 63. Jun 22 10:40:10 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:10 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:10 volumio-egreat go-librespot[4842]: go-librespot daemon starting... Jun 22 10:40:10 volumio-egreat go-librespot[4842]: time="2025-06-22T10:40:10+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:10 volumio-egreat go-librespot[4842]: time="2025-06-22T10:40:10+02:00" level=debug msg="app state loaded" Jun 22 10:40:10 volumio-egreat go-librespot[4842]: time="2025-06-22T10:40:10+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:10 volumio-egreat go-librespot[4842]: time="2025-06-22T10:40:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:10 volumio-egreat go-librespot[4842]: time="2025-06-22T10:40:10+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 22 10:40:10 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:10 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:10 volumio-egreat volumio[2926]: info: Checking if install.sh is present Jun 22 10:40:10 volumio-egreat volumio[2926]: info: Getting Spotify volume Jun 22 10:40:10 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:10 volumio-egreat volumio[2926]: info: Volumio Network Manager: Network status updated: 0 Jun 22 10:40:10 volumio-egreat volumio[2926]: info: Executing install.sh Jun 22 10:40:11 volumio-egreat volumio[2926]: (node:2926) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:11 volumio-egreat volumio[2926]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 22 10:40:11 volumio-egreat volumio[2926]: (node:2926) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 6) Jun 22 10:40:11 volumio-egreat volumio[2926]: info: Discovery: A device disappeared from network Jun 22 10:40:11 volumio-egreat volumio[2926]: info: Discovery: Device volumio-egreat disappeared from network Jun 22 10:40:11 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:11 volumio-egreat volumio[2926]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jun 22 10:40:11 volumio-egreat sudo[4852]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/audio_interface/fusiondsp/install.sh Jun 22 10:40:11 volumio-egreat sudo[4852]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:11 volumio-egreat volumio[2926]: info: CoreCommandRouter::volumioGetState Jun 22 10:40:11 volumio-egreat volumio[2926]: info: creating filters folder and copying demo filters Jun 22 10:40:11 volumio-egreat volumio[2926]: info: copying demo flters Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/ Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/2XEQ15/ Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/2XEQ15/.Bass-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/2XEQ15/.Soundtrack-FusionDsp.json Jun 22 10:40:11 volumio-egreat sudo[4877]: root : TTY=unknown ; PWD=/data/plugins/audio_interface/fusiondsp ; USER=root ; COMMAND=/usr/bin/apt update Jun 22 10:40:11 volumio-egreat sudo[4877]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/2XEQ15/.Classic-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/2XEQ15/.Voice-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/2XEQ15/.Rock-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/PEQ/ Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/convfir/ Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/convfir/kef.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/convfir/test.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/EQ15/ Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/EQ15/.Bass-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/EQ15/.Soundtrack-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/EQ15/.Classic-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/EQ15/.Voice-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: ./presets/EQ15/.Rock-FusionDsp.json Jun 22 10:40:11 volumio-egreat volumio[2926]: info: Installing/fusiondsp dependencies Jun 22 10:40:11 volumio-egreat volumio[2926]: info: Err:1 http://deb.debian.org/debian buster InRelease Jun 22 10:40:11 volumio-egreat volumio[2926]: info: System error resolving 'deb.debian.org:http' - getaddrinfo (16: Device or resource busy) Jun 22 10:40:11 volumio-egreat volumio[2926]: info: Err:2 https://deb.nodesource.com/node_14.x buster InRelease Jun 22 10:40:11 volumio-egreat volumio[2926]: info: System error resolving 'deb.nodesource.com:https' - getaddrinfo (16: Device or resource busy) Jun 22 10:40:12 volumio-egreat dhcpcd[1057]: wlan0: leased 192.168.2.138 for 86400 seconds Jun 22 10:40:12 volumio-egreat dhcpcd[1057]: wlan0: adding route to 192.168.2.0/24 Jun 22 10:40:12 volumio-egreat dhcpcd[1057]: wlan0: adding default route via 192.168.2.1 Jun 22 10:40:12 volumio-egreat avahi-daemon[829]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.138. Jun 22 10:40:12 volumio-egreat avahi-daemon[829]: New relevant interface wlan0.IPv4 for mDNS. Jun 22 10:40:12 volumio-egreat avahi-daemon[829]: Registering new address record for 192.168.2.138 on wlan0.IPv4. Jun 22 10:40:12 volumio-egreat ntpd[4469]: ntpd exiting on signal 15 (Terminated) Jun 22 10:40:12 volumio-egreat systemd[1]: Stopping Network Time Service... Jun 22 10:40:12 volumio-egreat systemd[1]: ntp.service: Succeeded. Jun 22 10:40:12 volumio-egreat systemd[1]: Stopped Network Time Service. Jun 22 10:40:12 volumio-egreat systemd[1]: Starting Network Time Service... Jun 22 10:40:12 volumio-egreat ntpd[4920]: ntpd 4.2.8p12@1.3728-o (1): Starting Jun 22 10:40:12 volumio-egreat ntpd[4920]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Jun 22 10:40:12 volumio-egreat systemd[1]: Started Network Time Service. Jun 22 10:40:12 volumio-egreat ntpd[4926]: proto: precision = 0.252 usec (-22) Jun 22 10:40:12 volumio-egreat ntpd[4926]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Jun 22 10:40:12 volumio-egreat ntpd[4926]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Jun 22 10:40:12 volumio-egreat ntpd[4926]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 908 days ago Jun 22 10:40:12 volumio-egreat ntpd[4926]: Listen and drop on 0 v6wildcard [::]:123 Jun 22 10:40:12 volumio-egreat ntpd[4926]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Jun 22 10:40:12 volumio-egreat ntpd[4926]: Listen normally on 2 lo 127.0.0.1:123 Jun 22 10:40:12 volumio-egreat ntpd[4926]: Listen normally on 3 wlan0 192.168.2.138:123 Jun 22 10:40:12 volumio-egreat ntpd[4926]: Listening on routing socket on fd #20 for interface updates Jun 22 10:40:12 volumio-egreat ntpd[4926]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Jun 22 10:40:12 volumio-egreat ntpd[4926]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Jun 22 10:40:13 volumio-egreat volumio[2926]: info: Discovery: adding 01addb09-39b4-4b2e-b94c-51fbb6fe772d Jun 22 10:40:13 volumio-egreat volumio[2926]: info: Discovery: Found device Volumio-Egreat Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CoreCommandRouter::volumioGetState Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 22 10:40:13 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:13 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 64. Jun 22 10:40:13 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:13 volumio-egreat volumio[2926]: info: Received Get System Version Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 22 10:40:13 volumio-egreat volumio[2926]: info: Received Get System Info Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 22 10:40:13 volumio-egreat volumio[2926]: info: Discovery: Getting this device information Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CoreCommandRouter::volumioGetState Jun 22 10:40:13 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 22 10:40:13 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:13 volumio-egreat go-librespot[4928]: go-librespot daemon starting... Jun 22 10:40:13 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:13+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:13 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:13+02:00" level=debug msg="app state loaded" Jun 22 10:40:13 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:13+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:13 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:13 volumio-egreat ntpd[4926]: Soliciting pool server 85.115.212.251 Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40: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]" Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40: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]" Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40: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]" Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:14+02:00" level=info msg="zeroconf server listening on port 35655" Jun 22 10:40:14 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:14+02:00" level=debug msg="new websocket client" Jun 22 10:40:14 volumio-egreat volumio[2926]: info: Connection to go-librespot Websocket established Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:14+02:00" level=debug msg="obtained new client token: AACaf/JNpqIcz7SgPkBdLIjHJKpckXtjFNmcGbP5xHomxLeu0AqXe+zp0NjFzfvpsE6DFz5Ns/oX2OMeU4POVsKUNoKrXAGgiLXVHXkUP5Uq17mM0rgDtcY2aVokiPx5Hjiq2Wo+jWewYp1v23pIqdDhVQZxl+UPwnei8dV8Z5s7pLyFcIig5/L+5/wrFBdXX0AHkFyT5ynp29eryNwwNotO1wMMA6huUUrkqZ+ycphndG01EBlD0g==" Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:14+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:14+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:14+02:00" level=debug msg="completed challenge" Jun 22 10:40:14 volumio-egreat go-librespot[4928]: time="2025-06-22T10:40:14+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:14 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:14 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:14 volumio-egreat volumio[2926]: info: Connection to go-librespot Websocket closed Jun 22 10:40:14 volumio-egreat ntpd[4926]: Soliciting pool server 91.210.128.220 Jun 22 10:40:14 volumio-egreat ntpd[4926]: Soliciting pool server 213.222.217.11 Jun 22 10:40:15 volumio-egreat ntpd[4926]: Soliciting pool server 85.115.212.254 Jun 22 10:40:15 volumio-egreat ntpd[4926]: Soliciting pool server 162.159.200.1 Jun 22 10:40:16 volumio-egreat ntpd[4926]: Soliciting pool server 194.146.251.100 Jun 22 10:40:16 volumio-egreat volumio[2926]: info: Reading package lists... Jun 22 10:40:16 volumio-egreat ntpd[4926]: Soliciting pool server 91.212.242.21 Jun 22 10:40:16 volumio-egreat ntpd[4926]: Soliciting pool server 212.127.95.218 Jun 22 10:40:16 volumio-egreat ntpd[4926]: Soliciting pool server 195.46.37.22 Jun 22 10:40:16 volumio-egreat ntpd[4926]: Soliciting pool server 85.115.212.250 Jun 22 10:40:17 volumio-egreat volumio[2926]: info: Getting Spotify volume Jun 22 10:40:17 volumio-egreat volumio[2926]: (node:2926) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:17 volumio-egreat volumio[2926]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 22 10:40:17 volumio-egreat volumio[2926]: (node:2926) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 7) Jun 22 10:40:17 volumio-egreat volumio[2926]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jun 22 10:40:17 volumio-egreat volumio[2926]: info: CoreCommandRouter::volumioGetState Jun 22 10:40:17 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:17 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:17 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:17 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 65. Jun 22 10:40:17 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:17 volumio-egreat volumio[2926]: info: Building dependency tree... Jun 22 10:40:17 volumio-egreat volumio[2926]: info: Reading state information... Jun 22 10:40:17 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:17 volumio-egreat go-librespot[4939]: go-librespot daemon starting... Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+02:00" level=debug msg="app state loaded" Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:17 volumio-egreat volumio[2926]: info: All packages are up to date. Jun 22 10:40:17 volumio-egreat sudo[4877]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:17 volumio-egreat sudo[4946]: root : TTY=unknown ; PWD=/data/plugins/audio_interface/fusiondsp ; USER=root ; COMMAND=/usr/bin/apt -y install python3-aiohttp python3-pip Jun 22 10:40:17 volumio-egreat sudo[4946]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:17 volumio-egreat volumio[2926]: info: Reading package lists... Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+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]" Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+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]" Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+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]" Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+02:00" level=info msg="zeroconf server listening on port 45531" Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+02:00" level=debug msg="obtained new client token: AAD/tacuKQ0qIo016ehxjNV+pxALIFwFi6968cEWpC6JR65krWo2hXD42BeX+nFsLsh9S6e1ebQRdZJcuTF9QXMG2RCaT7OfpKZAPkbX+7JCRYbGAv/zxCtG5d9NnwrOglZHpZhIlkKQNblZCHACIuTmUa/eUDZ/TJDo/6O6CcA61Of/I5sFAQHzqJjl8Ki4YpaZz29YXyF1uDTkzwjPULNxuHOAIhMJFEyAvY0K4RWSX8TVUWwS+iNf" Jun 22 10:40:17 volumio-egreat ntpd[4926]: Soliciting pool server 89.161.47.136 Jun 22 10:40:17 volumio-egreat ntpd[4926]: Soliciting pool server 91.212.242.20 Jun 22 10:40:17 volumio-egreat ntpd[4926]: Soliciting pool server 193.59.134.156 Jun 22 10:40:17 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:17+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:17 volumio-egreat ntpd[4926]: Soliciting pool server 212.127.78.21 Jun 22 10:40:18 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:18+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:18 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:18+02:00" level=debug msg="completed challenge" Jun 22 10:40:18 volumio-egreat go-librespot[4939]: time="2025-06-22T10:40:18+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:18 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:18 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:18 volumio-egreat volumio[2926]: info: Building dependency tree... Jun 22 10:40:18 volumio-egreat volumio[2926]: info: Reading state information... Jun 22 10:40:18 volumio-egreat ntpd[4926]: Soliciting pool server 149.156.70.60 Jun 22 10:40:18 volumio-egreat ntpd[4926]: Soliciting pool server 188.165.17.91 Jun 22 10:40:18 volumio-egreat ntpd[4926]: Soliciting pool server 89.25.168.148 Jun 22 10:40:18 volumio-egreat ntpd[4926]: Soliciting pool server 46.174.178.150 Jun 22 10:40:19 volumio-egreat volumio[2926]: info: Volumio Network Manager: Network status updated: 2 Jun 22 10:40:19 volumio-egreat volumio[2926]: info: python3-aiohttp is already the newest version (3.5.1-1+deb10u1). Jun 22 10:40:19 volumio-egreat volumio[2926]: info: python3-pip is already the newest version (18.1-5). Jun 22 10:40:19 volumio-egreat volumio[2926]: info: The following package was automatically installed and is no longer required: Jun 22 10:40:19 volumio-egreat volumio[2926]: info: liblirc-client0 Jun 22 10:40:19 volumio-egreat volumio[2926]: info: Use 'sudo apt autoremove' to remove it. Jun 22 10:40:19 volumio-egreat sudo[4946]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:19 volumio-egreat volumio[2926]: info: 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. Jun 22 10:40:19 volumio-egreat sudo[4966]: root : TTY=unknown ; PWD=/data/plugins/audio_interface/fusiondsp ; USER=root ; COMMAND=/bin/tar -xvf fusiondsp.service.tar -C / Jun 22 10:40:19 volumio-egreat sudo[4966]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:19 volumio-egreat volumio[2926]: info: lib/systemd/system/fusiondsp.service Jun 22 10:40:19 volumio-egreat sudo[4966]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:20 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:20 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:21 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:21 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 66. Jun 22 10:40:21 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:21 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:21 volumio-egreat go-librespot[4969]: go-librespot daemon starting... Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+02:00" level=debug msg="app state loaded" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+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]" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+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]" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+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]" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+02:00" level=info msg="zeroconf server listening on port 39743" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+02:00" level=debug msg="obtained new client token: AABaAPAr+S+VcGpDaFQ7kqT5H1vYLS5WNEuBSqCzCkrS567O+j1QtbetFRqqOCUEY1MoFzPNg2E5CnlfR9PvyyIlI3x8FcRLKB+a/J9cndnpLgxUMHCRALisxVfy6lys8iWbA4uNYrbLS0ieDc060xi5t7JWPQcWyR9ZVCmjMv3EHfLcib3ogOleFxJYwJvDsdX6ZZDflg5OjyDYMTs5x6FWupYwlWMrLd2+1t5Xwhs9u+wF/HMKtsF7" Jun 22 10:40:21 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:21+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Jun 22 10:40:22 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:22+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Jun 22 10:40:22 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:22+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:22 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:22+02:00" level=debug msg="completed challenge" Jun 22 10:40:22 volumio-egreat go-librespot[4969]: time="2025-06-22T10:40:22+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:22 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:22 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:22 volumio-egreat volumio[2926]: info: MiniUnz 1.01b, demo of zLib + Unz package written by Gilles Vollant Jun 22 10:40:22 volumio-egreat volumio[2926]: info: more info at http://www.winimage.com/zLibDll/unzip.html Jun 22 10:40:22 volumio-egreat volumio[2926]: info: Jun 22 10:40:22 volumio-egreat volumio[2926]: info: cgui-1.0.0.zip opened Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/ Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/LICENSE.txt Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/README.md Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/build/ Jun 22 10:40:22 volumio-egreat sudo[4979]: root : TTY=unknown ; PWD=/data/plugins/audio_interface/fusiondsp ; USER=root ; COMMAND=/bin/chown -R volumio cgui Jun 22 10:40:22 volumio-egreat sudo[4979]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/robots.txt Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/logo512.png Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/asset-manifest.json Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/index.html Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/.put_statics_here Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/favicon.ico Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/logo192.png Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/.xdp-css-variables-1.css-PvrWoX Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/manifest.json Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/css-variables.css Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/precache-manifest.76db5aad1647230454f47b1e22783b54.js Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/service-worker.js Jun 22 10:40:22 volumio-egreat sudo[4979]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/precache-manifest.5e6c675b70ef6a3fe73d0209febfe347.js Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/build/static/ Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/build/static/css/ Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/main.d51d005e.chunk.css Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/main.d51d005e.chunk.css.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/2.975d6916.chunk.css.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/main.56bdf14e.chunk.css Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/main.56bdf14e.chunk.css.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/main.1503f6cd.css.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/2.a4c7e7cf.chunk.css.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/main.1503f6cd.css Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/2.975d6916.chunk.css Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/css/2.a4c7e7cf.chunk.css Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/build/static/media/ Jun 22 10:40:22 volumio-egreat sudo[4981]: root : TTY=unknown ; PWD=/data/plugins/audio_interface/fusiondsp ; USER=root ; COMMAND=/bin/chgrp -R volumio cgui Jun 22 10:40:22 volumio-egreat sudo[4981]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/media/camilladsp.95719842.svg Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/media/camilladsp.4767ea4ad3510467418b818dc677a87e.svg Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/build/static/js/ Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/2.fd49ece5.chunk.js.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/main.71e11955.js Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/runtime-main.422581ec.js Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/2.fd49ece5.chunk.js Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/2.c1b9df8b.chunk.js.LICENSE.txt Jun 22 10:40:22 volumio-egreat sudo[4981]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/main.61bb6809.chunk.js Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/main.61bb6809.chunk.js.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/2.c1b9df8b.chunk.js Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/main.1b3ac690.chunk.js.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/main.71e11955.js.LICENSE.txt Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/main.71e11955.js.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/runtime-main.422581ec.js.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/main.1b3ac690.chunk.js Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/2.c1b9df8b.chunk.js.map Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/build/static/js/2.fd49ece5.chunk.js.LICENSE.txt Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/config/ Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/config/camillagui.yml Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/config/.xdp-css-variables-1.css-ppBDuX Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/config/gui-config.yml Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/backend/ Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/filters_test.py Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/version.py Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/filters.py Jun 22 10:40:22 volumio-egreat sudo[4983]: root : TTY=unknown ; PWD=/data/plugins/audio_interface/fusiondsp ; USER=root ; COMMAND=/bin/rm cgui-1.0.0.zip Jun 22 10:40:22 volumio-egreat sudo[4983]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/settings.py Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/views.py Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/filterdefaults.py Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__init__.py Jun 22 10:40:22 volumio-egreat volumio[2926]: info: creating directory: cgui/backend/__pycache__/ Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__pycache__/filterdefaults.cpython-37.pyc Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__pycache__/views.cpython-37.pyc Jun 22 10:40:22 volumio-egreat sudo[4983]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__pycache__/settings.cpython-37.pyc Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__pycache__/__init__.cpython-37.pyc Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__pycache__/routes.cpython-37.pyc Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__pycache__/filemanagement.cpython-37.pyc Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__pycache__/filters.cpython-37.pyc Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/__pycache__/version.cpython-37.pyc Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/routes.py Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/backend/filemanagement.py Jun 22 10:40:22 volumio-egreat volumio[2926]: info: extracting: cgui/main.py Jun 22 10:40:23 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:23 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:25 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:25 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 67. Jun 22 10:40:25 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:25 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:25 volumio-egreat go-librespot[4986]: go-librespot daemon starting... Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=debug msg="app state loaded" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+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]" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+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]" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+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]" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=info msg="zeroconf server listening on port 32909" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=debug msg="obtained new client token: AAD82ERFdnmrKT5U3DJwEiPJC+XEcI6+YFSLcbdNaeGiK6cp97iB4jiq62l6ORlk1UCzMsd+uyxkf/njJuTN0njcjfi9AeAR4nXZSJx+KRg+jvHLXKWB6ARcF7JodrV8EC7pu6qiuHWjRpqnrf3D2vY8zd8IZzZiWv81Bi8MACyXDL1zIe9LcyD9ZXl11oH+/y75S+i9EowfLTNszlfJ8DFoxtLy4FFHMIGkCSp0Y1BtCDkKTcRWOeMO" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=debug msg="completed challenge" Jun 22 10:40:25 volumio-egreat go-librespot[4986]: time="2025-06-22T10:40:25+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:25 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:25 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:26 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:26 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:26 volumio-egreat volumio[2926]: info: Collecting git+https://github.com/HEnquist/pycamilladsp.git@v1.0.0 Jun 22 10:40:26 volumio-egreat volumio[2926]: info: Cloning https://github.com/HEnquist/pycamilladsp.git (to revision v1.0.0) to /tmp/pip-req-build-9w2pvxqt Jun 22 10:40:29 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:29 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 68. Jun 22 10:40:29 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:29 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:29 volumio-egreat go-librespot[5014]: go-librespot daemon starting... Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=debug msg="app state loaded" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:29 volumio-egreat volumio[2926]: info: Requirement already satisfied (use --upgrade to upgrade): camilladsp==1.0.0 from git+https://github.com/HEnquist/pycamilladsp.git@v1.0.0 in /usr/local/lib/python3.7/dist-packages Jun 22 10:40:29 volumio-egreat volumio[2926]: info: Requirement already satisfied: PyYAML in /usr/local/lib/python3.7/dist-packages (from camilladsp==1.0.0) (6.0.1) Jun 22 10:40:29 volumio-egreat volumio[2926]: info: Requirement already satisfied: websocket_client in /usr/local/lib/python3.7/dist-packages (from camilladsp==1.0.0) (1.6.1) Jun 22 10:40:29 volumio-egreat volumio[2926]: info: Building wheels for collected packages: camilladsp Jun 22 10:40:29 volumio-egreat volumio[2926]: info: Running setup.py bdist_wheel for camilladsp: started Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+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]" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+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]" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+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]" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=info msg="zeroconf server listening on port 35207" Jun 22 10:40:29 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=debug msg="new websocket client" Jun 22 10:40:29 volumio-egreat volumio[2926]: info: Connection to go-librespot Websocket established Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=debug msg="obtained new client token: AAD0ncisPrCLg3otuQijrCXQ4ElHIFmFn5jHVwfYJI8t+gcyquIKN71wrEK+P81a4S8EtGjPTwlz+uFT7LFnA1vf53PrBWnkGc/vLFcKpHQEydJC4BK4EGHfGMvlt6a62PZDxLT6s0+NTqf0nUTx0ae3Ce4znSt7zmwtYEBAKnD/vu7tUTmpQkUcQ6z/IZY4jOI8Cs4bQONScw9oiMtrzZ0OMLVPCJQr58mds/EM4Wvn+GhYXqmQhM4w" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=debug msg="completed challenge" Jun 22 10:40:29 volumio-egreat go-librespot[5014]: time="2025-06-22T10:40:29+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:29 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:29 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:29 volumio-egreat volumio[2926]: info: Connection to go-librespot Websocket closed Jun 22 10:40:30 volumio-egreat volumio[2926]: info: Running setup.py bdist_wheel for camilladsp: finished with status 'done' Jun 22 10:40:30 volumio-egreat volumio[2926]: info: Stored in directory: /tmp/pip-ephem-wheel-cache-7ndsw7h0/wheels/ca/47/7d/ee36beb671f74869a8e2ecb2c3fd4a28c1b7488a9c78e442b6 Jun 22 10:40:30 volumio-egreat volumio[2926]: info: Successfully built camilladsp Jun 22 10:40:32 volumio-egreat volumio[2926]: info: Getting Spotify volume Jun 22 10:40:32 volumio-egreat volumio[2926]: (node:2926) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:32 volumio-egreat volumio[2926]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 22 10:40:32 volumio-egreat volumio[2926]: (node:2926) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 8) Jun 22 10:40:32 volumio-egreat volumio[2926]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 22 10:40:32 volumio-egreat volumio[2926]: info: CoreCommandRouter::volumioGetState Jun 22 10:40:32 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:32 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:32 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:32 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 69. Jun 22 10:40:32 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:32 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:32 volumio-egreat go-librespot[5041]: go-librespot daemon starting... Jun 22 10:40:32 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:32+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:32 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:32+02:00" level=debug msg="app state loaded" Jun 22 10:40:32 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:32+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:32 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+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]" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+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]" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+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]" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+02:00" level=info msg="zeroconf server listening on port 40157" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+02:00" level=debug msg="obtained new client token: AABaUxVOnfd7ux0Uhqn8vZs6i3jpRalfheW8haYaZQzFAmvnkuWkbQsUQjUMd8f0hyEns/skx7GQgDyfreeWCYS09k0T67a7x9KEwwVr1jR7YNe+bshVEBZV3NijES7po6cGZZ5WqucDqGUK6BJNj38v4OyZOtXNvBQHdB1AgEKIkh8bFm5gbKF2GeSYBeVJnoS/wGyyFhO/E1m+/02V3vpxwSd92IJa3t9rQcC2+MOWzpkmlg0BOA==" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+02:00" level=debug msg="completed challenge" Jun 22 10:40:33 volumio-egreat go-librespot[5041]: time="2025-06-22T10:40:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:33 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:33 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:34 volumio-egreat volumio[2926]: info: Collecting git+https://github.com/HEnquist/pycamilladsp-plot.git@v1.0.2 Jun 22 10:40:34 volumio-egreat volumio[2926]: info: Cloning https://github.com/HEnquist/pycamilladsp-plot.git (to revision v1.0.2) to /tmp/pip-req-build-m3tz14_j Jun 22 10:40:35 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:35 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:36 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:36 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 70. Jun 22 10:40:36 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:36 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:36 volumio-egreat go-librespot[5073]: go-librespot daemon starting... Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=debug msg="app state loaded" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+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]" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+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]" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+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]" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=info msg="zeroconf server listening on port 38485" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=debug msg="obtained new client token: AACMcEq8GUSO38gGWX6IYoA9/nuFywPpcmGhU/TREGUXA3xpHBO5ZgRZcBAwiYU1LVc0U48wTln2jSmAubOKey2eEulwz7g5onM3zmzAftGJqT0i2pvMhXy/YBhOxqi6bpdqxo81I+dSxQ1aCasX8YDUt4O11JKAe1SqHHAxDz8yv6q1mezZ7acGryn6BVYSG7AiTz1ohaZwAgfuxkrKwUeRgK3fTlo7yrg4UkGiwWC+Fi5EAc5KrZfG" Jun 22 10:40:36 volumio-egreat volumio[2926]: info: Requirement already satisfied (use --upgrade to upgrade): camilladsp-plot==1.0.2 from git+https://github.com/HEnquist/pycamilladsp-plot.git@v1.0.2 in /usr/local/lib/python3.7/dist-packages Jun 22 10:40:36 volumio-egreat volumio[2926]: info: Requirement already satisfied: PyYAML in /usr/local/lib/python3.7/dist-packages (from camilladsp-plot==1.0.2) (6.0.1) Jun 22 10:40:36 volumio-egreat volumio[2926]: info: Requirement already satisfied: jsonschema in /usr/local/lib/python3.7/dist-packages (from camilladsp-plot==1.0.2) (4.17.3) Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:36 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:36+02:00" level=debug msg="completed challenge" Jun 22 10:40:37 volumio-egreat go-librespot[5073]: time="2025-06-22T10:40:37+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:37 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:37 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Requirement already satisfied: importlib-resources>=1.4.0; python_version < "3.9" in /usr/local/lib/python3.7/dist-packages (from jsonschema->camilladsp-plot==1.0.2) (5.12.0) Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Requirement already satisfied: pkgutil-resolve-name>=1.3.10; python_version < "3.9" in /usr/local/lib/python3.7/dist-packages (from jsonschema->camilladsp-plot==1.0.2) (1.3.10) Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Requirement already satisfied: typing-extensions; python_version < "3.8" in /usr/local/lib/python3.7/dist-packages (from jsonschema->camilladsp-plot==1.0.2) (4.7.1) Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Requirement already satisfied: importlib-metadata; python_version < "3.8" in /usr/local/lib/python3.7/dist-packages (from jsonschema->camilladsp-plot==1.0.2) (6.7.0) Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Requirement already satisfied: pyrsistent!=0.17.0,!=0.17.1,!=0.17.2,>=0.14.0 in /usr/local/lib/python3.7/dist-packages (from jsonschema->camilladsp-plot==1.0.2) (0.19.3) Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Requirement already satisfied: attrs>=17.4.0 in /usr/lib/python3/dist-packages (from jsonschema->camilladsp-plot==1.0.2) (18.2.0) Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Requirement already satisfied: zipp>=3.1.0; python_version < "3.10" in /usr/local/lib/python3.7/dist-packages (from importlib-resources>=1.4.0; python_version < "3.9"->jsonschema->camilladsp-plot==1.0.2) (3.15.0) Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Building wheels for collected packages: camilladsp-plot Jun 22 10:40:37 volumio-egreat volumio[2926]: info: Running setup.py bdist_wheel for camilladsp-plot: started Jun 22 10:40:38 volumio-egreat volumio[2926]: info: Running setup.py bdist_wheel for camilladsp-plot: finished with status 'done' Jun 22 10:40:38 volumio-egreat volumio[2926]: info: Stored in directory: /tmp/pip-ephem-wheel-cache-4xbb_rt6/wheels/11/e1/43/8275af2f537d569c7097d202b4955f9aec629859be39dab2e9 Jun 22 10:40:38 volumio-egreat volumio[2926]: info: Successfully built camilladsp-plot Jun 22 10:40:38 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:38 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:38 volumio-egreat volumio[2926]: info: copying hw detection script Jun 22 10:40:38 volumio-egreat volumio[2926]: info: Detected cpu architecture as x86_64 Jun 22 10:40:40 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:40 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71. Jun 22 10:40:40 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:40 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:40 volumio-egreat go-librespot[5102]: go-librespot daemon starting... Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+02:00" level=debug msg="app state loaded" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+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]" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+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]" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+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]" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+02:00" level=info msg="zeroconf server listening on port 44787" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+02:00" level=debug msg="obtained new client token: AABIEj4X9TM+dnDZUcMLmvYSkn34mJJpG1Laq+lcZq4EJffi3aR03AVcEroAl7p8MKxkACnTLDOUzrG9QnfJ+pQq/dj7Ns170yACjSzCsoZVEfzeHcQ2PjIDVhOtkZRzsmQRnRl9SX5xHbgfaqxdiAZp2crEAec3fWITAMTA88urGynqiJmDp0nEDbStrbcRqpYFVm56DPKkWeLFj89pHwIx5Qg7toFIuZHLsOk3e2TD3epO7meYBRB7" Jun 22 10:40:40 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:40+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:41 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:41+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:41 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:41+02:00" level=debug msg="completed challenge" Jun 22 10:40:41 volumio-egreat go-librespot[5102]: time="2025-06-22T10:40:41+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:41 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:41 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:41 volumio-egreat sudo[5119]: root : TTY=unknown ; PWD=/tmp ; USER=root ; COMMAND=/usr/bin/apt-get -y install drc Jun 22 10:40:41 volumio-egreat sudo[5119]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:40:41 volumio-egreat volumio[2926]: info: Reading package lists... Jun 22 10:40:41 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:41 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:41 volumio-egreat volumio[2926]: info: Building dependency tree... Jun 22 10:40:41 volumio-egreat volumio[2926]: info: Reading state information... Jun 22 10:40:42 volumio-egreat volumio[2926]: info: drc is already the newest version (3.2.2~dfsg0-2). Jun 22 10:40:42 volumio-egreat volumio[2926]: info: The following package was automatically installed and is no longer required: Jun 22 10:40:42 volumio-egreat volumio[2926]: info: liblirc-client0 Jun 22 10:40:42 volumio-egreat volumio[2926]: info: Use 'sudo apt autoremove' to remove it. Jun 22 10:40:43 volumio-egreat volumio[2926]: info: 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. Jun 22 10:40:43 volumio-egreat sudo[5119]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:43 volumio-egreat sudo[4852]: pam_unix(sudo:session): session closed for user root Jun 22 10:40:43 volumio-egreat volumio[2926]: info: Install script completed Jun 22 10:40:43 volumio-egreat volumio[2926]: info: Done installing plugin. Jun 22 10:40:43 volumio-egreat volumio[2926]: info: Enabling plugin fusiondsp Jun 22 10:40:43 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 22 10:40:43 volumio-egreat volumio[2926]: info: [{"prettyName":"FusionDsp","name":"fusiondsp","category":"audio_interface","version":"1.0.61","icon":"fa-sliders fa-rotate-90","isManuallyInstalled":true,"enabled":true,"active":false},{"prettyName":"80s80s Radio","name":"80s80s","category":"music_service","version":"1.0.4","icon":"fa-headphones","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Bandcamp Discover","name":"bandcamp","category":"music_service","version":"1.2.0","icon":"fa-bandcamp","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Calm Radio","name":"calmradio","category":"music_service","version":"1.2.4","icon":"fa-heartbeat","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Mixcloud","name":"mixcloud","category":"music_service","version":"1.0.1","icon":"fa-mixcloud","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Moosbox","name":"moosbox","category":"music_service","version":"1.0.0","icon":"fa-solid fa-music","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Radio Nowy Swiat","name":"nowyswiat","category":"music_service","version":"1.0.4","icon":"fa-lightbulb-o","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"RADIO 357","name":"rad357pl","category":"music_service","version":"1.0.2","icon":"fa-lightbulb-o","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Radio Paradise","name":"radio_paradise","category":"music_service","version":"1.0.12","icon":"fa-headphones","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"SoundCloud","name":"soundcloud","category":"music_service","version":"1.0.3","icon":"fa-music","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Spotify","name":"spop","category":"music_service","version":"4.1.4","icon":"fa-spotify","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Squeezelite MC","name":"squeezelite_mc","category":"music_service","version":"1.0.4","icon":"fa-play-circle-o","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"System information","name":"Systeminfo","category":"user_interface","version":"3.0.6","icon":"fa-info-circle","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Peppy-meter-Basic","name":"peppymeterbasic","category":"user_interface","version":"0.0.1","icon":"fa-bar-chart","isManuallyInstalled":false,"enabled":true,"active":true}] Jun 22 10:40:43 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 22 10:40:43 volumio-egreat volumio[2926]: info: Folder /tmp/plugins removed Jun 22 10:40:43 volumio-egreat volumio[2926]: info: Folder /tmp/downloaded_plugin.zip removed Jun 22 10:40:43 volumio-egreat volumio[2926]: Plugin install end detected on script Jun 22 10:40:43 volumio-egreat volumio[2926]: info: Folder /data/temp removed Jun 22 10:40:43 volumio-egreat volumio[2926]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 22 10:40:43 volumio-egreat volumio[2926]: info: FusionDsp - Jun 22 10:40:43 volumio-egreat volumio[2926]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json Jun 22 10:40:44 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:44 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72. Jun 22 10:40:44 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:44 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:44 volumio-egreat go-librespot[5123]: go-librespot daemon starting... Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=debug msg="app state loaded" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+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]" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+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]" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+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]" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=info msg="zeroconf server listening on port 41169" Jun 22 10:40:44 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=debug msg="new websocket client" Jun 22 10:40:44 volumio-egreat volumio[2926]: info: Connection to go-librespot Websocket established Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=debug msg="obtained new client token: AADNoY3/PX2Q97I7Zu9snCQxjWja1KZfcBVahfx+MAAdj19eQ8dr5RPydMmNdsWOP0+LnZSOb5uMbZ7aX5AqaZ0PistfrRX/t0SaqE+6LJ9zv7pwvZcM128AJXaA7LXrKFAFrbfseJJGyanCNi2py1tWH0eRMJTG1+vRkZdl0YTHUHDBOr4Jax55gYDsjFENV9BInjsNEj//rAagx1LTYgb/nVDJhp6r7Poyoy2IeHDAiEBX8dyWxNOS" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=debug msg="completed challenge" Jun 22 10:40:44 volumio-egreat go-librespot[5123]: time="2025-06-22T10:40:44+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:44 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:44 volumio-egreat volumio[2926]: info: Connection to go-librespot Websocket closed Jun 22 10:40:44 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:47 volumio-egreat volumio[2926]: info: Getting Spotify volume Jun 22 10:40:47 volumio-egreat volumio[2926]: (node:2926) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:47 volumio-egreat volumio[2926]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jun 22 10:40:47 volumio-egreat volumio[2926]: (node:2926) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 9) Jun 22 10:40:47 volumio-egreat volumio[2926]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 22 10:40:47 volumio-egreat volumio[2926]: info: CoreCommandRouter::volumioGetState Jun 22 10:40:47 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:47 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:48 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:48 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 73. Jun 22 10:40:48 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:48 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:48 volumio-egreat go-librespot[5131]: go-librespot daemon starting... Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=debug msg="app state loaded" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+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]" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+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]" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+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]" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=info msg="zeroconf server listening on port 39507" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=debug msg="obtained new client token: AACtZdNcS7wnHLDE4FspLMuVEVyc+5OMqffkEqOo5nkfHbH4wz3Q2YTtj6wY7U/qQHTlXBufGAedE0W+rvZwLuKWbOoargeLsdT/n903cPju3Pjwye/YmBShCe8qKJ8kc/tffjrw0/PtZVWPgNxUuuwWEWapAefNGS66xptb9+F/LUoOWKOIj7g8Oe4fNmxejVECR6lbpyQWkT3jCGwAOyHfXsI9atDQd44h5He2K+YnY9c81LwRMLXL" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=debug msg="completed challenge" Jun 22 10:40:48 volumio-egreat go-librespot[5131]: time="2025-06-22T10:40:48+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:48 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:48 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:50 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:50 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:51 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:51 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 74. Jun 22 10:40:51 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:51 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:51 volumio-egreat go-librespot[5191]: go-librespot daemon starting... Jun 22 10:40:51 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:51+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:51 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:51+02:00" level=debug msg="app state loaded" Jun 22 10:40:51 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:51+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:51 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:51+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+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]" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+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]" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+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]" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+02:00" level=info msg="zeroconf server listening on port 39911" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+02:00" level=debug msg="obtained new client token: AACnLb1D5PpHWjVGZ0Ft1Qx9vgwUUsUO/e+LOrKLoUEWyKsVNsHo8XEFRm6Et1He54MMDX8hD9A95pTD7DAwjp4sijStcX2nsYsgeDykzxtgQPB5WKxg17bqGD0Cawk3ebsB9w8QHKjQ+OM0ztlQ/QwuUUMCh+K2XvyTf0CwmEemT6QU2LeW24aKeBR2TMgAhJLNZaShLYxVMRUhQDTCKHtxfJMtRQ3D8NLWUQ9H5cLeiBAncxnvow==" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+02:00" level=debug msg="completed challenge" Jun 22 10:40:52 volumio-egreat go-librespot[5191]: time="2025-06-22T10:40:52+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:52 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:52 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:53 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:53 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:55 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:55 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 75. Jun 22 10:40:55 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:55 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:55 volumio-egreat go-librespot[5203]: go-librespot daemon starting... Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+02:00" level=debug msg="app state loaded" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+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]" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+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]" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+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]" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+02:00" level=info msg="zeroconf server listening on port 34207" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+02:00" level=debug msg="obtained new client token: AADgmmswcVdqfZGPL6BQjjwI6EhYYkKEbPh85GA2mJqPY1KfWTjDF29XExzN+9N6zNZpBfVBPk2oU0+Dkks5Nw1t2BKs4JLvlxKORObBOjfZuGt60D+z4AAkm8qAfygiPnyg5+/sP5DBJgLCKCRzxPgRUr8LU8Eco3ZGgQCI3SDox3LYuAfzjg93hyxfmkq1N7HTbSiHLCcxTluW5H5SrHfhdN4yZF/Uc5uJDKJPx/GnHZ/F5Eq1/7TC" Jun 22 10:40:55 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:55+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:56 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:56+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:56 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:56+02:00" level=debug msg="completed challenge" Jun 22 10:40:56 volumio-egreat go-librespot[5203]: time="2025-06-22T10:40:56+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:56 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:56 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:56 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:56 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:40:57 volumio-egreat volumio[2926]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 22 10:40:59 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:40:59 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 76. Jun 22 10:40:59 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:40:59 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:40:59 volumio-egreat go-librespot[5212]: go-librespot daemon starting... Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=debug msg="app state loaded" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=debug msg="stored credentials not found" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+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]" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+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]" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+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]" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=info msg="zeroconf server listening on port 35555" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=debug msg="obtained new client token: AAA0JnK38GqWbeCaO/R0g/4NI8Q6qZ+AJ6BnS5ErXit44Kbr6ebnOUvFYf+EuyBABdLYCTFfphR3aBsT4oMfmInGBSNnDq2oN/pSLIb7+nt8dE+qTMopcQuh/cEktfcPUldvvtGWTle/95IcTdyUSgm/Nau1f8u/kg5LetOCBGCI7PElv7HfszkLEt1+MCbybonwytFO+ZTHZyoyFlcQh/vSTIeMCz9R97KBA8YSntb5NHay0oOf9exA" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=debug msg="completed keyexchange" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=debug msg="completed challenge" Jun 22 10:40:59 volumio-egreat go-librespot[5212]: time="2025-06-22T10:40:59+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:40:59 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:40:59 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:40:59 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:40:59 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:41:02 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:41:02 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:41:03 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:41:03 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 77. Jun 22 10:41:03 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:41:03 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:41:03 volumio-egreat go-librespot[5234]: go-librespot daemon starting... Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=debug msg="app state loaded" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=debug msg="stored credentials not found" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+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]" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+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]" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+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]" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=info msg="zeroconf server listening on port 35765" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=debug msg="obtained new client token: AAAQKbmYFKKzZmR0kSPQQZcyliDM6XKXu6NUhJ2we8smexgowQfGSsE44SD9BIthVzbrCysi0aWSGRhcyyrL/howefjSkxOIrvM2jBH16WPEWUIac34uxacThv2qctIoudH/jmBqdWO8lfdR/zIUZfpCkvJKEyY5qE+MwNPCP2/Y5TbPf7L5g0Akb4Ip4yBYrAOGQRaVXm1I723OySJb7trjCsGY/uKIV0X1Sm/JuTXg/koMGTjCkSwx" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=debug msg="completed keyexchange" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=debug msg="completed challenge" Jun 22 10:41:03 volumio-egreat go-librespot[5234]: time="2025-06-22T10:41:03+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:41:03 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:41:03 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:41:05 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:41:05 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:41:06 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:41:06 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 78. Jun 22 10:41:06 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:41:06 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:41:06 volumio-egreat go-librespot[5242]: go-librespot daemon starting... Jun 22 10:41:06 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:06+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:41:06 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:06+02:00" level=debug msg="app state loaded" Jun 22 10:41:06 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:06+02:00" level=debug msg="stored credentials not found" Jun 22 10:41:06 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+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]" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+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]" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+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]" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+02:00" level=info msg="zeroconf server listening on port 41477" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+02:00" level=debug msg="obtained new client token: AABSPqyS93tqTbZ5FIbWDfCfJvA5xNiyydgTlnSK6iZhQPbFtUn33/aF769LUZro9nPlHcygMrhPmTSyjBPkBOHCJxtsnJTH+se+zD+ENUF1NhNh4mpHAdK59f5Ap6fYM8G34zBFtuhM6xwBAYjL9fw4UgS63CPTVRbXn4SjksO+LQb19SeQQlsx99BpfC/QTdXbxzB9tiLHZY6AjvFB6yfBfMGhuvkic8p4BBgQPNOpYGwaoplbpQ==" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+02:00" level=debug msg="completed keyexchange" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+02:00" level=debug msg="completed challenge" Jun 22 10:41:07 volumio-egreat go-librespot[5242]: time="2025-06-22T10:41:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jun 22 10:41:07 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:41:07 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:41:07 volumio-egreat volumio[2926]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/80s80s/volumio/buster/amd64 Jun 22 10:41:08 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:41:08 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:41:09 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-DISCONNECTED bssid=08:bf:b8:8e:9b:ac reason=0 locally_generated=1 Jun 22 10:41:09 volumio-egreat dhcpcd[1057]: wlan0: carrier lost Jun 22 10:41:09 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-ASSOC-REJECT status_code=1 Jun 22 10:41:09 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Jun 22 10:41:09 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=PL Jun 22 10:41:09 volumio-egreat avahi-daemon[829]: Withdrawing address record for 192.168.2.138 on wlan0. Jun 22 10:41:09 volumio-egreat avahi-daemon[829]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.138. Jun 22 10:41:09 volumio-egreat avahi-daemon[829]: Interface wlan0.IPv4 no longer relevant for mDNS. Jun 22 10:41:09 volumio-egreat volumio[2926]: info: Discovery: A device disappeared from network Jun 22 10:41:09 volumio-egreat volumio[2926]: info: Discovery: Device volumio-egreat disappeared from network Jun 22 10:41:09 volumio-egreat dhcpcd[1057]: wlan0: deleting route to 192.168.2.0/24 Jun 22 10:41:09 volumio-egreat dhcpcd[1057]: wlan0: deleting default route via 192.168.2.1 Jun 22 10:41:10 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:41:10 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 79. Jun 22 10:41:10 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:41:10 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:41:10 volumio-egreat go-librespot[5288]: go-librespot daemon starting... Jun 22 10:41:10 volumio-egreat go-librespot[5288]: time="2025-06-22T10:41:10+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:41:10 volumio-egreat go-librespot[5288]: time="2025-06-22T10:41:10+02:00" level=debug msg="app state loaded" Jun 22 10:41:10 volumio-egreat go-librespot[5288]: time="2025-06-22T10:41:10+02:00" level=debug msg="stored credentials not found" Jun 22 10:41:10 volumio-egreat go-librespot[5288]: time="2025-06-22T10:41:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:41:10 volumio-egreat go-librespot[5288]: time="2025-06-22T10:41:10+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 22 10:41:10 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:41:10 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:41:10 volumio-egreat ntpd[4926]: Deleting interface #3 wlan0, 192.168.2.138#123, interface stats: received=116, sent=126, dropped=0, active_time=58 secs Jun 22 10:41:10 volumio-egreat ntpd[4926]: 149.156.70.60 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 188.165.17.91 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 46.174.178.150 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 89.25.168.148 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 212.127.78.21 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 89.161.47.136 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 193.59.134.156 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 91.212.242.20 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 85.115.212.250 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 195.46.37.22 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 91.212.242.21 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 212.127.95.218 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 194.146.251.100 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 85.115.212.254 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 162.159.200.1 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 213.222.217.11 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 91.210.128.220 local addr 192.168.2.138 -> Jun 22 10:41:10 volumio-egreat ntpd[4926]: 85.115.212.251 local addr 192.168.2.138 -> Jun 22 10:41:11 volumio-egreat wpa_supplicant[1135]: wlan0: Trying to associate with 08:bf:b8:8e:9b:ac (SSID='RBS-24' freq=2457 MHz) Jun 22 10:41:11 volumio-egreat wpa_supplicant[1135]: wlan0: Associated with 08:bf:b8:8e:9b:ac Jun 22 10:41:11 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jun 22 10:41:11 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Jun 22 10:41:11 volumio-egreat wpa_supplicant[1135]: wlan0: WPA: Key negotiation completed with 08:bf:b8:8e:9b:ac [PTK=CCMP GTK=CCMP] Jun 22 10:41:11 volumio-egreat wpa_supplicant[1135]: wlan0: CTRL-EVENT-CONNECTED - Connection to 08:bf:b8:8e:9b:ac completed [id=0 id_str=] Jun 22 10:41:11 volumio-egreat dhcpcd[1057]: wlan0: carrier acquired Jun 22 10:41:11 volumio-egreat dhcpcd[1057]: wlan0: IAID 09:01:29:36 Jun 22 10:41:11 volumio-egreat dhcpcd[1057]: wlan0: soliciting an IPv6 router Jun 22 10:41:11 volumio-egreat dhcpcd[1057]: wlan0: rebinding lease of 192.168.2.138 Jun 22 10:41:11 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:41:11 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:41:11 volumio-egreat dhcpcd[1057]: wlan0: probing address 192.168.2.138/24 Jun 22 10:41:13 volumio-egreat systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 22 10:41:13 volumio-egreat systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 80. Jun 22 10:41:13 volumio-egreat systemd[1]: Stopped go-librespot Daemon. Jun 22 10:41:13 volumio-egreat systemd[1]: Started go-librespot Daemon. Jun 22 10:41:13 volumio-egreat go-librespot[5300]: go-librespot daemon starting... Jun 22 10:41:13 volumio-egreat go-librespot[5300]: time="2025-06-22T10:41:13+02:00" level=info msg="running go-librespot 0.2.0" Jun 22 10:41:13 volumio-egreat go-librespot[5300]: time="2025-06-22T10:41:13+02:00" level=debug msg="app state loaded" Jun 22 10:41:13 volumio-egreat go-librespot[5300]: time="2025-06-22T10:41:13+02:00" level=debug msg="stored credentials not found" Jun 22 10:41:13 volumio-egreat go-librespot[5300]: time="2025-06-22T10:41:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 10:41:13 volumio-egreat go-librespot[5300]: time="2025-06-22T10:41:13+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 22 10:41:13 volumio-egreat systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 22 10:41:13 volumio-egreat systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 22 10:41:14 volumio-egreat volumio[2926]: info: Initializing connection to go-librespot Websocket Jun 22 10:41:14 volumio-egreat volumio[2926]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 22 10:41:15 volumio-egreat volumio[2926]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 22 10:41:15 volumio-egreat volumio[2926]: Error: send ENETUNREACH 255.255.255.255:3483 Jun 22 10:41:15 volumio-egreat volumio[2926]: at doSend (dgram.js:714:16) Jun 22 10:41:15 volumio-egreat volumio[2926]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:452:18) Jun 22 10:41:15 volumio-egreat volumio[2926]: at afterDns (dgram.js:660:5) Jun 22 10:41:15 volumio-egreat volumio[2926]: at processTicksAndRejections (internal/process/task_queues.js:83:21) { Jun 22 10:41:15 volumio-egreat volumio[2926]: errno: -101, Jun 22 10:41:15 volumio-egreat volumio[2926]: code: 'ENETUNREACH', Jun 22 10:41:15 volumio-egreat volumio[2926]: syscall: 'send', Jun 22 10:41:15 volumio-egreat volumio[2926]: address: '255.255.255.255', Jun 22 10:41:15 volumio-egreat volumio[2926]: port: 3483 Jun 22 10:41:15 volumio-egreat volumio[2926]: } Jun 22 10:41:15 volumio-egreat volumio[2926]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 22 10:41:16 volumio-egreat sudo[5316]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-22 10:40 Jun 22 10:41:16 volumio-egreat sudo[5316]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 10:41:16 volumio-egreat dhcpcd[1057]: wlan0: leased 192.168.2.138 for 86400 seconds PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 05:26:48 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="a63f40325536655a08b14de2b295ce76"