Oct 23 19:10:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Oct 23 19:10:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:00 volumio go-librespot[2957]: go-librespot daemon starting... Oct 23 19:10:00 volumio go-librespot[2958]: time="2025-10-23T19:10:00+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:00 volumio go-librespot[2958]: time="2025-10-23T19:10:00+02:00" level=debug msg="app state loaded" Oct 23 19:10:00 volumio go-librespot[2958]: time="2025-10-23T19:10:00+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:00 volumio go-librespot[2958]: time="2025-10-23T19:10:00+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" Oct 23 19:10:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:10:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:10:01 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:01 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: AggregateError Oct 23 19:10:04 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Oct 23 19:10:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:04 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: AggregateError Oct 23 19:10:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:04 volumio go-librespot[2964]: go-librespot daemon starting... Oct 23 19:10:04 volumio go-librespot[2965]: time="2025-10-23T19:10:04+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:04 volumio go-librespot[2965]: time="2025-10-23T19:10:04+02:00" level=debug msg="app state loaded" Oct 23 19:10:04 volumio go-librespot[2965]: time="2025-10-23T19:10:04+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:04 volumio go-librespot[2965]: time="2025-10-23T19:10:04+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" Oct 23 19:10:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:10:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:10:07 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:07 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: AggregateError Oct 23 19:10:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Oct 23 19:10:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:07 volumio go-librespot[2974]: go-librespot daemon starting... Oct 23 19:10:07 volumio go-librespot[2975]: time="2025-10-23T19:10:07+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:07 volumio go-librespot[2975]: time="2025-10-23T19:10:07+02:00" level=debug msg="app state loaded" Oct 23 19:10:07 volumio go-librespot[2975]: time="2025-10-23T19:10:07+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:07 volumio go-librespot[2975]: time="2025-10-23T19:10:07+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" Oct 23 19:10:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:10:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:10:07 volumio volumio[2309]: info: CALLMETHOD: system_controller network saveWirelessNet [object Object] Oct 23 19:10:07 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: network , saveWirelessNet Oct 23 19:10:07 volumio sudo[2983]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/network/interfaces Oct 23 19:10:07 volumio sudo[2983]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:07 volumio sudo[2983]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:07 volumio sudo[2985]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/dhcpcd.conf Oct 23 19:10:07 volumio sudo[2985]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:07 volumio sudo[2985]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:07 volumio volumio[2309]: info: Permissions for /etc/network/interfaces set Oct 23 19:10:07 volumio volumio[2309]: info: Restarting Wireless Network Oct 23 19:10:07 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , onNetworkingRestart Oct 23 19:10:07 volumio volumio[2309]: info: Discovery: Restarting Advertising due to device name change Oct 23 19:10:07 volumio sudo[2988]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart wireless.service Oct 23 19:10:07 volumio sudo[2988]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:07 volumio systemd[1]: Stopping wireless.service - Wireless Services... Oct 23 19:10:07 volumio systemd[1]: wireless.service: Deactivated successfully. Oct 23 19:10:07 volumio systemd[1]: Stopped wireless.service - Wireless Services. Oct 23 19:10:07 volumio systemd[1]: Starting wireless.service - Wireless Services... Oct 23 19:10:07 volumio wireless.js[2990]: WIRELESS.JS: Single Network Mode enabled, only one network device can be active at a time between ethernet and wireless Oct 23 19:10:07 volumio wireless.js[2990]: WIRELESS.JS: Wireless.js initializing wireless flow Oct 23 19:10:07 volumio wireless.js[2990]: WIRELESS.JS: Cleaning previous... Oct 23 19:10:07 volumio sudo[3008]: root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/ip addr flush dev wlan0 Oct 23 19:10:07 volumio sudo[3008]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 23 19:10:07 volumio sudo[3008]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:07 volumio sudo[3010]: root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/ifconfig wlan0 down Oct 23 19:10:07 volumio sudo[3010]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 23 19:10:07 volumio sudo[3010]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:07 volumio wireless.js[2990]: WIRELESS.JS: Stopped aP Oct 23 19:10:07 volumio sudo[3018]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Oct 23 19:10:07 volumio sudo[3018]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:07 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 23 19:10:07 volumio sudo[3018]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:07 volumio sudo[3020]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Oct 23 19:10:07 volumio sudo[3020]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:07 volumio sudo[3020]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:07 volumio sudo[3028]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Oct 23 19:10:07 volumio sudo[3028]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:07 volumio sudo[3028]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:07 volumio sudo[3030]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Oct 23 19:10:07 volumio sudo[3030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:08 volumio volumio[2309]: info: Discovery: A device disappeared from network Oct 23 19:10:08 volumio volumio[2309]: info: Discovery: Device volumio disappeared from network Oct 23 19:10:10 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:10 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: AggregateError Oct 23 19:10:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Oct 23 19:10:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:10 volumio sudo[3030]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:10 volumio wireless.js[2990]: WIRELESS.JS: SETTING APPROPRIATE REG DOMAIN: PL Oct 23 19:10:10 volumio sudo[3051]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Oct 23 19:10:10 volumio sudo[3051]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:10 volumio sudo[3051]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:10 volumio sudo[3053]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set PL Oct 23 19:10:10 volumio sudo[3053]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:10 volumio go-librespot[3048]: go-librespot daemon starting... Oct 23 19:10:10 volumio sudo[3053]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:10 volumio go-librespot[3056]: time="2025-10-23T19:10:10+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:10 volumio go-librespot[3056]: time="2025-10-23T19:10:10+02:00" level=debug msg="app state loaded" Oct 23 19:10:10 volumio go-librespot[3056]: time="2025-10-23T19:10:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:10 volumio wireless.js[2990]: WIRELESS.JS: SUCCESSFULLY SET NEW REGDOMAIN: PL Oct 23 19:10:10 volumio go-librespot[3056]: time="2025-10-23T19:10: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" Oct 23 19:10:10 volumio wireless.js[2990]: WIRELESS.JS: Start wireless flow Oct 23 19:10:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:10:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:10:10 volumio wireless.js[2990]: WIRELESS.JS: Stopped hotspot (if there).. Oct 23 19:10:10 volumio sudo[3067]: root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/ip addr flush dev wlan0 Oct 23 19:10:10 volumio sudo[3067]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 23 19:10:10 volumio sudo[3067]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:10 volumio sudo[3069]: root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/ifconfig wlan0 down Oct 23 19:10:10 volumio sudo[3069]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 23 19:10:10 volumio sudo[3069]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:10 volumio wireless.js[2990]: WIRELESS.JS: DHCP IP fallback Oct 23 19:10:10 volumio wireless.js[2990]: WIRELESS.JS: Start ap Oct 23 19:10:10 volumio wpa_supplicant[3074]: Successfully initialized wpa_supplicant Oct 23 19:10:10 volumio sudo[3075]: root : PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Oct 23 19:10:10 volumio sudo[3075]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 23 19:10:10 volumio dhcpcd[1068]: control_free: No such file or directory Oct 23 19:10:10 volumio dhcpcd[1068]: control command: /sbin/dhcpcd Oct 23 19:10:10 volumio sudo[3075]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:10 volumio dhcpcd[1068]: lo: IAID 00:00:00:00 Oct 23 19:10:10 volumio dhcpcd[1068]: lo: adding address fe80::fbbf:7644:48f3:64c9 Oct 23 19:10:10 volumio dhcpcd[1068]: ipv6_addaddr1: Permission denied Oct 23 19:10:10 volumio dhcpcd[1068]: lo: using static address 127.0.0.1/8 Oct 23 19:10:10 volumio dhcpcd[1068]: lo: adding route to 127.0.0.0/8 Oct 23 19:10:10 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 23 19:10:10 volumio systemd[1]: Reached target ip-changed@lo.target - IP Address changed on lo. Oct 23 19:10:11 volumio wpa_supplicant[3074]: nl80211: kernel reports: Registration to specific type not supported Oct 23 19:10:11 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:11 volumio sudo[3101]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:11 volumio sudo[3101]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:11 volumio sudo[3101]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:12 volumio volumio[2309]: info: Discovery: Started advertising with name: Volumio Oct 23 19:10:12 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:12 volumio sudo[3106]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:12 volumio sudo[3106]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:12 volumio sudo[3106]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:13 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:13 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: AggregateError Oct 23 19:10:13 volumio volumio[2309]: info: Discovery: adding 0b32e340-2dd3-42f0-887a-13542d2c5d69 Oct 23 19:10:13 volumio volumio[2309]: info: Discovery: Found device Volumio Oct 23 19:10:13 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:13 volumio volumio[2309]: info: CorePlayQueue::getTrack 0 Oct 23 19:10:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Oct 23 19:10:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:13 volumio go-librespot[3109]: go-librespot daemon starting... Oct 23 19:10:13 volumio go-librespot[3110]: time="2025-10-23T19:10:13+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:13 volumio go-librespot[3110]: time="2025-10-23T19:10:13+02:00" level=debug msg="app state loaded" Oct 23 19:10:13 volumio go-librespot[3110]: time="2025-10-23T19:10:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:13 volumio go-librespot[3110]: time="2025-10-23T19:10: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" Oct 23 19:10:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:10:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:10:13 volumio wpa_supplicant[3098]: wlan0: Trying to associate with d0:6d:c9:75:32:00 (SSID='BigPrivateHome24' freq=5520 MHz) Oct 23 19:10:13 volumio wpa_supplicant[3098]: wlan0: Associated with d0:6d:c9:75:32:00 Oct 23 19:10:13 volumio wpa_supplicant[3098]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Oct 23 19:10:13 volumio wpa_supplicant[3098]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=PL Oct 23 19:10:13 volumio wpa_supplicant[3098]: wlan0: WPA: Key negotiation completed with d0:6d:c9:75:32:00 [PTK=CCMP GTK=CCMP] Oct 23 19:10:13 volumio wpa_supplicant[3098]: wlan0: CTRL-EVENT-CONNECTED - Connection to d0:6d:c9:75:32:00 completed [id=0 id_str=] Oct 23 19:10:13 volumio dhcpcd[1068]: wlan0: carrier acquired Oct 23 19:10:13 volumio dhcpcd[1068]: wlan0: connected to Access Point: BigPrivateHome24 Oct 23 19:10:13 volumio dhcpcd[1068]: wlan0: config file changed, expiring leases Oct 23 19:10:13 volumio dhcpcd[1068]: wlan0: IAID dd:cc:4b:f1 Oct 23 19:10:13 volumio dhcpcd[1068]: wlan0: adding address fe80::54ba:6931:efdd:38cc Oct 23 19:10:13 volumio dhcpcd[1068]: ipv6_addaddr1: Permission denied Oct 23 19:10:13 volumio dhcpcd[1068]: wlan0: soliciting an IPv6 router Oct 23 19:10:13 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:13 volumio sudo[3119]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:13 volumio sudo[3119]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:13 volumio sudo[3119]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:14 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:14 volumio sudo[3123]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:14 volumio sudo[3123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:14 volumio sudo[3123]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:15 volumio dhcpcd[1068]: wlan0: rebinding lease of 192.168.1.113 Oct 23 19:10:15 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:15 volumio sudo[3129]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:15 volumio sudo[3129]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:15 volumio sudo[3129]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:16 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:16 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: AggregateError Oct 23 19:10:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. Oct 23 19:10:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:16 volumio go-librespot[3131]: go-librespot daemon starting... Oct 23 19:10:16 volumio go-librespot[3132]: time="2025-10-23T19:10:16+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:16 volumio go-librespot[3132]: time="2025-10-23T19:10:16+02:00" level=debug msg="app state loaded" Oct 23 19:10:16 volumio go-librespot[3132]: time="2025-10-23T19:10:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:16 volumio go-librespot[3132]: time="2025-10-23T19:10:16+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" Oct 23 19:10:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:10:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:10:16 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:16 volumio sudo[3140]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:16 volumio sudo[3140]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:16 volumio sudo[3140]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:17 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:17 volumio sudo[3144]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:17 volumio sudo[3144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:17 volumio sudo[3144]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:18 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:18 volumio sudo[3148]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:18 volumio sudo[3148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:18 volumio sudo[3148]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:19 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:19 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: AggregateError Oct 23 19:10:19 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:19 volumio sudo[3166]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:19 volumio sudo[3166]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:19 volumio sudo[3166]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. Oct 23 19:10:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:20 volumio dhcpcd[1068]: wlan0: probing address 192.168.1.113/24 Oct 23 19:10:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:20 volumio go-librespot[3168]: go-librespot daemon starting... Oct 23 19:10:20 volumio go-librespot[3169]: time="2025-10-23T19:10:20+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:20 volumio go-librespot[3169]: time="2025-10-23T19:10:20+02:00" level=debug msg="app state loaded" Oct 23 19:10:20 volumio go-librespot[3169]: time="2025-10-23T19:10:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:20 volumio go-librespot[3169]: time="2025-10-23T19:10:20+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" Oct 23 19:10:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:10:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:10:20 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:20 volumio sudo[3177]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:20 volumio sudo[3177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:20 volumio sudo[3177]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:21 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:21 volumio sudo[3181]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:21 volumio sudo[3181]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:21 volumio sudo[3181]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:22 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:22 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: AggregateError Oct 23 19:10:22 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:22 volumio sudo[3185]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:22 volumio sudo[3185]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:22 volumio sudo[3185]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33. Oct 23 19:10:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:23 volumio go-librespot[3187]: go-librespot daemon starting... Oct 23 19:10:23 volumio go-librespot[3188]: time="2025-10-23T19:10:23+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:23 volumio go-librespot[3188]: time="2025-10-23T19:10:23+02:00" level=debug msg="app state loaded" Oct 23 19:10:23 volumio go-librespot[3188]: time="2025-10-23T19:10:23+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:23 volumio go-librespot[3188]: time="2025-10-23T19:10:23+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" Oct 23 19:10:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:10:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:10:23 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:23 volumio sudo[3206]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:23 volumio sudo[3206]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:23 volumio sudo[3206]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:24 volumio dhcpcd[1068]: wlan0: leased 192.168.1.113 for 86400 seconds Oct 23 19:10:24 volumio avahi-daemon[955]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.113. Oct 23 19:10:24 volumio avahi-daemon[955]: New relevant interface wlan0.IPv4 for mDNS. Oct 23 19:10:24 volumio avahi-daemon[955]: Registering new address record for 192.168.1.113 on wlan0.IPv4. Oct 23 19:10:24 volumio dhcpcd[1068]: wlan0: adding route to 192.168.1.0/24 Oct 23 19:10:24 volumio systemd[1]: welcome.service: Deactivated successfully. Oct 23 19:10:24 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Oct 23 19:10:24 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Oct 23 19:10:24 volumio dhcpcd[1068]: wlan0: adding default route via 192.168.1.1 Oct 23 19:10:24 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Oct 23 19:10:24 volumio welcome[3220]: Resolved ip:[1] 192.168.1.113 Oct 23 19:10:24 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Oct 23 19:10:24 volumio systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Oct 23 19:10:24 volumio wireless.js[2990]: WIRELESS.JS: trying... Oct 23 19:10:24 volumio sudo[3240]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 23 19:10:24 volumio sudo[3240]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:24 volumio sudo[3240]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:24 volumio wireless.js[2990]: WIRELESS.JS: Connected to: ----BigPrivateHome24---- Oct 23 19:10:24 volumio sudo[3243]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 23 19:10:24 volumio sudo[3243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 23 19:10:24 volumio sudo[3243]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:24 volumio wireless.js[2990]: WIRELESS.JS: ... joined AP, wlan0 IPv4 is 192.168.1.113, ipV6 is undefined Oct 23 19:10:24 volumio wireless.js[2990]: WIRELESS.JS: It's done! AP Oct 23 19:10:25 volumio wireless.js[2990]: WIRELESS.JS: Restarting avahi-daemon... Oct 23 19:10:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 23 19:10:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 23 19:10:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 23 19:10:25 volumio systemd[1]: shairport-sync.service: Consumed 1.588s CPU time. Oct 23 19:10:25 volumio avahi-daemon[955]: Got SIGTERM, quitting. Oct 23 19:10:25 volumio avahi-daemon[955]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.113. Oct 23 19:10:25 volumio avahi-daemon[955]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1. Oct 23 19:10:25 volumio systemd[1]: Stopping avahi-daemon.service - Avahi mDNS/DNS-SD Stack... Oct 23 19:10:25 volumio volumio[2309]: error: Discovery: Advertisement error: Error: dns service error: unknown Oct 23 19:10:25 volumio volumio[2309]: error: Discovery: advertisement error: Error: dns service error: unknown Oct 23 19:10:25 volumio volumio[2309]: info: Discovery: Advertisement raised the following error Error: dns service error: unknown Oct 23 19:10:25 volumio volumio[2309]: info: Discovery: Browse raised the following error Error: dns service error: unknown Oct 23 19:10:25 volumio avahi-daemon[955]: avahi-daemon 0.8 exiting. Oct 23 19:10:25 volumio volumio[2309]: info: Discovery: Browse raised the following error Error: dns service error: unknown Oct 23 19:10:25 volumio dbus-daemon[957]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' requested by ':1.35' (uid=0 pid=1446 comm="/usr/sbin/smbd --foreground --no-process-group") Oct 23 19:10:25 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:25 volumio volumio[2309]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:10:25 volumio systemd[1]: avahi-daemon.service: Deactivated successfully. Oct 23 19:10:25 volumio systemd[1]: Stopped avahi-daemon.service - Avahi mDNS/DNS-SD Stack. Oct 23 19:10:25 volumio wireless.js[2990]: WIRELESS.JS: Notified systemd about wireless ready Oct 23 19:10:25 volumio systemd[1]: Started wireless.service - Wireless Services. Oct 23 19:10:25 volumio sudo[2988]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:25 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 23 19:10:25 volumio systemd[1]: Starting avahi-daemon.service - Avahi mDNS/DNS-SD Stack... Oct 23 19:10:25 volumio avahi-daemon[3251]: Process 955 died: No such process; trying to remove PID file. (/run/avahi-daemon//pid) Oct 23 19:10:25 volumio avahi-daemon[3251]: Found user 'avahi' (UID 103) and group 'avahi' (GID 109). Oct 23 19:10:25 volumio avahi-daemon[3251]: Successfully dropped root privileges. Oct 23 19:10:25 volumio avahi-daemon[3251]: avahi-daemon 0.8 starting up. Oct 23 19:10:25 volumio dbus-daemon[957]: [system] Successfully activated service 'org.freedesktop.Avahi' Oct 23 19:10:25 volumio systemd[1]: Started avahi-daemon.service - Avahi mDNS/DNS-SD Stack. Oct 23 19:10:25 volumio avahi-daemon[3251]: Successfully called chroot(). Oct 23 19:10:25 volumio avahi-daemon[3251]: Successfully dropped remaining capabilities. Oct 23 19:10:25 volumio avahi-daemon[3251]: No service file found in /etc/avahi/services. Oct 23 19:10:25 volumio avahi-daemon[3251]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.113. Oct 23 19:10:25 volumio avahi-daemon[3251]: New relevant interface wlan0.IPv4 for mDNS. Oct 23 19:10:25 volumio avahi-daemon[3251]: Joining mDNS multicast group on interface lo.IPv4 with address 127.0.0.1. Oct 23 19:10:25 volumio avahi-daemon[3251]: New relevant interface lo.IPv4 for mDNS. Oct 23 19:10:25 volumio avahi-daemon[3251]: Network interface enumeration completed. Oct 23 19:10:25 volumio avahi-daemon[3251]: Registering new address record for 192.168.1.113 on wlan0.IPv4. Oct 23 19:10:25 volumio avahi-daemon[3251]: Registering new address record for 127.0.0.1 on lo.IPv4. Oct 23 19:10:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 23 19:10:25 volumio avahi-daemon[3251]: Server startup complete. Host name is volumio.local. Local service cookie is 2281158178. Oct 23 19:10:26 volumio ntpd[1184]: IO: Listen normally on 3 wlan0 192.168.1.113:123 Oct 23 19:10:26 volumio ntpd[1184]: IO: new interface(s) found: waking up resolver Oct 23 19:10:26 volumio ntpd[1184]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Oct 23 19:10:26 volumio ntpd[1184]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Oct 23 19:10:26 volumio ntpd[1184]: DNS: Pool taking: 194.146.251.114 Oct 23 19:10:26 volumio ntpd[1184]: DNS: Pool taking: 162.159.200.123 Oct 23 19:10:26 volumio ntpd[1184]: DNS: Pool taking: 162.159.200.1 Oct 23 19:10:26 volumio ntpd[1184]: DNS: Pool taking: 51.68.141.5 Oct 23 19:10:26 volumio ntpd[1184]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Oct 23 19:10:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34. Oct 23 19:10:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:10:26 volumio go-librespot[3269]: go-librespot daemon starting... Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+02:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+02:00" level=debug msg="app state loaded" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 23 19:10:26 volumio volumio[2309]: info: Adding plugin bluetooth to MyMusic Plugins Oct 23 19:10:26 volumio volumio[2309]: info: Adding plugin multiroom to MyMusic Plugins Oct 23 19:10:26 volumio volumio[2309]: info: Adding plugin metavolumio to MyMusic Plugins Oct 23 19:10:26 volumio volumio[2309]: info: Adding plugin cd_controller to MyMusic Plugins Oct 23 19:10:26 volumio volumio[2309]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 23 19:10:26 volumio volumio[2309]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 23 19:10:26 volumio volumio[2309]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 23 19:10:26 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+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]" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+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]" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+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]" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+02:00" level=info msg="zeroconf server listening on port 36137" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+02:00" level=debug msg="obtained new client token: AAAguryK8vK/hKG2umAJVCGn3jYksg8A8VRfwU+iO/YJC15AFAwklavaLJF1k/Acx6nEe3TY8OIUikx08HEpd7tlAyEBfVzQQsSO4ZAplKRuhPwMNSysmkUDfq0Q8q9OBO/rcbL73TyARJdc7CEAZ8MAIrV8XxGE40EjijhBgmAT27hXjJk10oi8yteGV39y5c34QhEWfyqUcBrpz08vkvGDdY6eEDqX2vJk+OXc14BTDbATPZktcaalXQ==" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+02:00" level=debug msg="completed keyexchange" Oct 23 19:10:26 volumio go-librespot[3270]: time="2025-10-23T19:10:26+02:00" level=debug msg="completed challenge" Oct 23 19:10:27 volumio volumio[2309]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 23 19:10:27 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 23 19:10:27 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:27 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:27 volumio volumio[2309]: info: Starting MyVolumio Remote Streaming Endpoints Oct 23 19:10:27 volumio volumio[2309]: info: MyVolumio login type: Token Oct 23 19:10:27 volumio volumio[2309]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 23 19:10:27 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=info msg="authenticated AP" username="pi*********sz" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=info msg="authenticated Login5" username="pi*********sz" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="initializing zeroconf session" username="pi*********sz" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="dealer connection opened" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=trace msg="starting accesspoint recv loop" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=trace msg="starting dealer recv loop" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=trace msg="received accesspoint ping" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="received connection id: NzQwNTRhYTktODMz...MUJFMUQwODUzNg==" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=trace msg="received accesspoint pong ack" Oct 23 19:10:27 volumio volumio[2309]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 23 19:10:27 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 23 19:10:27 volumio volumio[2309]: info: Streaming services startup Oct 23 19:10:27 volumio volumio[2309]: info: Starting Streaming Daemon Oct 23 19:10:27 volumio sudo[3278]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 23 19:10:27 volumio sudo[3278]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:27 volumio volumio[2309]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 23 19:10:27 volumio sudo[3278]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:27 volumio volumio[2309]: error: Cannot start Volumio Streaming Daemon Oct 23 19:10:27 volumio volumio[2309]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 23 19:10:27 volumio volumio[2309]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="update volume requested to 65535/65535" Oct 23 19:10:27 volumio ntpd[1184]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Oct 23 19:10:27 volumio volumio[2309]: error: MyVolumio Custom Token format not valid, refreshing it Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 23 19:10:27 volumio go-librespot[3270]: time="2025-10-23T19:10:27+02:00" level=trace msg="emitting websocket event: volume" Oct 23 19:10:27 volumio ntpd[1184]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Oct 23 19:10:27 volumio ntpd[1184]: DNS: Pool taking: 195.46.37.22 Oct 23 19:10:27 volumio ntpd[1184]: DNS: Pool taking: 94.240.10.55 Oct 23 19:10:27 volumio ntpd[1184]: DNS: Pool skipping: 162.159.200.123 Oct 23 19:10:27 volumio ntpd[1184]: DNS: Pool taking: 94.154.96.7 Oct 23 19:10:27 volumio ntpd[1184]: DNS: Pool taking: 2001:678:8::123 Oct 23 19:10:27 volumio ntpd[1184]: DNS: Pool taking: 2a00:d5c0:10:10::136 Oct 23 19:10:27 volumio ntpd[1184]: DNS: Pool taking: 2a05:9404::15e Oct 23 19:10:27 volumio ntpd[1184]: DNS: Pool taking: 2001:41d0:601:1100::649c Oct 23 19:10:27 volumio ntpd[1184]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Oct 23 19:10:28 volumio volumio[2309]: info: Initializing connection to go-librespot Websocket Oct 23 19:10:28 volumio go-librespot[3270]: time="2025-10-23T19:10:28+02:00" level=debug msg="new websocket client" Oct 23 19:10:28 volumio volumio[2309]: info: Connection to go-librespot Websocket established Oct 23 19:10:28 volumio volumio[2309]: info: MyVolumio login type: Token Oct 23 19:10:28 volumio ntpd[1184]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Oct 23 19:10:28 volumio ntpd[1184]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Oct 23 19:10:28 volumio ntpd[1184]: DNS: Pool taking: 89.161.47.136 Oct 23 19:10:28 volumio ntpd[1184]: DNS: Pool taking: 212.127.78.21 Oct 23 19:10:28 volumio ntpd[1184]: DNS: Pool taking: 46.175.224.7 Oct 23 19:10:28 volumio ntpd[1184]: DNS: Pool taking: 156.17.20.254 Oct 23 19:10:28 volumio ntpd[1184]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Oct 23 19:10:28 volumio volumio[2309]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 23 19:10:29 volumio volumio[2309]: info: MyVolumio token set successfully Oct 23 19:10:29 volumio volumio[2309]: info: MYVOLUMIO: Adding device Oct 23 19:10:29 volumio volumio[2309]: info: MYVOLUMIO: Evaluating Server Oct 23 19:10:29 volumio volumio[2309]: info: MyVolumio Plan changed: premium Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Oct 23 19:10:29 volumio volumio[2309]: info: Removing browser output: myVolumio user plan is not superstar Oct 23 19:10:29 volumio volumio[2309]: info: Removing audio output: Oct 23 19:10:29 volumio volumio[2309]: info: MYVOLUMIO: Adding device Oct 23 19:10:29 volumio volumio[2309]: info: MYVOLUMIO: Evaluating Server Oct 23 19:10:29 volumio volumio[2309]: info: Remote config written successfully Oct 23 19:10:29 volumio volumio[2309]: info: Starting Tunnel 1 Oct 23 19:10:29 volumio volumio[2309]: info: Starting Tunnel Connection Checker Oct 23 19:10:29 volumio volumio[2309]: info: MYVolumio Device enabled Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Oct 23 19:10:29 volumio volumio[2309]: info: MyVolumio status changed Oct 23 19:10:29 volumio volumio[2309]: info: Streaming services startup Oct 23 19:10:29 volumio volumio[2309]: info: Starting Streaming Daemon Oct 23 19:10:29 volumio volumio[2309]: info: Volumio Network Manager: Network status updated: 2 Oct 23 19:10:29 volumio sudo[3352]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 23 19:10:29 volumio sudo[3352]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:29 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Oct 23 19:10:29 volumio sudo[3352]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:29 volumio volumio[2309]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Oct 23 19:10:29 volumio ntpd[1184]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Oct 23 19:10:29 volumio ntpd[1184]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Oct 23 19:10:29 volumio ntpd[1184]: DNS: Pool taking: 193.70.94.182 Oct 23 19:10:29 volumio ntpd[1184]: DNS: Pool taking: 89.250.197.242 Oct 23 19:10:29 volumio ntpd[1184]: DNS: Pool taking: 91.212.242.20 Oct 23 19:10:29 volumio ntpd[1184]: DNS: Pool skipping: 212.127.78.21 Oct 23 19:10:29 volumio ntpd[1184]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Oct 23 19:10:29 volumio sudo[3357]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Oct 23 19:10:29 volumio sudo[3357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:29 volumio sudo[3357]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:29 volumio volumio[2309]: info: MRS: MultiRoom plugin initialized Oct 23 19:10:29 volumio volumio[2309]: info: MRS: STOPPING SNAPCLIENT Oct 23 19:10:29 volumio volumio[2309]: info: MRS: Snap server stop Oct 23 19:10:29 volumio volumio[2309]: info: MRS: STOPPING volumioStreaming Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Oct 23 19:10:29 volumio sudo[3375]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Oct 23 19:10:29 volumio sudo[3376]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Oct 23 19:10:29 volumio sudo[3376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:29 volumio sudo[3375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Oct 23 19:10:29 volumio sudo[3378]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Oct 23 19:10:29 volumio sudo[3378]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:29 volumio sudo[3380]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Oct 23 19:10:29 volumio sudo[3380]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Oct 23 19:10:29 volumio sudo[3380]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Oct 23 19:10:29 volumio sudo[3378]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Oct 23 19:10:29 volumio sudo[3376]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:29 volumio sudo[3375]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Oct 23 19:10:29 volumio volumio[2309]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Oct 23 19:10:29 volumio volumio[2309]: info: Preparing to generate the ALSA configuration file Oct 23 19:10:29 volumio volumio[2309]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Oct 23 19:10:29 volumio volumio[2309]: info: Reading ALSA contributions from plugins. Oct 23 19:10:29 volumio volumio[2309]: info: Setting Geolocation for MyVolumio to eu5 Oct 23 19:10:29 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:29 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:29 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:29 volumio volumio[2309]: info: Setting Geolocation for MyVolumio to eu5 Oct 23 19:10:29 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:29 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:29 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:29 volumio volumio[2309]: info: MRS: Removed streaming files Oct 23 19:10:29 volumio volumio[2309]: info: MRS: volumioStreaming STOPPED Oct 23 19:10:29 volumio volumio[2309]: info: MRS: SNAPSERVER STOPPED Oct 23 19:10:29 volumio volumio[2309]: info: MRS: SNAPCLIENT STOPPED Oct 23 19:10:29 volumio volumio[2309]: error: Cannot start Volumio Streaming Daemon Oct 23 19:10:29 volumio volumio[2309]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 23 19:10:29 volumio volumio[2309]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 23 19:10:29 volumio volumio[2309]: info: Asound.conf file written Oct 23 19:10:29 volumio sudo[3389]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Oct 23 19:10:29 volumio sudo[3389]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:29 volumio sudo[3389]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:29 volumio volumio[2309]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 23 19:10:29 volumio volumio[2309]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Oct 23 19:10:29 volumio volumio[2309]: info: Output device has changed, restarting MPD Oct 23 19:10:30 volumio volumio[2309]: info: Output device has changed, restarting Shairport Sync Oct 23 19:10:30 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:30 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:30 volumio sudo[3395]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 23 19:10:30 volumio sudo[3395]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:30 volumio sudo[3395]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:30 volumio sudo[3397]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 23 19:10:30 volumio sudo[3397]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:30 volumio volumio[2309]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 23 19:10:30 volumio volumio[2309]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 23 19:10:30 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:30 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 23 19:10:30 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Oct 23 19:10:30 volumio volumio[2309]: ------------------------------------ BT MESSAGE: [FUNC] onStart Oct 23 19:10:30 volumio volumio[2309]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Oct 23 19:10:30 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 23 19:10:30 volumio volumio[2309]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Oct 23 19:10:30 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 23 19:10:30 volumio volumio[2309]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Oct 23 19:10:30 volumio volumio[2309]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Oct 23 19:10:30 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 23 19:10:30 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 23 19:10:30 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 23 19:10:30 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Oct 23 19:10:30 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Oct 23 19:10:30 volumio volumio[2309]: info: MRS: Pushing multiroomSync output for this device Oct 23 19:10:30 volumio volumio[2309]: info: MRS: Pushing multiroomSync output Oct 23 19:10:30 volumio volumio[2309]: info: Adding audio output: Oct 23 19:10:30 volumio volumio[2309]: info: Adding audio output: Oct 23 19:10:30 volumio volumio[2309]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 23 19:10:30 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:30 volumio bluetoothd[956]: Path / reserved for Adv Monitor app :1.40 Oct 23 19:10:30 volumio bluetoothd[956]: Adv Monitor app :1.40 disconnected from D-Bus Oct 23 19:10:30 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 23 19:10:30 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 23 19:10:30 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Oct 23 19:10:30 volumio volumio[2309]: info: Adding METAVOLUMIO REST API Endpoints Oct 23 19:10:30 volumio volumio[2309]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Oct 23 19:10:30 volumio volumio[2309]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Oct 23 19:10:30 volumio volumio[2309]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Oct 23 19:10:30 volumio volumio[2309]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Oct 23 19:10:30 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Oct 23 19:10:30 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Oct 23 19:10:30 volumio volumio[2309]: info: Preparing CD Folders Oct 23 19:10:30 volumio volumio[2309]: info: Adding CD REST API Endpoints Oct 23 19:10:30 volumio volumio[2309]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Oct 23 19:10:30 volumio volumio[2309]: info: Starting UDEV Watcher for CD Oct 23 19:10:30 volumio volumio[2309]: info: Detecting CD presence with UDEV Oct 23 19:10:30 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Oct 23 19:10:30 volumio sudo[3411]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 23 19:10:30 volumio sudo[3411]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 23 19:10:30 volumio sudo[3411]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:30 volumio mpd[3417]: 2025-10-23T19:10:30 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 23 19:10:30 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 23 19:10:30 volumio sudo[3397]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:32 volumio ntpd[1184]: CLOCK: time stepped by -0.264301 Oct 23 19:10:32 volumio ntpd[1184]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Oct 23 19:10:32 volumio upmpdcli[3420]: writing RSA key Oct 23 19:10:34 volumio volumio[2309]: warn: [cd-plugin] cdspeedctl: device or media not ready Oct 23 19:10:34 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Oct 23 19:10:34 volumio volumio[2309]: info: Adding inputs REST Endpoints Oct 23 19:10:34 volumio volumio[2309]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Oct 23 19:10:34 volumio volumio[2309]: info: Scanning Audio Inputs Oct 23 19:10:34 volumio volumio[2309]: info: Checking against Known Cards name Oct 23 19:10:34 volumio volumio[2309]: info: Adding Server instance for streaming Oct 23 19:10:34 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Oct 23 19:10:34 volumio volumio[2309]: error: Hi Res Audio Failed Login: Missing Login Data Oct 23 19:10:34 volumio volumio[2309]: info: Adding HIGHRESAUDIO REST API Endpoints Oct 23 19:10:34 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Oct 23 19:10:34 volumio volumio[2309]: info: Refreshing TIDAL token Oct 23 19:10:34 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Oct 23 19:10:34 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Oct 23 19:10:34 volumio volumio[2309]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Oct 23 19:10:34 volumio volumio[2309]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Oct 23 19:10:34 volumio volumio[2309]: info: QobuzConnect: Starting Qobuz Connect socket and service Oct 23 19:10:34 volumio sudo[3435]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 23 19:10:34 volumio sudo[3435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio volumio[2309]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Oct 23 19:10:34 volumio volumio[2309]: info: Stopping AccessToken refresher cron for QOBUZ Oct 23 19:10:34 volumio sudo[3442]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 23 19:10:34 volumio sudo[3442]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio volumio[2309]: info: AccessToken refresher cron started for QOBUZ Oct 23 19:10:34 volumio volumio[2309]: info: Adding QOBUZ REST API Endpoints Oct 23 19:10:34 volumio volumio[2309]: info: Discovery: Started advertising with name: Volumio Oct 23 19:10:34 volumio sudo[3442]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:34 volumio sudo[3435]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:34 volumio sudo[3445]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 23 19:10:34 volumio sudo[3445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: wizard , reportWirelessConnection Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessInfo Oct 23 19:10:34 volumio volumio[2309]: info: MRS: Getting audio outputs on start Oct 23 19:10:34 volumio volumio[2309]: info: MRS: Requesting all other devices output Oct 23 19:10:34 volumio volumio[2309]: info: Updating MyVolumio device info Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: Updating MyVolumio device info Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:34 volumio sudo[3449]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 23 19:10:34 volumio sudo[3449]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio volumio[2309]: info: Getting Spotify volume Oct 23 19:10:34 volumio sudo[3449]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: upnp , onRestart Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: network , onNetworkingRestart Oct 23 19:10:34 volumio volumio[2309]: info: Refreshing Cached IP Addresses Oct 23 19:10:34 volumio systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Oct 23 19:10:34 volumio sudo[3453]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/killall upmpdcli Oct 23 19:10:34 volumio sudo[3445]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:34 volumio sudo[3453]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio sudo[3455]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 23 19:10:34 volumio sudo[3455]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio sudo[3457]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 23 19:10:34 volumio sudo[3457]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio sudo[3453]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:34 volumio sudo[3455]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:34 volumio sudo[3457]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:34 volumio volumio[2309]: info: Successfully Added MyVolumio device Oct 23 19:10:34 volumio volumio[2309]: info: Successfully Added MyVolumio device Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 23 19:10:34 volumio volumio[2309]: info: Received Get System Info Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 19:10:34 volumio volumio[2309]: info: Discovery: Getting this device information Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:34 volumio volumio[2309]: info: CorePlayQueue::getTrack 0 Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 19:10:34 volumio sudo[3463]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 23 19:10:34 volumio sudo[3463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio sudo[3463]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:34 volumio volumio[2309]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Oct 23 19:10:34 volumio volumio[2309]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Oct 23 19:10:34 volumio volumio[2309]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Oct 23 19:10:34 volumio volumio[2309]: info: MPD Permissions set Oct 23 19:10:34 volumio sudo[3469]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Oct 23 19:10:34 volumio sudo[3469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:34 volumio volumio[2309]: info: Spotify volume: 100 Oct 23 19:10:34 volumio volumio[2309]: error: updateQueue error: null Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:34 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:35 volumio volumio[2309]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 23 19:10:35 volumio volumio[2309]: info: Starting Shairport Sync Oct 23 19:10:35 volumio sudo[3485]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Oct 23 19:10:35 volumio sudo[3485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:35 volumio systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Oct 23 19:10:35 volumio sudo[3469]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:35 volumio volumiobt[3489]: INFO [BTSTART] Ensuring Bluetooth directory exists... Oct 23 19:10:35 volumio sudo[3487]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 23 19:10:35 volumio sudo[3487]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:35 volumio sudo[3490]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Oct 23 19:10:35 volumio sudo[3490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:35 volumio sudo[3490]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:35 volumio volumio[2309]: info: Executing endpoint qc_getconfig Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Oct 23 19:10:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 23 19:10:35 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 23 19:10:35 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 23 19:10:35 volumio systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Oct 23 19:10:35 volumio sudo[3485]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:35 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 23 19:10:35 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 23 19:10:35 volumio systemd[1]: shairport-sync.service: Consumed 1.528s CPU time. Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.058 [3450.3450] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Oct 23 19:10:35 volumio sudo[3494]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Oct 23 19:10:35 volumio sudo[3494]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:35 volumio volumio[2309]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioStop Oct 23 19:10:35 volumio volumio[2309]: info: CoreStateMachine::stop Oct 23 19:10:35 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 23 19:10:35 volumio volumio[2309]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 19:10:35 volumio volumio[2309]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Oct 23 19:10:35 volumio volumio[2309]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 19:10:35 volumio sudo[3494]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:35 volumio volumiobt[3503]: INFO [BTSTART] Powering on Bluetooth if needed... Oct 23 19:10:35 volumio autossh[3498]: port set to 0, monitoring disabled Oct 23 19:10:35 volumio autossh[3498]: starting ssh (count 1) Oct 23 19:10:35 volumio autossh[3498]: ssh child pid is 3504 Oct 23 19:10:35 volumio sudo[3487]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:35 volumio volumio[2309]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Oct 23 19:10:35 volumio volumio[2309]: info: QobuzConnect: QOBUZ Connect daemon connected Oct 23 19:10:35 volumio volumio[2309]: info: Remote SSH Started Oct 23 19:10:35 volumio bluetoothd[956]: Adv Monitor app :1.44 disconnected from D-Bus Oct 23 19:10:35 volumio volumiobt[3521]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.109 [3450.3450] INFO VolumeManager: [0x1498368]: Setting new playback volume: 75 Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.110 [3450.3450] INFO VolumeManager: [0x1498368]: Setting new mute state: 0 Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.110 [3450.3450] INFO QobuzConnect: [0x1498d38]: Client initialized! Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.110 [3450.3450] INFO SampleApp: Starting Avahi advertising, name: Volumio, service name: _qobuz-connect._tcp Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.122 [3450.3450] INFO LocalConfigManager: [0x1497c48]: Starting Local Configuration server Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.122 [3450.3450] INFO SampleApp: Starting Local configuration server Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.122 [3450.3450] INFO SampleApp: Connected to UNIX socket client 0x1482818 Oct 23 19:10:35 volumio volumiobt[3522]: [176B blob data] Oct 23 19:10:35 volumio volumiobt[3522]: [157B blob data] Oct 23 19:10:35 volumio volumiobt[3522]: [157B blob data] Oct 23 19:10:35 volumio volumiobt[3522]: [157B blob data] Oct 23 19:10:35 volumio volumiobt[3522]: [113B blob data] Oct 23 19:10:35 volumio volumiobt[3522]: [bluetoothctl]> discoverable on Oct 23 19:10:35 volumio volumiobt[3522]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Oct 23 19:10:35 volumio volumiobt[3522]: [bluetoothctl]> pairable on Oct 23 19:10:35 volumio bluetoothd[956]: Path / reserved for Adv Monitor app :1.48 Oct 23 19:10:35 volumio bluetoothd[956]: Adv Monitor app :1.48 disconnected from D-Bus Oct 23 19:10:35 volumio volumiobt[3522]: [bluetoothctl]> Oct 23 19:10:35 volumio volumiobt[3525]: INFO [BTSTART] Registering Bluetooth agent... Oct 23 19:10:35 volumio volumiobt[3526]: [NEW] Media /org/bluez/hci0 Oct 23 19:10:35 volumio volumiobt[3526]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Oct 23 19:10:35 volumio volumiobt[3526]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Oct 23 19:10:35 volumio volumiobt[3526]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Oct 23 19:10:35 volumio volumio[2309]: info: Shairport-Sync Started Oct 23 19:10:35 volumio bluetoothd[956]: Adv Monitor app :1.49 disconnected from D-Bus Oct 23 19:10:35 volumio volumio[2309]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 23 19:10:35 volumio volumiobt[3527]: No agent is registered Oct 23 19:10:35 volumio volumiobt[3527]: [NEW] Media /org/bluez/hci0 Oct 23 19:10:35 volumio volumiobt[3527]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Oct 23 19:10:35 volumio volumiobt[3527]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Oct 23 19:10:35 volumio volumiobt[3527]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Oct 23 19:10:35 volumio bluetoothd[956]: Path / reserved for Adv Monitor app :1.50 Oct 23 19:10:35 volumio volumio[2309]: info: MRS: Found cast device: Google-Home-Mini-3ef6b982f1a15bdeb7a4443ebb5e9e87 Oct 23 19:10:35 volumio volumio[2309]: info: Adding audio output: Oct 23 19:10:35 volumio bluetoothd[956]: Adv Monitor app :1.50 disconnected from D-Bus Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:35 volumio volumiobt[3528]: INFO [BTSTART] Agent registered successfully. Oct 23 19:10:35 volumio volumiobt[3529]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:35 volumio volumio[2309]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.gpYJ4ZnQuEWTT2ByhbGrirkU8652.21ceb3731c061d7301f094ac35434edf.state.status' Oct 23 19:10:35 volumio qobuz-connect[3450]: 20251023 19:10:35.208 [3450.3450] INFO SampleApp: Playback volume changed: 75 Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:35 volumio volumio[2309]: info: Successfully Updated MyVolumio device Oct 23 19:10:35 volumio volumiossh-tunnel[3504]: Warning: Permanently added '[eu5.myvolumio.org]:2222' (RSA) to the list of known hosts. Oct 23 19:10:35 volumio sudo[3534]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 23 19:10:35 volumio sudo[3534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:35 volumio sudo[3534]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:35 volumio sudo[3532]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 23 19:10:35 volumio sudo[3532]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:35 volumio sudo[3532]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:35 volumio volumio[2309]: verbose: New Socket.io Connection to 192.168.1.113 from 192.168.1.10 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Oct 23 19:10:35 volumio volumiobt[3530]: INFO:a2dp-agent:Connecting to system bus. Oct 23 19:10:35 volumio volumiobt[3530]: INFO:a2dp-agent:Found Bluetooth adapter at: /org/bluez/hci0 Oct 23 19:10:35 volumio volumiobt[3530]: INFO:a2dp-agent:Enabling infinite discovery on adapter. Oct 23 19:10:35 volumio volumiobt[3530]: INFO:a2dp-agent:Registering agent. Oct 23 19:10:35 volumio volumiobt[3530]: INFO:a2dp-agent:Searching for MediaPlayer1 interface... Oct 23 19:10:35 volumio volumiobt[3530]: WARNING:a2dp-agent:No active MediaPlayer1 found. Metadata updates won't work. Oct 23 19:10:35 volumio volumio[2309]: info: Access Token successfully retrieved Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 23 19:10:35 volumio volumio[2309]: info: Successfully retrieved User Session From TIDAL Oct 23 19:10:35 volumio volumio[2309]: info: Successfully Updated MyVolumio device Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioGetVisibleSources Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 23 19:10:35 volumio volumio[2309]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Oct 23 19:10:35 volumio volumio[2309]: info: Received Get System Info Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 19:10:35 volumio volumio[2309]: info: Discovery: Getting this device information Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:35 volumio volumio[2309]: info: Listing playlists Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 23 19:10:35 volumio volumio[2309]: info: Successfully retrieved User Subscription From TIDAL Oct 23 19:10:35 volumio volumio[2309]: info: Adding TIDAL to Browse Sources Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 23 19:10:35 volumio volumio[2309]: info: [1761239435762] CoreMusicLibrary::Adding element TIDAL Oct 23 19:10:35 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 19:10:35 volumio volumio[2309]: Cannot find translation for source TIDAL Oct 23 19:10:35 volumio volumio[2309]: info: Stopping AccessToken refresher cron Oct 23 19:10:35 volumio volumio[2309]: info: AccessToken refresher cron started Oct 23 19:10:35 volumio volumio[2309]: info: Adding TIDAL REST API Endpoints Oct 23 19:10:36 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:37 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 23 19:10:37 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 23 19:10:37 volumio volumio[2309]: info: Received Get System Info Oct 23 19:10:37 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 19:10:37 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 19:10:37 volumio volumio[2309]: info: Discovery: Getting this device information Oct 23 19:10:37 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:37 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 19:10:37 volumio volumio[2309]: info: TidalConnect service stoped! Oct 23 19:10:37 volumio volumio[2309]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Oct 23 19:10:37 volumio volumio[2309]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Oct 23 19:10:37 volumio sudo[3546]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Oct 23 19:10:37 volumio sudo[3546]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:37 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Oct 23 19:10:37 volumio sudo[3546]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:37 volumio sudo[3552]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 23 19:10:37 volumio sudo[3552]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:37 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 23 19:10:37 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 23 19:10:37 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 23 19:10:37 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 23 19:10:37 volumio sudo[3552]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:37 volumio mpd_monitor.sh[3554]: MPD Monitor Service: Starting MPD Monitor Service Oct 23 19:10:37 volumio volumio[2309]: info: Successfully started MPD Monitor Oct 23 19:10:38 volumio volumio[2309]: info: Executing endpoint tc_getconfig Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Oct 23 19:10:38 volumio vtcs[3549]: STARTING TidalConnect services, version: 1.5.1-beta1 Oct 23 19:10:38 volumio vtcs[3549]: STARTED TidalConnect services. Oct 23 19:10:38 volumio volumio[2309]: info: Executing endpoint tc_connect Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Oct 23 19:10:38 volumio volumio[2309]: info: Connecting to TidalConnect Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::servicePushState Oct 23 19:10:38 volumio volumio[2309]: info: CoreStateMachine::pushState Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::volumioPushState Oct 23 19:10:38 volumio volumio[2309]: info: MRS: Pushing multiroomSync output update for this device Oct 23 19:10:38 volumio volumio[2309]: info: MRS: Pushing multiroomSync output Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:38 volumio volumio[2309]: info: CorePlayQueue::getTrack 0 Oct 23 19:10:38 volumio volumio[2309]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::servicePushState Oct 23 19:10:38 volumio volumio[2309]: info: CoreStateMachine::pushState Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::volumioPushState Oct 23 19:10:38 volumio volumio[2309]: info: MRS: Pushing multiroomSync output update for this device Oct 23 19:10:38 volumio volumio[2309]: info: MRS: Pushing multiroomSync output Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:38 volumio volumio[2309]: info: CorePlayQueue::getTrack 0 Oct 23 19:10:38 volumio volumio[2309]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect Oct 23 19:10:38 volumio volumio[2309]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.gpYJ4ZnQuEWTT2ByhbGrirkU8652.21ceb3731c061d7301f094ac35434edf.state.status' Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 23 19:10:38 volumio volumio[2309]: info: Received Get System Info Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 19:10:38 volumio volumio[2309]: info: Discovery: Getting this device information Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:38 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 19:10:40 volumio volumio[2309]: info: Executing endpoint metavolumio Oct 23 19:10:40 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 23 19:10:40 volumio volumio[2309]: info: TidalConnect service started! Oct 23 19:10:41 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 23 19:10:41 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 23 19:10:41 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 23 19:10:41 volumio volumio[2309]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 23 19:10:41 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:44 volumio sudo[3591]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 23 19:10:44 volumio sudo[3591]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:44 volumio sudo[3589]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 23 19:10:44 volumio sudo[3589]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:44 volumio sudo[3591]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:44 volumio sudo[3589]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:45 volumio sudo[3595]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 23 19:10:45 volumio sudo[3595]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:10:45 volumio sudo[3595]: pam_unix(sudo:session): session closed for user root Oct 23 19:10:45 volumio volumio[2309]: info: Upmpdcli Daemon Started Oct 23 19:10:45 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 23 19:10:46 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:46 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:10:46 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 23 19:10:46 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 23 19:10:46 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 23 19:10:46 volumio volumio[2309]: info: CoreCommandRouter::volumioGetBrowseSources Oct 23 19:10:46 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 23 19:10:51 volumio volumio[2309]: info: Starting Uninstall of plugin user_interface - now_playing Oct 23 19:10:53 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 23 19:10:53 volumio volumio[2309]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 23 19:10:53 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 23 19:10:53 volumio volumio[2309]: info: Received Get System Version Oct 23 19:10:53 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 23 19:10:53 volumio volumio[2309]: info: Received Get System Info Oct 23 19:10:53 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 19:10:53 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 19:10:53 volumio volumio[2309]: info: Discovery: Getting this device information Oct 23 19:10:53 volumio volumio[2309]: info: CoreCommandRouter::volumioGetState Oct 23 19:10:53 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 19:10:57 volumio go-librespot[3270]: time="2025-10-23T19:10:57+02:00" level=trace msg="sent dealer ping" Oct 23 19:10:57 volumio go-librespot[3270]: time="2025-10-23T19:10:57+02:00" level=trace msg="received dealer pong" Oct 23 19:10:59 volumio volumio[2309]: info: Enabling plugin now_playing Oct 23 19:10:59 volumio volumio[2309]: info: Loading plugin "now_playing"... Oct 23 19:10:59 volumio volumio[2309]: error: !!!! WARNING !!!! Oct 23 19:10:59 volumio volumio[2309]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module '/data/plugins//user_interface/now_playing/./dist/index.js' Oct 23 19:10:59 volumio volumio[2309]: Require stack: Oct 23 19:10:59 volumio volumio[2309]: - /volumio/app/pluginmanager.js Oct 23 19:10:59 volumio volumio[2309]: - /volumio/app/index.js Oct 23 19:10:59 volumio volumio[2309]: - /volumio/index.js Oct 23 19:10:59 volumio volumio[2309]: error: Stack trace: Error: Cannot find module '/data/plugins//user_interface/now_playing/./dist/index.js' Oct 23 19:10:59 volumio volumio[2309]: Require stack: Oct 23 19:10:59 volumio volumio[2309]: - /volumio/app/pluginmanager.js Oct 23 19:10:59 volumio volumio[2309]: - /volumio/app/index.js Oct 23 19:10:59 volumio volumio[2309]: - /volumio/index.js Oct 23 19:10:59 volumio volumio[2309]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Oct 23 19:10:59 volumio volumio[2309]: at Module._load (node:internal/modules/cjs/loader:901:27) Oct 23 19:10:59 volumio volumio[2309]: at Module.require (node:internal/modules/cjs/loader:1115:19) Oct 23 19:10:59 volumio volumio[2309]: at require (node:internal/modules/helpers:130:18) Oct 23 19:10:59 volumio volumio[2309]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Oct 23 19:10:59 volumio volumio[2309]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Oct 23 19:10:59 volumio volumio[2309]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 23 19:10:59 volumio volumio[2309]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Oct 23 19:10:59 volumio volumio[2309]: error: !!!! WARNING !!!! Oct 23 19:10:59 volumio volumio[2309]: info: Done. Oct 23 19:11:04 volumio volumio[2309]: info: Enabling plugin now_playing Oct 23 19:11:04 volumio volumio[2309]: info: Loading plugin "now_playing"... Oct 23 19:11:04 volumio volumio[2309]: error: !!!! WARNING !!!! Oct 23 19:11:04 volumio volumio[2309]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module '/data/plugins//user_interface/now_playing/./dist/index.js' Oct 23 19:11:04 volumio volumio[2309]: Require stack: Oct 23 19:11:04 volumio volumio[2309]: - /volumio/app/pluginmanager.js Oct 23 19:11:04 volumio volumio[2309]: - /volumio/app/index.js Oct 23 19:11:04 volumio volumio[2309]: - /volumio/index.js Oct 23 19:11:04 volumio volumio[2309]: error: Stack trace: Error: Cannot find module '/data/plugins//user_interface/now_playing/./dist/index.js' Oct 23 19:11:04 volumio volumio[2309]: Require stack: Oct 23 19:11:04 volumio volumio[2309]: - /volumio/app/pluginmanager.js Oct 23 19:11:04 volumio volumio[2309]: - /volumio/app/index.js Oct 23 19:11:04 volumio volumio[2309]: - /volumio/index.js Oct 23 19:11:04 volumio volumio[2309]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Oct 23 19:11:04 volumio volumio[2309]: at Module._load (node:internal/modules/cjs/loader:901:27) Oct 23 19:11:04 volumio volumio[2309]: at Module.require (node:internal/modules/cjs/loader:1115:19) Oct 23 19:11:04 volumio volumio[2309]: at require (node:internal/modules/helpers:130:18) Oct 23 19:11:04 volumio volumio[2309]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Oct 23 19:11:04 volumio volumio[2309]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Oct 23 19:11:04 volumio volumio[2309]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 23 19:11:04 volumio volumio[2309]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Oct 23 19:11:04 volumio volumio[2309]: error: !!!! WARNING !!!! Oct 23 19:11:04 volumio volumio[2309]: info: Error: TypeError: Cannot read properties of null (reading 'printToastMessage') Oct 23 19:11:17 volumio volumio[2309]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 23 19:11:25 volumio volumio[2309]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/download/now_playing/1.0.2/volumio/bookworm/armhf Oct 23 19:11:25 volumio volumio[2309]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 19:11:25 volumio volumio[2309]: TypeError: Cannot read properties of null (reading 'broadcastMessage') Oct 23 19:11:25 volumio volumio[2309]: at /volumio/app/index.js:1534:32 Oct 23 19:11:25 volumio volumio[2309]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Oct 23 19:11:25 volumio volumio[2309]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Oct 23 19:11:25 volumio volumio[2309]: at CoreCommandRouter.broadcastMessage (/volumio/app/index.js:1532:13) Oct 23 19:11:25 volumio volumio[2309]: at PluginManager.pushMessage (/volumio/app/pluginmanager.js:1594:20) Oct 23 19:11:25 volumio volumio[2309]: at PluginManager.installPlugin (/volumio/app/pluginmanager.js:776:8) Oct 23 19:11:25 volumio volumio[2309]: at CoreCommandRouter.installPlugin (/volumio/app/index.js:1453:22) Oct 23 19:11:25 volumio volumio[2309]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1209:47) Oct 23 19:11:25 volumio volumio[2309]: at Socket.emit (node:events:514:28) Oct 23 19:11:25 volumio volumio[2309]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Oct 23 19:11:25 volumio volumio[2309]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Oct 23 19:11:25 volumio volumio[2309]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 19:11:25 volumio sudo[3674]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-23 19:10' Oct 23 19:11:25 volumio sudo[3674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5ef3d56f987d109f3e21bfa246dbbb723cf6a917" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="c7bff9654d2984a81c5720476c2c8ac531869c54" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Oct 9 18:08:11 UTC 2025" VOLUMIO_VERSION="4.062" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="00524295c246b7d72f125e4c54b86a88"