-- Logs begin at Fri 2024-10-04 06:43:17 EDT, end at Fri 2024-10-04 16:11:17 EDT. -- Oct 04 16:10:03 volumiofr wpa_supplicant[943]: wlan0: CTRL-EVENT-DISCONNECTED bssid=e8:6f:f2:be:31:d2 reason=0 locally_generated=1 Oct 04 16:10:03 volumiofr dhcpcd[740]: wlan0: carrier lost Oct 04 16:10:03 volumiofr wpa_supplicant[943]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Oct 04 16:10:03 volumiofr wpa_supplicant[943]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=TW Oct 04 16:10:03 volumiofr avahi-daemon[651]: Withdrawing address record for 192.168.254.122 on wlan0. Oct 04 16:10:03 volumiofr avahi-daemon[651]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.254.122. Oct 04 16:10:03 volumiofr avahi-daemon[651]: Interface wlan0.IPv4 no longer relevant for mDNS. Oct 04 16:10:03 volumiofr dhcpcd[740]: wlan0: deleting route to 192.168.254.0/24 Oct 04 16:10:03 volumiofr dhcpcd[740]: wlan0: deleting default route via 192.168.254.254 Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: A device disappeared from network Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: A device disappeared from network Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: Device volumio-garage disappeared from network Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: Disconnected from remote: 192.168.254.66 Oct 04 16:10:03 volumiofr volumio[18221]: info: MRS: Cleaning up device: 228eec69-74e8-4f9d-9116-1083bb37aaf5 Oct 04 16:10:03 volumiofr volumio[18221]: info: Removing audio output: Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: A device disappeared from network Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: Device stealth disappeared from network Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: Disconnected from remote: 192.168.254.119 Oct 04 16:10:03 volumiofr volumio[18221]: info: MRS: Cleaning up device: 6c154f72-88f5-4490-b4bc-21802e71dc63 Oct 04 16:10:03 volumiofr volumio[18221]: info: Removing audio output: Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: A device disappeared from network Oct 04 16:10:03 volumiofr volumio[18221]: info: Discovery: Device volumiofr disappeared from network Oct 04 16:10:03 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:10:03 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:10:03 volumiofr autossh[24732]: starting ssh (count 3) Oct 04 16:10:03 volumiofr autossh[24732]: ssh child pid is 24883 Oct 04 16:10:03 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:10:03 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:10:03 volumiofr autossh[24732]: starting ssh (count 4) Oct 04 16:10:03 volumiofr autossh[24732]: ssh child pid is 24884 Oct 04 16:10:03 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:10:03 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:10:03 volumiofr autossh[24732]: starting ssh (count 5) Oct 04 16:10:03 volumiofr autossh[24732]: ssh child pid is 24885 Oct 04 16:10:03 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:10:03 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:10:03 volumiofr autossh[24732]: starting ssh (count 6) Oct 04 16:10:03 volumiofr autossh[24732]: ssh child pid is 24886 Oct 04 16:10:03 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:10:03 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:10:04 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 04 16:10:04 volumiofr volumio[18221]: 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 04 16:10:04 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Oct 04 16:10:04 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Oct 04 16:10:04 volumiofr go-librespot[24798]: time="2024-10-04T16:10:04-04:00" level=debug msg="new websocket client" Oct 04 16:10:05 volumiofr volumio[18221]: info: Connection to go-librespot Websocket established Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 14 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 16 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 17 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 18 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 19 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 20 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 21 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 22 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 23 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 24 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 25 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 26 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 27 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 28 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 29 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 30 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 31 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 32 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 33 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 34 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 35 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 36 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 37 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 38 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 39 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 40 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 41 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 42 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 43 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 44 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 45 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 46 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 47 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 48 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 49 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 50 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 51 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 52 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 53 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 54 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 55 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 56 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 57 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 58 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 59 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 60 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 61 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 62 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 63 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 64 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 65 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 66 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 67 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 68 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 69 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 70 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 71 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 72 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 73 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 74 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 75 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 76 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 77 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 78 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 79 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 80 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 81 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 82 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 83 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 84 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 85 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 86 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 87 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 88 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 89 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 90 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 91 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 92 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 93 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 94 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 95 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 96 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 97 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 98 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 99 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 100 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 101 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 102 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 103 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 104 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 105 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 106 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 107 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 108 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 109 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 110 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 111 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 112 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 113 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 114 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 115 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 116 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 117 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 118 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 119 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 120 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 121 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 122 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 123 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 124 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 125 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 126 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 127 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 128 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 129 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 130 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 131 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 132 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 133 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 134 Oct 04 16:10:05 volumiofr ntpd[828]: Deleting interface #20 wlan0, 192.168.254.122#123, interface stats: received=53, sent=84, dropped=0, active_time=5831 secs Oct 04 16:10:05 volumiofr ntpd[828]: 168.61.215.74 local addr 192.168.254.122 -> Oct 04 16:10:05 volumiofr ntpd[828]: 209.253.210.114 local addr 192.168.254.122 -> Oct 04 16:10:05 volumiofr ntpd[828]: 161.35.230.200 local addr 192.168.254.122 -> Oct 04 16:10:05 volumiofr ntpd[828]: 216.229.4.69 local addr 192.168.254.122 -> Oct 04 16:10:05 volumiofr ntpd[828]: 162.159.200.123 local addr 192.168.254.122 -> Oct 04 16:10:05 volumiofr ntpd[828]: 152.70.159.102 local addr 192.168.254.122 -> Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 135 Oct 04 16:10:05 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 136 Oct 04 16:10:05 volumiofr autossh[24732]: starting ssh (count 7) Oct 04 16:10:05 volumiofr autossh[24732]: ssh child pid is 24888 Oct 04 16:10:05 volumiofr volumio[18221]: info: CoreCommandRouter::volumioGetState Oct 04 16:10:05 volumiofr volumio[18221]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:05 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:10:05 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:10:05 volumiofr volumio[18221]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 04 16:10:06 volumiofr volumio[18221]: info: Discovery: Disconnected from remote: 192.168.254.120 Oct 04 16:10:06 volumiofr volumio[18221]: info: MRS: Cleaning up device: b69dca05-4a3f-43a5-b69b-322021478566 Oct 04 16:10:06 volumiofr volumio[18221]: info: Removing audio output: Oct 04 16:10:07 volumiofr volumio[18221]: info: Discovery: Remote connection error: 192.168.254.120 Oct 04 16:10:08 volumiofr volumio[18221]: info: Getting Spotify volume Oct 04 16:10:08 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 137 Oct 04 16:10:08 volumiofr volumio[18221]: info: CoreCommandRouter::volumioGetState Oct 04 16:10:08 volumiofr volumio[18221]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:08 volumiofr volumio[18221]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 04 16:10:09 volumiofr go-librespot[24798]: time="2024-10-04T16:10:09-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:09 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:09 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:09 volumiofr volumio[18221]: (node:18221) UnhandledPromiseRejectionWarning: Error: socket hang up Oct 04 16:10:09 volumiofr volumio[18221]: at connResetException (internal/errors.js:607:14) Oct 04 16:10:09 volumiofr volumio[18221]: at Socket.socketOnEnd (_http_client.js:493:23) Oct 04 16:10:09 volumiofr volumio[18221]: at Socket.emit (events.js:327:22) Oct 04 16:10:09 volumiofr volumio[18221]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 04 16:10:09 volumiofr volumio[18221]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 04 16:10:09 volumiofr volumio[18221]: (node:18221) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 28) Oct 04 16:10:09 volumiofr volumio[18221]: info: Connection to go-librespot Websocket closed Oct 04 16:10:09 volumiofr volumio[18221]: info: Discovery: Remote connection error: 192.168.254.120 Oct 04 16:10:10 volumiofr volumio[18221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 137 Oct 04 16:10:10 volumiofr volumio[18221]: info: CoreCommandRouter::volumioGetState Oct 04 16:10:10 volumiofr volumio[18221]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:12 volumiofr volumio[18221]: info: Initializing connection to go-librespot Websocket Oct 04 16:10:12 volumiofr volumio[18221]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 04 16:10:12 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:12 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 107. Oct 04 16:10:12 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:12 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:12 volumiofr go-librespot[24898]: Librespot-go daemon starting... Oct 04 16:10:12 volumiofr go-librespot[24898]: time="2024-10-04T16:10:12-04:00" level=info msg="generated new device id: e060be1bafe65f214a063afdf87602a75302fb6b" Oct 04 16:10:12 volumiofr go-librespot[24898]: time="2024-10-04T16:10:12-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:12 volumiofr go-librespot[24898]: time="2024-10-04T16:10:12-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:12 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:12 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:13 volumiofr autossh[24732]: starting ssh (count 8) Oct 04 16:10:13 volumiofr autossh[24732]: ssh child pid is 24905 Oct 04 16:10:13 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:10:13 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:10:14 volumiofr volumio[18221]: info: Discovery: Remote connection error: 192.168.254.120 Oct 04 16:10:15 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:15 volumiofr volumio[18221]: info: Initializing connection to go-librespot Websocket Oct 04 16:10:15 volumiofr volumio[18221]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 04 16:10:15 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:15 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 108. Oct 04 16:10:15 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:15 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:15 volumiofr go-librespot[24906]: Librespot-go daemon starting... Oct 04 16:10:15 volumiofr go-librespot[24906]: time="2024-10-04T16:10:15-04:00" level=info msg="generated new device id: c07b0f27fad8b063fb6248ac5027606dd2cc259c" Oct 04 16:10:15 volumiofr go-librespot[24906]: time="2024-10-04T16:10:15-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:16 volumiofr go-librespot[24906]: time="2024-10-04T16:10:16-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:16 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:16 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:18 volumiofr volumio[18221]: info: Initializing connection to go-librespot Websocket Oct 04 16:10:18 volumiofr volumio[18221]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 04 16:10:19 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:19 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 109. Oct 04 16:10:19 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:19 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:19 volumiofr go-librespot[24913]: Librespot-go daemon starting... Oct 04 16:10:19 volumiofr go-librespot[24913]: time="2024-10-04T16:10:19-04:00" level=info msg="generated new device id: c77e095366801e483d2289fc594d32d8329a4cf8" Oct 04 16:10:19 volumiofr go-librespot[24913]: time="2024-10-04T16:10:19-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:19 volumiofr go-librespot[24913]: time="2024-10-04T16:10:19-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:19 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:19 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:19 volumiofr volumio[18221]: info: Discovery: Remote connection error: 192.168.254.120 Oct 04 16:10:20 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:21 volumiofr volumio[18221]: info: Initializing connection to go-librespot Websocket Oct 04 16:10:21 volumiofr volumio[18221]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 04 16:10:22 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:22 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 110. Oct 04 16:10:22 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:22 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:22 volumiofr go-librespot[24920]: Librespot-go daemon starting... Oct 04 16:10:22 volumiofr go-librespot[24920]: time="2024-10-04T16:10:22-04:00" level=info msg="generated new device id: 6013d92e3a9cc677f734e0c75a9d9781c7bc36c3" Oct 04 16:10:22 volumiofr go-librespot[24920]: time="2024-10-04T16:10:22-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:22 volumiofr go-librespot[24920]: time="2024-10-04T16:10:22-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:22 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:22 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:24 volumiofr volumio[18221]: info: Initializing connection to go-librespot Websocket Oct 04 16:10:24 volumiofr volumio[18221]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 04 16:10:24 volumiofr volumio[18221]: info: Discovery: Remote connection error: 192.168.254.120 Oct 04 16:10:25 volumiofr volumio[18221]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:10:25 volumiofr volumio[18221]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 04 16:10:25 volumiofr volumio[18221]: at doSend (dgram.js:692:16) Oct 04 16:10:25 volumiofr volumio[18221]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 04 16:10:25 volumiofr volumio[18221]: at afterDns (dgram.js:638:5) Oct 04 16:10:25 volumiofr volumio[18221]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 04 16:10:25 volumiofr volumio[18221]: errno: -101, Oct 04 16:10:25 volumiofr volumio[18221]: code: 'ENETUNREACH', Oct 04 16:10:25 volumiofr volumio[18221]: syscall: 'send', Oct 04 16:10:25 volumiofr volumio[18221]: address: '255.255.255.255', Oct 04 16:10:25 volumiofr volumio[18221]: port: 3483 Oct 04 16:10:25 volumiofr volumio[18221]: } Oct 04 16:10:25 volumiofr volumio[18221]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:10:25 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:25 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 111. Oct 04 16:10:25 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:25 volumiofr sudo[24937]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-04 16:09 Oct 04 16:10:25 volumiofr sudo[24937]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:25 volumiofr sudo[24937]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:25 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:25 volumiofr go-librespot[24936]: Librespot-go daemon starting... Oct 04 16:10:25 volumiofr go-librespot[24936]: time="2024-10-04T16:10:25-04:00" level=info msg="generated new device id: fa4c63a96a869aa93e9797a05924b708e204879b" Oct 04 16:10:25 volumiofr go-librespot[24936]: time="2024-10-04T16:10:25-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:25 volumiofr go-librespot[24936]: time="2024-10-04T16:10:25-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:25 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:25 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:25 volumiofr volumio-remote-updater[639]: [2024-10-04 16:10:25] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 04 16:10:25 volumiofr volumio-remote-updater[639]: [2024-10-04 16:10:25] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 04 16:10:25 volumiofr systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:25 volumiofr systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 04 16:10:26 volumiofr systemd[1]: Started dynamicswap service. Oct 04 16:10:26 volumiofr systemd[1]: dynamicswap.service: Succeeded. Oct 04 16:10:26 volumiofr systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 04 16:10:26 volumiofr systemd[1]: volumio.service: Scheduled restart job, restart counter is at 73. Oct 04 16:10:26 volumiofr systemd[1]: Stopped Volumio Backend Module. Oct 04 16:10:26 volumiofr systemd[1]: Started Volumio Backend Module. Oct 04 16:10:26 volumiofr systemd[1]: Started dynamicswap service. Oct 04 16:10:26 volumiofr systemd[1]: dynamicswap.service: Succeeded. Oct 04 16:10:26 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:28 volumiofr volumio[24957]: info: ------------------------------------------- Oct 04 16:10:28 volumiofr volumio[24957]: info: ----- Volumio3 ---- Oct 04 16:10:28 volumiofr volumio[24957]: info: ------------------------------------------- Oct 04 16:10:28 volumiofr volumio[24957]: info: ----- System startup ---- Oct 04 16:10:28 volumiofr volumio[24957]: info: ------------------------------------------- Oct 04 16:10:28 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:28 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 112. Oct 04 16:10:28 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:28 volumiofr volumio[24957]: info: MYVOLUMIO Environment detected Oct 04 16:10:28 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:28 volumiofr go-librespot[24978]: Librespot-go daemon starting... Oct 04 16:10:29 volumiofr go-librespot[24978]: time="2024-10-04T16:10:29-04:00" level=info msg="generated new device id: ecb953120dafb3f027f0840906a9b44245e31406" Oct 04 16:10:29 volumiofr go-librespot[24978]: time="2024-10-04T16:10:29-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:29 volumiofr go-librespot[24978]: time="2024-10-04T16:10:29-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:29 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:29 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:29 volumiofr volumio[24957]: info: Plugin folders cleanup Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning into folder /volumio/app/plugins/ Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category audio_interface Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category miscellanea Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category music_service Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category plugins.json Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category system_controller Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category user_interface Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning into folder /data/plugins/ Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category audio_interface Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category miscellanea Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category music_service Oct 04 16:10:29 volumiofr volumio[24957]: info: Scanning category user_interface Oct 04 16:10:29 volumiofr volumio[24957]: info: Plugin folders cleanup completed Oct 04 16:10:29 volumiofr volumio[24957]: info: ------------------------------------------- Oct 04 16:10:29 volumiofr volumio[24957]: info: ----- Core plugins startup ---- Oct 04 16:10:29 volumiofr volumio[24957]: info: ------------------------------------------- Oct 04 16:10:29 volumiofr volumio[24957]: info: Loading plugins from folder /volumio/app/plugins/ Oct 04 16:10:29 volumiofr volumio[24957]: info: Adding plugin upnp to MyMusic Plugins Oct 04 16:10:29 volumiofr volumio[24957]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 04 16:10:29 volumiofr volumio[24957]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 04 16:10:29 volumiofr volumio[24957]: info: Loading plugins from folder /data/plugins/ Oct 04 16:10:29 volumiofr volumio[24957]: info: Loading plugin "system"... Oct 04 16:10:29 volumiofr volumio[24957]: info: Loading plugin "appearance"... Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "network"... Oct 04 16:10:30 volumiofr volumio[24957]: info: Refreshing Cached IP Addresses Oct 04 16:10:30 volumiofr sudo[24992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 04 16:10:30 volumiofr sudo[24992]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:30 volumiofr sudo[24994]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 04 16:10:30 volumiofr volumio[24957]: info: Plugin peppy_screensaver is not enabled Oct 04 16:10:30 volumiofr sudo[24994]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "services"... Oct 04 16:10:30 volumiofr sudo[24992]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:30 volumiofr sudo[24994]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "alsa_controller"... Oct 04 16:10:30 volumiofr sudo[24997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 04 16:10:30 volumiofr sudo[24997]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:30 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "wizard"... Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "networkfs"... Oct 04 16:10:30 volumiofr volumio[24957]: info: Cannot mount NAS OpenMediaVault at system boot, trial number 1 ,retrying in 5 seconds Oct 04 16:10:30 volumiofr volumio[24957]: info: Starting Udev Watcher for removable devices Oct 04 16:10:30 volumiofr volumio[24957]: info: Ignoring mount for partition: boot Oct 04 16:10:30 volumiofr volumio[24957]: info: Ignoring mount for partition: volumio Oct 04 16:10:30 volumiofr volumio[24957]: info: Ignoring mount for partition: volumio_data Oct 04 16:10:30 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "volumio_command_line_client"... Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "upnp"... Oct 04 16:10:30 volumiofr volumio[24957]: info: [1728072630784] Starting Upmpd Daemon Oct 04 16:10:30 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "my_music"... Oct 04 16:10:30 volumiofr volumio[24957]: info: Loading plugin "mpd"... Oct 04 16:10:30 volumiofr volumio-remote-updater[639]: [2024-10-04 16:10:30] [connect] Successful connection Oct 04 16:10:31 volumiofr sudo[24997]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:31 volumiofr volumio[24957]: info: Loading plugin "upnp_browser"... Oct 04 16:10:31 volumiofr volumio[24957]: info: Loading plugin "alarm-clock"... Oct 04 16:10:31 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:31 volumiofr nmbd[811]: [2024/10/04 16:10:31.859874, 0] ../source3/nmbd/nmbd.c:361(reload_interfaces) Oct 04 16:10:31 volumiofr nmbd[811]: reload_interfaces: No subnets to listen to. Waiting.. Oct 04 16:10:31 volumiofr volumio[24957]: info: Loading plugin "airplay_emulation"... Oct 04 16:10:31 volumiofr volumio[24957]: info: Starting Shairport Sync Oct 04 16:10:31 volumiofr volumio[24957]: info: Loading plugin "last_100"... Oct 04 16:10:31 volumiofr volumio[24957]: info: Loading plugin "webradio"... Oct 04 16:10:31 volumiofr autossh[24732]: starting ssh (count 9) Oct 04 16:10:31 volumiofr autossh[24732]: ssh child pid is 25005 Oct 04 16:10:32 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:10:32 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:10:32 volumiofr volumio[24957]: info: Loading plugin "i2s_dacs"... Oct 04 16:10:32 volumiofr volumio[24957]: info: I2S DAC not set, start Auto-detection Oct 04 16:10:32 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:32 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 113. Oct 04 16:10:32 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:32 volumiofr volumio[24957]: info: Loading plugin "volumiodiscovery"... Oct 04 16:10:32 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:32 volumiofr go-librespot[25006]: Librespot-go daemon starting... Oct 04 16:10:32 volumiofr volumio[24957]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:32 volumiofr volumio[24957]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:32 volumiofr volumio[24957]: *** WARNING *** For more information see Oct 04 16:10:32 volumiofr node[24957]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:32 volumiofr volumio[24957]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:32 volumiofr volumio[24957]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:32 volumiofr volumio[24957]: *** WARNING *** For more information see Oct 04 16:10:32 volumiofr node[24957]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:32 volumiofr node[24957]: *** WARNING *** For more information see Oct 04 16:10:32 volumiofr node[24957]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:32 volumiofr node[24957]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:32 volumiofr node[24957]: *** WARNING *** For more information see Oct 04 16:10:32 volumiofr volumio[24957]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 04 16:10:32 volumiofr go-librespot[25006]: time="2024-10-04T16:10:32-04:00" level=info msg="generated new device id: 29736a5b0737787074e6cbad6d3324a74f629f2f" Oct 04 16:10:32 volumiofr go-librespot[25006]: time="2024-10-04T16:10:32-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:32 volumiofr volumio[24957]: info: Discovery: Started advertising with name: VolumioFR Oct 04 16:10:32 volumiofr go-librespot[25006]: time="2024-10-04T16:10:32-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:32 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:32 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:32 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:32 volumiofr volumio[24957]: info: Loading plugin "spop"... Oct 04 16:10:33 volumiofr volumio[24957]: info: Loading plugin "squeezelite_mc"... Oct 04 16:10:34 volumiofr volumio[24957]: info: Plugin now_playing is not enabled Oct 04 16:10:34 volumiofr volumio[24957]: info: Loading plugin "outputs"... Oct 04 16:10:34 volumiofr volumio[24957]: info: Loading plugin "albumart"... Oct 04 16:10:35 volumiofr volumio[24957]: info: Plugin example_plugin is not enabled Oct 04 16:10:35 volumiofr volumio[24957]: info: Loading plugin "inputs"... Oct 04 16:10:35 volumiofr volumio[24957]: info: Loading plugin "updater_comm"... Oct 04 16:10:35 volumiofr volumio[24957]: info: Plugin mpdemulation is not enabled Oct 04 16:10:35 volumiofr volumio[24957]: info: Loading plugin "rest_api"... Oct 04 16:10:35 volumiofr volumio[24957]: info: Loading plugin "websocket"... Oct 04 16:10:35 volumiofr volumio[24957]: info: Starting Socket.io Server version 2.3.0 Oct 04 16:10:35 volumiofr volumio[24957]: info: Loading plugin "fusiondsp"... Oct 04 16:10:35 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:35 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 114. Oct 04 16:10:35 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:35 volumiofr volumio[24957]: Forking 3 albumart workers Oct 04 16:10:35 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:35 volumiofr go-librespot[25022]: Librespot-go daemon starting... Oct 04 16:10:35 volumiofr go-librespot[25022]: time="2024-10-04T16:10:35-04:00" level=info msg="generated new device id: a2e15d8f8b77a4839596de45a5b6a1cf30dd7278" Oct 04 16:10:35 volumiofr go-librespot[25022]: time="2024-10-04T16:10:35-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:35 volumiofr go-librespot[25022]: time="2024-10-04T16:10:35-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:35 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:35 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:35 volumiofr volumio[24957]: info: Applying required configuration parameters for plugin fusiondsp Oct 04 16:10:36 volumiofr volumio[24957]: info: Loading plugin "RoonBridge"... Oct 04 16:10:36 volumiofr volumio[24957]: Starting albumart workers Oct 04 16:10:36 volumiofr volumio[24957]: Starting albumart workers Oct 04 16:10:36 volumiofr volumio[24957]: info: Applying required configuration parameters for plugin RoonBridge Oct 04 16:10:36 volumiofr volumio[24957]: info: Loading plugin "radio_paradise"... Oct 04 16:10:36 volumiofr volumio[24957]: Starting albumart workers Oct 04 16:10:37 volumiofr volumio[24957]: info: Applying required configuration parameters for plugin radio_paradise Oct 04 16:10:37 volumiofr volumio[24957]: info: [1728072637091] [RadioParadise] API delay: 5 Oct 04 16:10:37 volumiofr volumio[24957]: info: Plugin touch_display is not enabled Oct 04 16:10:37 volumiofr volumio[24957]: info: Loading i18n strings for locale en Oct 04 16:10:37 volumiofr volumio[24957]: Updating browse sources language Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:37 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::initPlayerControls Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: Express server listening on port 3000 Oct 04 16:10:37 volumiofr volumio[24957]: [Metrics] WebUI: 9s 990.68ms Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreStateMachine::resetVolumioState Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreStateMachine::getcurrentVolume Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:37 volumiofr volumio[24957]: info: Cannot mount NAS OpenMediaVault at system boot, trial number 2 ,retrying in 5 seconds Oct 04 16:10:37 volumiofr volumio[24957]: info: Reloading queue from file Oct 04 16:10:37 volumiofr volumio[24957]: info: Setting Device type: Raspberry PI Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreStateMachine::setRepeat null single undefined Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreStateMachine::pushState Oct 04 16:10:37 volumiofr volumio[24957]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreStateMachine::setRandom true Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreStateMachine::pushState Oct 04 16:10:37 volumiofr volumio[24957]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:37 volumiofr volumio[24957]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreStateMachine::pushState Oct 04 16:10:37 volumiofr volumio[24957]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreStateMachine::updateTrackBlock Oct 04 16:10:37 volumiofr volumio[24957]: info: CorePlayQueue::getTrackBlock Oct 04 16:10:37 volumiofr volumio[24957]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:10:37 volumiofr volumio[24957]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 04 16:10:37 volumiofr volumio[24957]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 04 16:10:37 volumiofr volumio[24957]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 04 16:10:37 volumiofr volumio[24957]: info: Completed loading Core Plugins Oct 04 16:10:37 volumiofr volumio[24957]: info: Preparing to generate the ALSA configuration file Oct 04 16:10:37 volumiofr volumio[24957]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 04 16:10:37 volumiofr volumio[24957]: info: Reading ALSA contributions from plugins. Oct 04 16:10:37 volumiofr volumio[24957]: info: Asound.conf file written Oct 04 16:10:38 volumiofr sudo[25086]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Oct 04 16:10:38 volumiofr sudo[25086]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:38 volumiofr sudo[25086]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:38 volumiofr volumio[24957]: info: Output device has changed, restarting MPD Oct 04 16:10:38 volumiofr sudo[25091]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 04 16:10:38 volumiofr sudo[25091]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:38 volumiofr volumio[24957]: info: Output device has changed, restarting Shairport Sync Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:38 volumiofr sudo[25091]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:38 volumiofr sudo[25094]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 04 16:10:38 volumiofr sudo[25094]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:38 volumiofr systemd[1]: Stopping Music Player Daemon... Oct 04 16:10:38 volumiofr volumio[24957]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:10:38 volumiofr volumio[24957]: info: ___________ START PLUGINS ___________ Oct 04 16:10:38 volumiofr systemd[1]: mpd.service: Succeeded. Oct 04 16:10:38 volumiofr systemd[1]: Stopped Music Player Daemon. Oct 04 16:10:38 volumiofr volumio[24957]: info: ControllerMpd::onStart: Initializing MPD Oct 04 16:10:38 volumiofr volumio[24957]: info: Creating MPD Configuration file Oct 04 16:10:38 volumiofr sudo[25101]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 04 16:10:38 volumiofr sudo[25101]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:38 volumiofr systemd[1]: Starting Music Player Daemon... Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:10:38 volumiofr volumio[24957]: info: [1728072638295] CoreMusicLibrary::Adding element Media Servers Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:38 volumiofr sudo[25101]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:38 volumiofr sudo[25104]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 04 16:10:38 volumiofr sudo[25104]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:38 volumiofr systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 04 16:10:38 volumiofr systemd[1]: mpd.service: Succeeded. Oct 04 16:10:38 volumiofr systemd[1]: Stopped Music Player Daemon. Oct 04 16:10:38 volumiofr systemd[1]: Starting Music Player Daemon... Oct 04 16:10:38 volumiofr volumio[24957]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:38 volumiofr volumio[24957]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:10:38 volumiofr volumio[24957]: info: [1728072638449] CoreMusicLibrary::Adding element Last_100 Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:10:38 volumiofr volumio[24957]: info: [1728072638453] CoreMusicLibrary::Adding element Webradio Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:10:38 volumiofr volumio[24957]: info: Initializing BBC Radios Oct 04 16:10:38 volumiofr sudo[25109]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 04 16:10:38 volumiofr sudo[25109]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:38 volumiofr sudo[25109]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:38 volumiofr volumio[24957]: info: Creating Spotify config file Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:38 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:38 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 115. Oct 04 16:10:38 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:38 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:38 volumiofr go-librespot[25125]: Librespot-go daemon starting... Oct 04 16:10:38 volumiofr volumio[24957]: info: [squeezelite_mc] Starting proxy server... Oct 04 16:10:38 volumiofr volumio[24957]: info: Loading i18n strings for locale en Oct 04 16:10:38 volumiofr go-librespot[25125]: time="2024-10-04T16:10:38-04:00" level=info msg="generated new device id: 8e8e41f9a3e1a2883063171b57c20a48600468ac" Oct 04 16:10:38 volumiofr go-librespot[25125]: time="2024-10-04T16:10:38-04:00" level=fatal msg="unknown credentials: " Oct 04 16:10:38 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:38 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:38 volumiofr volumio[24957]: info: FusionDsp - mixtype--------------------- Hardware Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:10:38 volumiofr volumio[24957]: info: [1728072638818] CoreMusicLibrary::Adding element Radio Paradise Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:38 volumiofr volumio[24957]: Cannot find translation for source Radio Paradise Oct 04 16:10:38 volumiofr volumio[24957]: info: Volumio Calling Home Oct 04 16:10:38 volumiofr sudo[25133]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Oct 04 16:10:38 volumiofr sudo[25133]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:38 volumiofr sudo[25133]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:38 volumiofr volumio[24957]: info: [squeezelite_mc] Proxy server started on port 39711 Oct 04 16:10:38 volumiofr volumio[24957]: info: Preparing to generate the ALSA configuration file Oct 04 16:10:38 volumiofr volumio[24957]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:10:39 volumiofr volumio[24957]: Unhandled rejection Error: No sockets available, cannot start. Oct 04 16:10:39 volumiofr volumio[24957]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Oct 04 16:10:39 volumiofr volumio[24957]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Oct 04 16:10:39 volumiofr volumio[24957]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Oct 04 16:10:39 volumiofr volumio[24957]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Oct 04 16:10:39 volumiofr volumio[24957]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Oct 04 16:10:39 volumiofr volumio[24957]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Oct 04 16:10:39 volumiofr volumio[24957]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Oct 04 16:10:39 volumiofr volumio[24957]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Oct 04 16:10:39 volumiofr volumio[24957]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Oct 04 16:10:39 volumiofr volumio[24957]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Oct 04 16:10:39 volumiofr volumio[24957]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Oct 04 16:10:39 volumiofr volumio[24957]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Oct 04 16:10:39 volumiofr volumio[24957]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Oct 04 16:10:39 volumiofr volumio[24957]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Oct 04 16:10:39 volumiofr volumio[24957]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Oct 04 16:10:39 volumiofr volumio[24957]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 04 16:10:39 volumiofr volumio[24957]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.dfs.volumio.org Oct 04 16:10:39 volumiofr volumio[24957]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 04 16:10:39 volumiofr volumio[24957]: info: Reading ALSA contributions from plugins. Oct 04 16:10:39 volumiofr volumio[24957]: info: MPD Permissions set Oct 04 16:10:39 volumiofr volumio[24957]: info: MPD Permissions set Oct 04 16:10:39 volumiofr volumio[24957]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreStateMachine::pushState Oct 04 16:10:39 volumiofr volumio[24957]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:39 volumiofr volumio[24957]: info: Spotify config file written Oct 04 16:10:39 volumiofr sudo[25141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 04 16:10:39 volumiofr sudo[25141]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:39 volumiofr volumio[24957]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:39 volumiofr go-librespot[25144]: Librespot-go daemon starting... Oct 04 16:10:39 volumiofr sudo[25141]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:39 volumiofr go-librespot[25144]: time="2024-10-04T16:10:39-04:00" level=info msg="generated new device id: 36744ab651162d2b5bee9ac0ccb5c40f36be8b9f" Oct 04 16:10:39 volumiofr go-librespot[25144]: time="2024-10-04T16:10:39-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr go-librespot[25144]: time="2024-10-04T16:10:39-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:39 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:39 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:39 volumiofr volumio[24957]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreStateMachine::pushState Oct 04 16:10:39 volumiofr volumio[24957]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:39 volumiofr volumio[24957]: info: [squeezelite_mc] Server discovery started Oct 04 16:10:39 volumiofr volumio[24957]: info: [squeezelite_mc] Player finder started Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:10:39 volumiofr volumio[24957]: info: [squeezelite_mc] Executing aplay -D hw:5 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 04 16:10:39 volumiofr volumio[24957]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:10:39 volumiofr volumio[24957]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 04 16:10:39 volumiofr volumio[24957]: at doSend (dgram.js:692:16) Oct 04 16:10:39 volumiofr volumio[24957]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 04 16:10:39 volumiofr volumio[24957]: at afterDns (dgram.js:638:5) Oct 04 16:10:39 volumiofr volumio[24957]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 04 16:10:39 volumiofr volumio[24957]: errno: -101, Oct 04 16:10:39 volumiofr volumio[24957]: code: 'ENETUNREACH', Oct 04 16:10:39 volumiofr volumio[24957]: syscall: 'send', Oct 04 16:10:39 volumiofr volumio[24957]: address: '255.255.255.255', Oct 04 16:10:39 volumiofr volumio[24957]: port: 3483 Oct 04 16:10:39 volumiofr volumio[24957]: } Oct 04 16:10:39 volumiofr volumio[24957]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:10:40 volumiofr sudo[25169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-04 16:09 Oct 04 16:10:40 volumiofr sudo[25169]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:40 volumiofr sudo[25169]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:40 volumiofr mpd[25116]: decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 04 16:10:40 volumiofr mpd[25116]: output: No 'audio_output' defined in config file Oct 04 16:10:40 volumiofr mpd[25116]: output: Successfully detected a sndio audio device Oct 04 16:10:40 volumiofr mpd[25116]: zeroconf: No global port, disabling zeroconf Oct 04 16:10:40 volumiofr systemd[1]: Started Music Player Daemon. Oct 04 16:10:40 volumiofr sudo[25104]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:40 volumiofr sudo[25094]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:40 volumiofr systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:40 volumiofr systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 04 16:10:40 volumiofr systemd[1]: Started dynamicswap service. Oct 04 16:10:40 volumiofr systemd[1]: dynamicswap.service: Succeeded. Oct 04 16:10:40 volumiofr systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 04 16:10:40 volumiofr systemd[1]: volumio.service: Scheduled restart job, restart counter is at 74. Oct 04 16:10:40 volumiofr systemd[1]: Started dynamicswap service. Oct 04 16:10:40 volumiofr systemd[1]: Stopped Volumio Backend Module. Oct 04 16:10:40 volumiofr systemd[1]: Started Volumio Backend Module. Oct 04 16:10:40 volumiofr systemd[1]: dynamicswap.service: Succeeded. Oct 04 16:10:42 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:42 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 116. Oct 04 16:10:42 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:42 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:42 volumiofr go-librespot[25240]: Librespot-go daemon starting... Oct 04 16:10:42 volumiofr go-librespot[25240]: time="2024-10-04T16:10:42-04:00" level=info msg="generated new device id: 4be3c02bd65ec5174ce3aa613b3052c634f02764" Oct 04 16:10:42 volumiofr go-librespot[25240]: time="2024-10-04T16:10:42-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:42 volumiofr go-librespot[25240]: time="2024-10-04T16:10:42-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:42 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:42 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:42 volumiofr volumio[25186]: info: ------------------------------------------- Oct 04 16:10:42 volumiofr volumio[25186]: info: ----- Volumio3 ---- Oct 04 16:10:42 volumiofr volumio[25186]: info: ------------------------------------------- Oct 04 16:10:42 volumiofr volumio[25186]: info: ----- System startup ---- Oct 04 16:10:42 volumiofr volumio[25186]: info: ------------------------------------------- Oct 04 16:10:42 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:43 volumiofr volumio-remote-updater[639]: [2024-10-04 16:10:43] [connect] Successful connection Oct 04 16:10:43 volumiofr volumio[25186]: info: MYVOLUMIO Environment detected Oct 04 16:10:43 volumiofr volumio[25186]: info: Plugin folders cleanup Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning into folder /volumio/app/plugins/ Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category audio_interface Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category miscellanea Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category music_service Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category plugins.json Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category system_controller Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category user_interface Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning into folder /data/plugins/ Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category audio_interface Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category miscellanea Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category music_service Oct 04 16:10:43 volumiofr volumio[25186]: info: Scanning category user_interface Oct 04 16:10:43 volumiofr volumio[25186]: info: Plugin folders cleanup completed Oct 04 16:10:43 volumiofr volumio[25186]: info: ------------------------------------------- Oct 04 16:10:43 volumiofr volumio[25186]: info: ----- Core plugins startup ---- Oct 04 16:10:43 volumiofr volumio[25186]: info: ------------------------------------------- Oct 04 16:10:43 volumiofr volumio[25186]: info: Loading plugins from folder /volumio/app/plugins/ Oct 04 16:10:43 volumiofr volumio[25186]: info: Adding plugin upnp to MyMusic Plugins Oct 04 16:10:43 volumiofr volumio[25186]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 04 16:10:43 volumiofr volumio[25186]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 04 16:10:43 volumiofr volumio[25186]: info: Loading plugins from folder /data/plugins/ Oct 04 16:10:43 volumiofr volumio[25186]: info: Loading plugin "system"... Oct 04 16:10:43 volumiofr volumio[25186]: info: Loading plugin "appearance"... Oct 04 16:10:44 volumiofr volumio[25186]: info: Loading plugin "network"... Oct 04 16:10:44 volumiofr volumio[25186]: info: Refreshing Cached IP Addresses Oct 04 16:10:44 volumiofr sudo[25262]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 04 16:10:44 volumiofr sudo[25262]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:44 volumiofr sudo[25262]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:44 volumiofr sudo[25264]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 04 16:10:44 volumiofr volumio[25186]: info: Plugin peppy_screensaver is not enabled Oct 04 16:10:44 volumiofr sudo[25264]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:44 volumiofr volumio[25186]: info: Loading plugin "services"... Oct 04 16:10:44 volumiofr volumio[25186]: info: Loading plugin "alsa_controller"... Oct 04 16:10:44 volumiofr sudo[25264]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:44 volumiofr sudo[25267]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 04 16:10:44 volumiofr sudo[25267]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:44 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:10:44 volumiofr volumio[25186]: info: Loading plugin "wizard"... Oct 04 16:10:44 volumiofr volumio[25186]: info: Loading plugin "networkfs"... Oct 04 16:10:44 volumiofr volumio[25186]: info: Cannot mount NAS OpenMediaVault at system boot, trial number 1 ,retrying in 5 seconds Oct 04 16:10:44 volumiofr volumio[25186]: info: Starting Udev Watcher for removable devices Oct 04 16:10:44 volumiofr volumio[25186]: info: Ignoring mount for partition: boot Oct 04 16:10:44 volumiofr volumio[25186]: info: Ignoring mount for partition: volumio Oct 04 16:10:44 volumiofr volumio[25186]: info: Ignoring mount for partition: volumio_data Oct 04 16:10:44 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "volumio_command_line_client"... Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "upnp"... Oct 04 16:10:45 volumiofr volumio[25186]: info: [1728072645013] Starting Upmpd Daemon Oct 04 16:10:45 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "my_music"... Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "mpd"... Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "upnp_browser"... Oct 04 16:10:45 volumiofr sudo[25267]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:45 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:45 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 117. Oct 04 16:10:45 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "alarm-clock"... Oct 04 16:10:45 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:45 volumiofr go-librespot[25275]: Librespot-go daemon starting... Oct 04 16:10:45 volumiofr go-librespot[25275]: time="2024-10-04T16:10:45-04:00" level=info msg="generated new device id: 45f4566cee80060f69f97959e21c017d91e2fbe0" Oct 04 16:10:45 volumiofr go-librespot[25275]: time="2024-10-04T16:10:45-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:45 volumiofr go-librespot[25275]: time="2024-10-04T16:10:45-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:45 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:45 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "airplay_emulation"... Oct 04 16:10:45 volumiofr volumio[25186]: info: Starting Shairport Sync Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "last_100"... Oct 04 16:10:45 volumiofr volumio[25186]: info: Loading plugin "webradio"... Oct 04 16:10:46 volumiofr volumio[25186]: info: Loading plugin "i2s_dacs"... Oct 04 16:10:46 volumiofr volumio[25186]: info: I2S DAC not set, start Auto-detection Oct 04 16:10:46 volumiofr volumio[25186]: info: Loading plugin "volumiodiscovery"... Oct 04 16:10:46 volumiofr volumio[25186]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:46 volumiofr volumio[25186]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:46 volumiofr volumio[25186]: *** WARNING *** For more information see Oct 04 16:10:46 volumiofr node[25186]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:46 volumiofr volumio[25186]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:46 volumiofr volumio[25186]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:46 volumiofr volumio[25186]: *** WARNING *** For more information see Oct 04 16:10:46 volumiofr node[25186]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:46 volumiofr node[25186]: *** WARNING *** For more information see Oct 04 16:10:46 volumiofr node[25186]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:46 volumiofr node[25186]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:46 volumiofr node[25186]: *** WARNING *** For more information see Oct 04 16:10:46 volumiofr volumio[25186]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 04 16:10:46 volumiofr volumio[25186]: info: Discovery: Started advertising with name: VolumioFR Oct 04 16:10:46 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:46 volumiofr volumio[25186]: info: Loading plugin "spop"... Oct 04 16:10:47 volumiofr volumio[25186]: info: Loading plugin "squeezelite_mc"... Oct 04 16:10:48 volumiofr volumio[25186]: info: Plugin now_playing is not enabled Oct 04 16:10:48 volumiofr volumio[25186]: info: Loading plugin "outputs"... Oct 04 16:10:48 volumiofr volumio[25186]: info: Loading plugin "albumart"... Oct 04 16:10:48 volumiofr volumio[25186]: info: Plugin example_plugin is not enabled Oct 04 16:10:48 volumiofr volumio[25186]: info: Loading plugin "inputs"... Oct 04 16:10:48 volumiofr volumio[25186]: info: Loading plugin "updater_comm"... Oct 04 16:10:48 volumiofr volumio[25186]: info: Plugin mpdemulation is not enabled Oct 04 16:10:48 volumiofr volumio[25186]: info: Loading plugin "rest_api"... Oct 04 16:10:48 volumiofr volumio[25186]: info: Loading plugin "websocket"... Oct 04 16:10:48 volumiofr volumio[25186]: info: Starting Socket.io Server version 2.3.0 Oct 04 16:10:48 volumiofr volumio[25186]: info: Loading plugin "fusiondsp"... Oct 04 16:10:48 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:48 volumiofr volumio[25186]: Forking 3 albumart workers Oct 04 16:10:48 volumiofr volumio[25186]: info: Applying required configuration parameters for plugin fusiondsp Oct 04 16:10:48 volumiofr volumio[25186]: info: Loading plugin "RoonBridge"... Oct 04 16:10:48 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:48 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 118. Oct 04 16:10:48 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:48 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:48 volumiofr go-librespot[25312]: Librespot-go daemon starting... Oct 04 16:10:49 volumiofr go-librespot[25312]: time="2024-10-04T16:10:49-04:00" level=info msg="generated new device id: 1ec65d1d031ee4efb7ad823289ba083190288002" Oct 04 16:10:49 volumiofr go-librespot[25312]: time="2024-10-04T16:10:49-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:49 volumiofr go-librespot[25312]: time="2024-10-04T16:10:49-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:49 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:49 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:49 volumiofr volumio[25186]: info: Applying required configuration parameters for plugin RoonBridge Oct 04 16:10:49 volumiofr volumio[25186]: info: Loading plugin "radio_paradise"... Oct 04 16:10:49 volumiofr volumio[25186]: info: Applying required configuration parameters for plugin radio_paradise Oct 04 16:10:49 volumiofr volumio[25186]: info: [1728072649572] [RadioParadise] API delay: 5 Oct 04 16:10:49 volumiofr volumio[25186]: info: Plugin touch_display is not enabled Oct 04 16:10:49 volumiofr volumio[25186]: info: Loading i18n strings for locale en Oct 04 16:10:49 volumiofr volumio[25186]: Updating browse sources language Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:49 volumiofr volumio[25186]: Starting albumart workers Oct 04 16:10:49 volumiofr volumio[25186]: Starting albumart workers Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::initPlayerControls Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:10:49 volumiofr volumio[25186]: Express server listening on port 3000 Oct 04 16:10:49 volumiofr volumio[25186]: [Metrics] WebUI: 7s 770.03ms Oct 04 16:10:49 volumiofr volumio[25186]: Starting albumart workers Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreStateMachine::resetVolumioState Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreStateMachine::getcurrentVolume Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:10:49 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:50 volumiofr volumio[25186]: info: Cannot mount NAS OpenMediaVault at system boot, trial number 2 ,retrying in 5 seconds Oct 04 16:10:50 volumiofr volumio[25186]: info: Reloading queue from file Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreStateMachine::setRepeat null single undefined Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreStateMachine::pushState Oct 04 16:10:50 volumiofr volumio[25186]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreStateMachine::setRandom true Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreStateMachine::pushState Oct 04 16:10:50 volumiofr volumio[25186]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:50 volumiofr volumio[25186]: info: Setting Device type: Raspberry PI Oct 04 16:10:50 volumiofr volumio[25186]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 04 16:10:50 volumiofr volumio[25186]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 04 16:10:50 volumiofr volumio[25186]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 04 16:10:50 volumiofr volumio[25186]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreStateMachine::pushState Oct 04 16:10:50 volumiofr volumio[25186]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreStateMachine::updateTrackBlock Oct 04 16:10:50 volumiofr volumio[25186]: info: CorePlayQueue::getTrackBlock Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:10:50 volumiofr volumio[25186]: info: Completed loading Core Plugins Oct 04 16:10:50 volumiofr volumio[25186]: info: Preparing to generate the ALSA configuration file Oct 04 16:10:50 volumiofr volumio[25186]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 04 16:10:50 volumiofr volumio[25186]: info: Reading ALSA contributions from plugins. Oct 04 16:10:50 volumiofr volumio[25186]: info: Asound.conf file unchanged, so no further update is needed Oct 04 16:10:50 volumiofr volumio[25186]: info: Output device has changed, restarting MPD Oct 04 16:10:50 volumiofr volumio[25186]: info: Output device has changed, restarting Shairport Sync Oct 04 16:10:50 volumiofr sudo[25344]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:50 volumiofr sudo[25344]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:50 volumiofr sudo[25349]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 04 16:10:50 volumiofr sudo[25344]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:50 volumiofr sudo[25349]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:50 volumiofr systemd[1]: Stopping Music Player Daemon... Oct 04 16:10:50 volumiofr volumio[25186]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:10:50 volumiofr systemd[1]: mpd.service: Succeeded. Oct 04 16:10:50 volumiofr volumio[25186]: info: ___________ START PLUGINS ___________ Oct 04 16:10:50 volumiofr systemd[1]: Stopped Music Player Daemon. Oct 04 16:10:50 volumiofr volumio[25186]: info: ControllerMpd::onStart: Initializing MPD Oct 04 16:10:50 volumiofr volumio[25186]: info: Creating MPD Configuration file Oct 04 16:10:50 volumiofr systemd[1]: Starting Music Player Daemon... Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:10:50 volumiofr volumio[25186]: info: [1728072650853] CoreMusicLibrary::Adding element Media Servers Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:50 volumiofr sudo[25370]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 04 16:10:50 volumiofr sudo[25370]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:50 volumiofr sudo[25365]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 04 16:10:50 volumiofr sudo[25365]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:50 volumiofr sudo[25365]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:50 volumiofr systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 04 16:10:50 volumiofr systemd[1]: mpd.service: Succeeded. Oct 04 16:10:50 volumiofr systemd[1]: Stopped Music Player Daemon. Oct 04 16:10:50 volumiofr systemd[1]: Starting Music Player Daemon... Oct 04 16:10:50 volumiofr volumio[25186]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:50 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:10:51 volumiofr volumio[25186]: info: [1728072651035] CoreMusicLibrary::Adding element Last_100 Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:10:51 volumiofr volumio[25186]: info: [1728072651040] CoreMusicLibrary::Adding element Webradio Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:10:51 volumiofr volumio[25186]: info: Initializing BBC Radios Oct 04 16:10:51 volumiofr sudo[25373]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 04 16:10:51 volumiofr sudo[25373]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:51 volumiofr sudo[25373]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: Creating Spotify config file Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: [squeezelite_mc] Starting proxy server... Oct 04 16:10:51 volumiofr volumio[25186]: info: Loading i18n strings for locale en Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: FusionDsp - mixtype--------------------- Hardware Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:10:51 volumiofr volumio[25186]: info: [1728072651373] CoreMusicLibrary::Adding element Radio Paradise Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:10:51 volumiofr volumio[25186]: Cannot find translation for source Radio Paradise Oct 04 16:10:51 volumiofr volumio[25186]: info: Volumio Calling Home Oct 04 16:10:51 volumiofr sudo[25393]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Oct 04 16:10:51 volumiofr sudo[25393]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:51 volumiofr sudo[25393]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:51 volumiofr volumio[25186]: info: [squeezelite_mc] Proxy server started on port 39083 Oct 04 16:10:51 volumiofr volumio[25186]: info: Preparing to generate the ALSA configuration file Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:10:51 volumiofr volumio[25186]: Unhandled rejection Error: No sockets available, cannot start. Oct 04 16:10:51 volumiofr volumio[25186]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Oct 04 16:10:51 volumiofr volumio[25186]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Oct 04 16:10:51 volumiofr volumio[25186]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Oct 04 16:10:51 volumiofr volumio[25186]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Oct 04 16:10:51 volumiofr volumio[25186]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Oct 04 16:10:51 volumiofr volumio[25186]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Oct 04 16:10:51 volumiofr volumio[25186]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Oct 04 16:10:51 volumiofr volumio[25186]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Oct 04 16:10:51 volumiofr volumio[25186]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Oct 04 16:10:51 volumiofr volumio[25186]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Oct 04 16:10:51 volumiofr volumio[25186]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Oct 04 16:10:51 volumiofr volumio[25186]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Oct 04 16:10:51 volumiofr volumio[25186]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Oct 04 16:10:51 volumiofr volumio[25186]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Oct 04 16:10:51 volumiofr volumio[25186]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Oct 04 16:10:51 volumiofr volumio[25186]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 04 16:10:51 volumiofr volumio[25186]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.dfs.volumio.org Oct 04 16:10:51 volumiofr volumio[25186]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 04 16:10:51 volumiofr volumio[25186]: info: Reading ALSA contributions from plugins. Oct 04 16:10:51 volumiofr volumio[25186]: info: MPD Permissions set Oct 04 16:10:51 volumiofr volumio[25186]: info: MPD Permissions set Oct 04 16:10:51 volumiofr volumio[25186]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreStateMachine::pushState Oct 04 16:10:51 volumiofr volumio[25186]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:51 volumiofr volumio[25186]: info: Spotify config file written Oct 04 16:10:51 volumiofr sudo[25401]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 04 16:10:51 volumiofr sudo[25401]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:51 volumiofr volumio[25186]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:51 volumiofr go-librespot[25403]: Librespot-go daemon starting... Oct 04 16:10:51 volumiofr sudo[25401]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr go-librespot[25403]: time="2024-10-04T16:10:51-04:00" level=info msg="generated new device id: 8525f3e93913f282537486bc15e6b2eac4d429db" Oct 04 16:10:51 volumiofr go-librespot[25403]: time="2024-10-04T16:10:51-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:51 volumiofr go-librespot[25403]: time="2024-10-04T16:10:51-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:51 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:51 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:51 volumiofr volumio[25186]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreStateMachine::pushState Oct 04 16:10:51 volumiofr volumio[25186]: info: CorePlayQueue::getTrack 0 Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::volumioPushState Oct 04 16:10:51 volumiofr volumio[25186]: info: [squeezelite_mc] Server discovery started Oct 04 16:10:51 volumiofr volumio[25186]: info: [squeezelite_mc] Player finder started Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:10:51 volumiofr volumio[25186]: info: [squeezelite_mc] Executing aplay -D hw:5 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 04 16:10:51 volumiofr volumio[25186]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:10:52 volumiofr volumio[25186]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 04 16:10:52 volumiofr volumio[25186]: at doSend (dgram.js:692:16) Oct 04 16:10:52 volumiofr volumio[25186]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 04 16:10:52 volumiofr volumio[25186]: at afterDns (dgram.js:638:5) Oct 04 16:10:52 volumiofr volumio[25186]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 04 16:10:52 volumiofr volumio[25186]: errno: -101, Oct 04 16:10:52 volumiofr volumio[25186]: code: 'ENETUNREACH', Oct 04 16:10:52 volumiofr volumio[25186]: syscall: 'send', Oct 04 16:10:52 volumiofr volumio[25186]: address: '255.255.255.255', Oct 04 16:10:52 volumiofr volumio[25186]: port: 3483 Oct 04 16:10:52 volumiofr volumio[25186]: } Oct 04 16:10:52 volumiofr volumio[25186]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:10:52 volumiofr sudo[25429]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-04 16:09 Oct 04 16:10:52 volumiofr sudo[25429]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:52 volumiofr sudo[25429]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:52 volumiofr mpd[25382]: decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 04 16:10:52 volumiofr mpd[25382]: output: No 'audio_output' defined in config file Oct 04 16:10:52 volumiofr mpd[25382]: output: Successfully detected a sndio audio device Oct 04 16:10:52 volumiofr mpd[25382]: zeroconf: No global port, disabling zeroconf Oct 04 16:10:52 volumiofr systemd[1]: Started Music Player Daemon. Oct 04 16:10:52 volumiofr sudo[25349]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:52 volumiofr sudo[25370]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:52 volumiofr systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:52 volumiofr systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 04 16:10:53 volumiofr systemd[1]: Started dynamicswap service. Oct 04 16:10:53 volumiofr systemd[1]: dynamicswap.service: Succeeded. Oct 04 16:10:53 volumiofr systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 04 16:10:53 volumiofr systemd[1]: volumio.service: Scheduled restart job, restart counter is at 75. Oct 04 16:10:53 volumiofr systemd[1]: Stopped Volumio Backend Module. Oct 04 16:10:53 volumiofr systemd[1]: Started Volumio Backend Module. Oct 04 16:10:53 volumiofr systemd[1]: Started dynamicswap service. Oct 04 16:10:53 volumiofr systemd[1]: dynamicswap.service: Succeeded. Oct 04 16:10:53 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:54 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:54 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 119. Oct 04 16:10:54 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:54 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:54 volumiofr go-librespot[25458]: Librespot-go daemon starting... Oct 04 16:10:55 volumiofr go-librespot[25458]: time="2024-10-04T16:10:55-04:00" level=info msg="generated new device id: 186001876892fd4aa2ae20b40283288a860af546" Oct 04 16:10:55 volumiofr go-librespot[25458]: time="2024-10-04T16:10:55-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:55 volumiofr go-librespot[25458]: time="2024-10-04T16:10:55-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:55 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:55 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:55 volumiofr volumio[25445]: info: ------------------------------------------- Oct 04 16:10:55 volumiofr volumio[25445]: info: ----- Volumio3 ---- Oct 04 16:10:55 volumiofr volumio[25445]: info: ------------------------------------------- Oct 04 16:10:55 volumiofr volumio[25445]: info: ----- System startup ---- Oct 04 16:10:55 volumiofr volumio[25445]: info: ------------------------------------------- Oct 04 16:10:56 volumiofr volumio[25445]: info: MYVOLUMIO Environment detected Oct 04 16:10:56 volumiofr volumio[25445]: info: Plugin folders cleanup Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning into folder /volumio/app/plugins/ Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category audio_interface Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category miscellanea Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category music_service Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category plugins.json Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category system_controller Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category user_interface Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning into folder /data/plugins/ Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category audio_interface Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category miscellanea Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category music_service Oct 04 16:10:56 volumiofr volumio[25445]: info: Scanning category user_interface Oct 04 16:10:56 volumiofr volumio[25445]: info: Plugin folders cleanup completed Oct 04 16:10:56 volumiofr volumio[25445]: info: ------------------------------------------- Oct 04 16:10:56 volumiofr volumio[25445]: info: ----- Core plugins startup ---- Oct 04 16:10:56 volumiofr volumio[25445]: info: ------------------------------------------- Oct 04 16:10:56 volumiofr volumio[25445]: info: Loading plugins from folder /volumio/app/plugins/ Oct 04 16:10:56 volumiofr volumio[25445]: info: Adding plugin upnp to MyMusic Plugins Oct 04 16:10:56 volumiofr volumio[25445]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 04 16:10:56 volumiofr volumio[25445]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 04 16:10:56 volumiofr volumio[25445]: info: Loading plugins from folder /data/plugins/ Oct 04 16:10:56 volumiofr volumio[25445]: info: Loading plugin "system"... Oct 04 16:10:56 volumiofr volumio[25445]: info: Loading plugin "appearance"... Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "network"... Oct 04 16:10:57 volumiofr volumio[25445]: info: Refreshing Cached IP Addresses Oct 04 16:10:57 volumiofr sudo[25480]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 04 16:10:57 volumiofr sudo[25480]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:57 volumiofr sudo[25480]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:57 volumiofr sudo[25482]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 04 16:10:57 volumiofr volumio[25445]: info: Plugin peppy_screensaver is not enabled Oct 04 16:10:57 volumiofr sudo[25482]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "services"... Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "alsa_controller"... Oct 04 16:10:57 volumiofr sudo[25482]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:57 volumiofr sudo[25485]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 04 16:10:57 volumiofr sudo[25485]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:10:57 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "wizard"... Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "networkfs"... Oct 04 16:10:57 volumiofr volumio[25445]: info: Cannot mount NAS OpenMediaVault at system boot, trial number 1 ,retrying in 5 seconds Oct 04 16:10:57 volumiofr volumio[25445]: info: Starting Udev Watcher for removable devices Oct 04 16:10:57 volumiofr volumio[25445]: info: Ignoring mount for partition: boot Oct 04 16:10:57 volumiofr volumio[25445]: info: Ignoring mount for partition: volumio Oct 04 16:10:57 volumiofr volumio[25445]: info: Ignoring mount for partition: volumio_data Oct 04 16:10:57 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "volumio_command_line_client"... Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "upnp"... Oct 04 16:10:57 volumiofr volumio[25445]: info: [1728072657509] Starting Upmpd Daemon Oct 04 16:10:57 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "my_music"... Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "mpd"... Oct 04 16:10:57 volumiofr volumio[25445]: info: Loading plugin "upnp_browser"... Oct 04 16:10:57 volumiofr sudo[25485]: pam_unix(sudo:session): session closed for user root Oct 04 16:10:58 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:10:58 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 120. Oct 04 16:10:58 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:10:58 volumiofr volumio[25445]: info: Loading plugin "alarm-clock"... Oct 04 16:10:58 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:10:58 volumiofr go-librespot[25492]: Librespot-go daemon starting... Oct 04 16:10:58 volumiofr go-librespot[25492]: time="2024-10-04T16:10:58-04:00" level=info msg="generated new device id: 13bf6922c6ab9ed0922a15fc1a430ade121eb275" Oct 04 16:10:58 volumiofr go-librespot[25492]: time="2024-10-04T16:10:58-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:10:58 volumiofr go-librespot[25492]: time="2024-10-04T16:10:58-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:10:58 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:10:58 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:10:58 volumiofr volumio[25445]: info: Loading plugin "airplay_emulation"... Oct 04 16:10:58 volumiofr volumio[25445]: info: Starting Shairport Sync Oct 04 16:10:58 volumiofr volumio[25445]: info: Loading plugin "last_100"... Oct 04 16:10:58 volumiofr volumio[25445]: info: Loading plugin "webradio"... Oct 04 16:10:58 volumiofr volumio-remote-updater[639]: [2024-10-04 16:10:58] [connect] Successful connection Oct 04 16:10:58 volumiofr volumio[25445]: info: Loading plugin "i2s_dacs"... Oct 04 16:10:58 volumiofr volumio[25445]: info: I2S DAC not set, start Auto-detection Oct 04 16:10:58 volumiofr volumio[25445]: info: Loading plugin "volumiodiscovery"... Oct 04 16:10:58 volumiofr volumio[25445]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:58 volumiofr volumio[25445]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:58 volumiofr volumio[25445]: *** WARNING *** For more information see Oct 04 16:10:58 volumiofr node[25445]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:58 volumiofr volumio[25445]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:58 volumiofr volumio[25445]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:58 volumiofr volumio[25445]: *** WARNING *** For more information see Oct 04 16:10:58 volumiofr node[25445]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:58 volumiofr node[25445]: *** WARNING *** For more information see Oct 04 16:10:58 volumiofr node[25445]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 04 16:10:58 volumiofr node[25445]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:10:58 volumiofr node[25445]: *** WARNING *** For more information see Oct 04 16:10:58 volumiofr volumio[25445]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 04 16:10:58 volumiofr volumio[25445]: info: Discovery: Started advertising with name: VolumioFR Oct 04 16:10:58 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:10:58 volumiofr volumio[25445]: info: Loading plugin "spop"... Oct 04 16:10:59 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:10:59 volumiofr volumio[25445]: info: Loading plugin "squeezelite_mc"... Oct 04 16:11:00 volumiofr volumio[25445]: info: Plugin now_playing is not enabled Oct 04 16:11:00 volumiofr volumio[25445]: info: Loading plugin "outputs"... Oct 04 16:11:00 volumiofr volumio[25445]: info: Loading plugin "albumart"... Oct 04 16:11:00 volumiofr volumio[25445]: info: Plugin example_plugin is not enabled Oct 04 16:11:00 volumiofr volumio[25445]: info: Loading plugin "inputs"... Oct 04 16:11:00 volumiofr volumio[25445]: info: Loading plugin "updater_comm"... Oct 04 16:11:00 volumiofr volumio[25445]: info: Plugin mpdemulation is not enabled Oct 04 16:11:00 volumiofr volumio[25445]: info: Loading plugin "rest_api"... Oct 04 16:11:00 volumiofr volumio[25445]: info: Loading plugin "websocket"... Oct 04 16:11:00 volumiofr volumio[25445]: info: Starting Socket.io Server version 2.3.0 Oct 04 16:11:00 volumiofr volumio[25445]: info: Loading plugin "fusiondsp"... Oct 04 16:11:01 volumiofr volumio[25445]: Forking 3 albumart workers Oct 04 16:11:01 volumiofr volumio[25445]: info: Applying required configuration parameters for plugin fusiondsp Oct 04 16:11:01 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:11:01 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 121. Oct 04 16:11:01 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:11:01 volumiofr volumio[25445]: info: Loading plugin "RoonBridge"... Oct 04 16:11:01 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:11:01 volumiofr go-librespot[25529]: Librespot-go daemon starting... Oct 04 16:11:01 volumiofr go-librespot[25529]: time="2024-10-04T16:11:01-04:00" level=info msg="generated new device id: 7fb7b129f5b2665472f02e31046bf14feb21e0fa" Oct 04 16:11:01 volumiofr go-librespot[25529]: time="2024-10-04T16:11:01-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:11:01 volumiofr go-librespot[25529]: time="2024-10-04T16:11:01-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:11:01 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:11:01 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:11:01 volumiofr volumio[25445]: info: Applying required configuration parameters for plugin RoonBridge Oct 04 16:11:01 volumiofr volumio[25445]: info: Loading plugin "radio_paradise"... Oct 04 16:11:02 volumiofr volumio[25445]: info: Applying required configuration parameters for plugin radio_paradise Oct 04 16:11:02 volumiofr volumio[25445]: info: [1728072662125] [RadioParadise] API delay: 5 Oct 04 16:11:02 volumiofr volumio[25445]: info: Plugin touch_display is not enabled Oct 04 16:11:02 volumiofr volumio[25445]: info: Loading i18n strings for locale en Oct 04 16:11:02 volumiofr volumio[25445]: Updating browse sources language Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:02 volumiofr volumio[25445]: Starting albumart workers Oct 04 16:11:02 volumiofr volumio[25445]: Starting albumart workers Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::initPlayerControls Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: Express server listening on port 3000 Oct 04 16:11:02 volumiofr volumio[25445]: [Metrics] WebUI: 7s 793.22ms Oct 04 16:11:02 volumiofr volumio[25445]: Starting albumart workers Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreStateMachine::resetVolumioState Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreStateMachine::getcurrentVolume Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:02 volumiofr volumio[25445]: info: Cannot mount NAS OpenMediaVault at system boot, trial number 2 ,retrying in 5 seconds Oct 04 16:11:02 volumiofr volumio-remote-updater[639]: [2024-10-04 16:11:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1728072658 101 Oct 04 16:11:02 volumiofr volumio[25445]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Oct 04 16:11:02 volumiofr volumio[25445]: info: Reloading queue from file Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreStateMachine::setRepeat null single undefined Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreStateMachine::pushState Oct 04 16:11:02 volumiofr volumio[25445]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreStateMachine::setRandom true Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreStateMachine::pushState Oct 04 16:11:02 volumiofr volumio[25445]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:02 volumiofr volumio[25445]: info: Setting Device type: Raspberry PI Oct 04 16:11:02 volumiofr volumio[25445]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreStateMachine::pushState Oct 04 16:11:02 volumiofr volumio[25445]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreStateMachine::updateTrackBlock Oct 04 16:11:02 volumiofr volumio[25445]: info: CorePlayQueue::getTrackBlock Oct 04 16:11:02 volumiofr volumio[25445]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:11:02 volumiofr volumio[25445]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 04 16:11:02 volumiofr volumio[25445]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 04 16:11:02 volumiofr volumio[25445]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 04 16:11:02 volumiofr volumio[25445]: info: Completed loading Core Plugins Oct 04 16:11:02 volumiofr volumio[25445]: info: Preparing to generate the ALSA configuration file Oct 04 16:11:03 volumiofr volumio[25445]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 04 16:11:03 volumiofr volumio[25445]: info: Reading ALSA contributions from plugins. Oct 04 16:11:03 volumiofr volumio[25445]: info: Asound.conf file unchanged, so no further update is needed Oct 04 16:11:03 volumiofr volumio[25445]: info: Output device has changed, restarting MPD Oct 04 16:11:03 volumiofr volumio[25445]: info: Output device has changed, restarting Shairport Sync Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:03 volumiofr sudo[25553]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 04 16:11:03 volumiofr sudo[25553]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:03 volumiofr sudo[25553]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:03 volumiofr sudo[25558]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 04 16:11:03 volumiofr sudo[25558]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:03 volumiofr systemd[1]: Stopping Music Player Daemon... Oct 04 16:11:03 volumiofr systemd[1]: mpd.service: Succeeded. Oct 04 16:11:03 volumiofr systemd[1]: Stopped Music Player Daemon. Oct 04 16:11:03 volumiofr volumio[25445]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:11:03 volumiofr volumio[25445]: info: ___________ START PLUGINS ___________ Oct 04 16:11:03 volumiofr volumio[25445]: info: ControllerMpd::onStart: Initializing MPD Oct 04 16:11:03 volumiofr volumio[25445]: info: Creating MPD Configuration file Oct 04 16:11:03 volumiofr systemd[1]: Starting Music Player Daemon... Oct 04 16:11:03 volumiofr sudo[25582]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 04 16:11:03 volumiofr sudo[25582]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:03 volumiofr sudo[25582]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:11:03 volumiofr volumio[25445]: info: [1728072663378] CoreMusicLibrary::Adding element Media Servers Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:03 volumiofr sudo[25585]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 04 16:11:03 volumiofr sudo[25585]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:03 volumiofr systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 04 16:11:03 volumiofr systemd[1]: mpd.service: Succeeded. Oct 04 16:11:03 volumiofr systemd[1]: Stopped Music Player Daemon. Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:03 volumiofr systemd[1]: Starting Music Player Daemon... Oct 04 16:11:03 volumiofr volumio[25445]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:03 volumiofr volumio[25445]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:11:03 volumiofr volumio[25445]: info: [1728072663548] CoreMusicLibrary::Adding element Last_100 Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:11:03 volumiofr volumio[25445]: info: [1728072663552] CoreMusicLibrary::Adding element Webradio Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:11:03 volumiofr volumio[25445]: info: Initializing BBC Radios Oct 04 16:11:03 volumiofr sudo[25587]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 04 16:11:03 volumiofr sudo[25587]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:03 volumiofr sudo[25587]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:03 volumiofr volumio[25445]: info: Creating Spotify config file Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:03 volumiofr volumio[25445]: info: [squeezelite_mc] Starting proxy server... Oct 04 16:11:03 volumiofr volumio[25445]: info: Loading i18n strings for locale en Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:03 volumiofr volumio[25445]: info: FusionDsp - mixtype--------------------- Hardware Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:11:03 volumiofr volumio[25445]: info: [1728072663888] CoreMusicLibrary::Adding element Radio Paradise Oct 04 16:11:03 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:03 volumiofr volumio[25445]: Cannot find translation for source Radio Paradise Oct 04 16:11:03 volumiofr volumio[25445]: info: Volumio Calling Home Oct 04 16:11:03 volumiofr sudo[25607]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Oct 04 16:11:03 volumiofr sudo[25607]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:03 volumiofr sudo[25607]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:04 volumiofr autossh[24732]: starting ssh (count 10) Oct 04 16:11:04 volumiofr autossh[24732]: ssh child pid is 25612 Oct 04 16:11:04 volumiofr volumio[25445]: info: [squeezelite_mc] Proxy server started on port 39257 Oct 04 16:11:04 volumiofr volumio[25445]: info: Preparing to generate the ALSA configuration file Oct 04 16:11:04 volumiofr volumiossh-tunnel[24730]: ssh: Could not resolve hostname us3.myvolumio.org: Device or resource busy Oct 04 16:11:04 volumiofr autossh[24732]: ssh exited with error status 255; restarting ssh Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:11:04 volumiofr volumio[25445]: Unhandled rejection Error: No sockets available, cannot start. Oct 04 16:11:04 volumiofr volumio[25445]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Oct 04 16:11:04 volumiofr volumio[25445]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Oct 04 16:11:04 volumiofr volumio[25445]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Oct 04 16:11:04 volumiofr volumio[25445]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Oct 04 16:11:04 volumiofr volumio[25445]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Oct 04 16:11:04 volumiofr volumio[25445]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Oct 04 16:11:04 volumiofr volumio[25445]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Oct 04 16:11:04 volumiofr volumio[25445]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Oct 04 16:11:04 volumiofr volumio[25445]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Oct 04 16:11:04 volumiofr volumio[25445]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Oct 04 16:11:04 volumiofr volumio[25445]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Oct 04 16:11:04 volumiofr volumio[25445]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Oct 04 16:11:04 volumiofr volumio[25445]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Oct 04 16:11:04 volumiofr volumio[25445]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Oct 04 16:11:04 volumiofr volumio[25445]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Oct 04 16:11:04 volumiofr volumio[25445]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 04 16:11:04 volumiofr volumio[25445]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.dfs.volumio.org Oct 04 16:11:04 volumiofr volumio[25445]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 04 16:11:04 volumiofr volumio[25445]: info: Reading ALSA contributions from plugins. Oct 04 16:11:04 volumiofr volumio[25445]: info: MPD Permissions set Oct 04 16:11:04 volumiofr volumio[25445]: info: MPD Permissions set Oct 04 16:11:04 volumiofr volumio[25445]: info: Spotify config file written Oct 04 16:11:04 volumiofr sudo[25617]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 04 16:11:04 volumiofr sudo[25617]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:04 volumiofr volumio[25445]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Oct 04 16:11:04 volumiofr volumio[25445]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreStateMachine::pushState Oct 04 16:11:04 volumiofr volumio[25445]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:04 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:11:04 volumiofr go-librespot[25619]: Librespot-go daemon starting... Oct 04 16:11:04 volumiofr sudo[25617]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:04 volumiofr go-librespot[25619]: time="2024-10-04T16:11:04-04:00" level=info msg="generated new device id: c200ad73c38ad3a12faf3eadc9292388f5b66115" Oct 04 16:11:04 volumiofr go-librespot[25619]: time="2024-10-04T16:11:04-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr go-librespot[25619]: time="2024-10-04T16:11:04-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:11:04 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:11:04 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:11:04 volumiofr volumio[25445]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreStateMachine::pushState Oct 04 16:11:04 volumiofr volumio[25445]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:04 volumiofr volumio[25445]: info: [squeezelite_mc] Server discovery started Oct 04 16:11:04 volumiofr volumio[25445]: info: [squeezelite_mc] Player finder started Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:11:04 volumiofr volumio[25445]: info: [squeezelite_mc] Executing aplay -D hw:5 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 04 16:11:04 volumiofr volumio[25445]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:11:04 volumiofr volumio[25445]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 04 16:11:04 volumiofr volumio[25445]: at doSend (dgram.js:692:16) Oct 04 16:11:04 volumiofr volumio[25445]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 04 16:11:04 volumiofr volumio[25445]: at afterDns (dgram.js:638:5) Oct 04 16:11:04 volumiofr volumio[25445]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 04 16:11:04 volumiofr volumio[25445]: errno: -101, Oct 04 16:11:04 volumiofr volumio[25445]: code: 'ENETUNREACH', Oct 04 16:11:04 volumiofr volumio[25445]: syscall: 'send', Oct 04 16:11:04 volumiofr volumio[25445]: address: '255.255.255.255', Oct 04 16:11:04 volumiofr volumio[25445]: port: 3483 Oct 04 16:11:04 volumiofr volumio[25445]: } Oct 04 16:11:04 volumiofr volumio[25445]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:11:04 volumiofr wpa_supplicant[943]: wlan0: Failed to initiate sched scan Oct 04 16:11:05 volumiofr sudo[25646]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-04 16:10 Oct 04 16:11:05 volumiofr sudo[25646]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:05 volumiofr sudo[25646]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:05 volumiofr mpd[25596]: decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 04 16:11:05 volumiofr mpd[25596]: output: No 'audio_output' defined in config file Oct 04 16:11:05 volumiofr mpd[25596]: output: Successfully detected a sndio audio device Oct 04 16:11:05 volumiofr mpd[25596]: zeroconf: No global port, disabling zeroconf Oct 04 16:11:05 volumiofr systemd[1]: Started Music Player Daemon. Oct 04 16:11:05 volumiofr sudo[25558]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:05 volumiofr sudo[25585]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:05 volumiofr volumio-remote-updater[639]: [2024-10-04 16:11:05] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 04 16:11:05 volumiofr volumio-remote-updater[639]: [2024-10-04 16:11:05] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 04 16:11:05 volumiofr systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:11:05 volumiofr systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 04 16:11:05 volumiofr systemd[1]: Started dynamicswap service. Oct 04 16:11:05 volumiofr systemd[1]: dynamicswap.service: Succeeded. Oct 04 16:11:05 volumiofr systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 04 16:11:05 volumiofr systemd[1]: volumio.service: Scheduled restart job, restart counter is at 76. Oct 04 16:11:05 volumiofr systemd[1]: Started dynamicswap service. Oct 04 16:11:05 volumiofr systemd[1]: Stopped Volumio Backend Module. Oct 04 16:11:05 volumiofr systemd[1]: Started Volumio Backend Module. Oct 04 16:11:05 volumiofr systemd[1]: dynamicswap.service: Succeeded. Oct 04 16:11:07 volumiofr volumio[25663]: info: ------------------------------------------- Oct 04 16:11:07 volumiofr volumio[25663]: info: ----- Volumio3 ---- Oct 04 16:11:07 volumiofr volumio[25663]: info: ------------------------------------------- Oct 04 16:11:07 volumiofr volumio[25663]: info: ----- System startup ---- Oct 04 16:11:07 volumiofr volumio[25663]: info: ------------------------------------------- Oct 04 16:11:07 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:11:07 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 122. Oct 04 16:11:07 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:11:07 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:11:07 volumiofr go-librespot[25683]: Librespot-go daemon starting... Oct 04 16:11:07 volumiofr go-librespot[25683]: time="2024-10-04T16:11:07-04:00" level=info msg="generated new device id: d39fbc0ac15fa4ea9711de9fa898e7c08742acf0" Oct 04 16:11:07 volumiofr go-librespot[25683]: time="2024-10-04T16:11:07-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:11:07 volumiofr go-librespot[25683]: time="2024-10-04T16:11:07-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:11:07 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:11:07 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:11:08 volumiofr volumio[25663]: info: MYVOLUMIO Environment detected Oct 04 16:11:08 volumiofr volumio[25663]: info: Plugin folders cleanup Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning into folder /volumio/app/plugins/ Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category audio_interface Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category miscellanea Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category music_service Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category plugins.json Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category system_controller Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category user_interface Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning into folder /data/plugins/ Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category audio_interface Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category miscellanea Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category music_service Oct 04 16:11:08 volumiofr volumio[25663]: info: Scanning category user_interface Oct 04 16:11:08 volumiofr volumio[25663]: info: Plugin folders cleanup completed Oct 04 16:11:08 volumiofr volumio[25663]: info: ------------------------------------------- Oct 04 16:11:08 volumiofr volumio[25663]: info: ----- Core plugins startup ---- Oct 04 16:11:08 volumiofr volumio[25663]: info: ------------------------------------------- Oct 04 16:11:08 volumiofr volumio[25663]: info: Loading plugins from folder /volumio/app/plugins/ Oct 04 16:11:08 volumiofr volumio[25663]: info: Adding plugin upnp to MyMusic Plugins Oct 04 16:11:08 volumiofr volumio[25663]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 04 16:11:08 volumiofr volumio[25663]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 04 16:11:08 volumiofr volumio[25663]: info: Loading plugins from folder /data/plugins/ Oct 04 16:11:08 volumiofr volumio[25663]: info: Loading plugin "system"... Oct 04 16:11:08 volumiofr volumio[25663]: info: Loading plugin "appearance"... Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "network"... Oct 04 16:11:09 volumiofr volumio[25663]: info: Refreshing Cached IP Addresses Oct 04 16:11:09 volumiofr sudo[25697]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 04 16:11:09 volumiofr sudo[25697]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:09 volumiofr sudo[25697]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:09 volumiofr sudo[25699]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 04 16:11:09 volumiofr sudo[25699]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:09 volumiofr volumio[25663]: info: Plugin peppy_screensaver is not enabled Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "services"... Oct 04 16:11:09 volumiofr sudo[25699]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "alsa_controller"... Oct 04 16:11:09 volumiofr sudo[25702]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 04 16:11:09 volumiofr sudo[25702]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:09 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "wizard"... Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "networkfs"... Oct 04 16:11:09 volumiofr volumio[25663]: info: Cannot mount NAS OpenMediaVault at system boot, trial number 1 ,retrying in 5 seconds Oct 04 16:11:09 volumiofr volumio[25663]: info: Starting Udev Watcher for removable devices Oct 04 16:11:09 volumiofr volumio[25663]: info: Ignoring mount for partition: boot Oct 04 16:11:09 volumiofr volumio[25663]: info: Ignoring mount for partition: volumio Oct 04 16:11:09 volumiofr volumio[25663]: info: Ignoring mount for partition: volumio_data Oct 04 16:11:09 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "volumio_command_line_client"... Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "upnp"... Oct 04 16:11:09 volumiofr volumio[25663]: info: [1728072669964] Starting Upmpd Daemon Oct 04 16:11:09 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "my_music"... Oct 04 16:11:09 volumiofr volumio[25663]: info: Loading plugin "mpd"... Oct 04 16:11:10 volumiofr volumio[25663]: info: Loading plugin "upnp_browser"... Oct 04 16:11:10 volumiofr volumio-remote-updater[639]: [2024-10-04 16:11:10] [connect] Successful connection Oct 04 16:11:10 volumiofr volumio[25663]: info: Loading plugin "alarm-clock"... Oct 04 16:11:10 volumiofr wpa_supplicant[943]: wlan0: Trying to associate with SSID 'WIN_79f0' Oct 04 16:11:10 volumiofr volumio[25663]: info: Loading plugin "airplay_emulation"... Oct 04 16:11:10 volumiofr sudo[25702]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:10 volumiofr volumio[25663]: info: Starting Shairport Sync Oct 04 16:11:10 volumiofr volumio[25663]: info: Loading plugin "last_100"... Oct 04 16:11:10 volumiofr volumio[25663]: info: Loading plugin "webradio"... Oct 04 16:11:10 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:11:10 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 123. Oct 04 16:11:10 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:11:10 volumiofr volumio[25663]: info: Loading plugin "i2s_dacs"... Oct 04 16:11:10 volumiofr volumio[25663]: info: I2S DAC not set, start Auto-detection Oct 04 16:11:10 volumiofr volumio[25663]: info: Loading plugin "volumiodiscovery"... Oct 04 16:11:11 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:11:11 volumiofr go-librespot[25709]: Librespot-go daemon starting... Oct 04 16:11:11 volumiofr go-librespot[25709]: time="2024-10-04T16:11:11-04:00" level=info msg="generated new device id: 1372c719f596c14efbe1ae79f171b9c1f0c82737" Oct 04 16:11:11 volumiofr go-librespot[25709]: time="2024-10-04T16:11:11-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:11:11 volumiofr go-librespot[25709]: time="2024-10-04T16:11:11-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:11:11 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:11:11 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:11:11 volumiofr volumio[25663]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 04 16:11:11 volumiofr volumio[25663]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:11:11 volumiofr volumio[25663]: *** WARNING *** For more information see Oct 04 16:11:11 volumiofr volumio[25663]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 04 16:11:11 volumiofr node[25663]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 04 16:11:11 volumiofr volumio[25663]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:11:11 volumiofr volumio[25663]: *** WARNING *** For more information see Oct 04 16:11:11 volumiofr node[25663]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:11:11 volumiofr node[25663]: *** WARNING *** For more information see Oct 04 16:11:11 volumiofr node[25663]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 04 16:11:11 volumiofr node[25663]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 04 16:11:11 volumiofr node[25663]: *** WARNING *** For more information see Oct 04 16:11:11 volumiofr volumio[25663]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 04 16:11:11 volumiofr volumio[25663]: info: Discovery: Started advertising with name: VolumioFR Oct 04 16:11:11 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 04 16:11:11 volumiofr volumio[25663]: info: Loading plugin "spop"... Oct 04 16:11:11 volumiofr wpa_supplicant[943]: wlan0: Associated with e8:6f:f2:be:31:d2 Oct 04 16:11:11 volumiofr wpa_supplicant[943]: wlan0: CTRL-EVENT-CONNECTED - Connection to e8:6f:f2:be:31:d2 completed [id=0 id_str=] Oct 04 16:11:11 volumiofr dhcpcd[740]: wlan0: carrier acquired Oct 04 16:11:11 volumiofr wpa_supplicant[943]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Oct 04 16:11:11 volumiofr wpa_supplicant[943]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Oct 04 16:11:11 volumiofr dhcpcd[740]: wlan0: IAID eb:a2:6a:77 Oct 04 16:11:12 volumiofr dhcpcd[740]: wlan0: soliciting an IPv6 router Oct 04 16:11:12 volumiofr dhcpcd[740]: wlan0: rebinding lease of 192.168.254.122 Oct 04 16:11:12 volumiofr volumio[25663]: info: Loading plugin "squeezelite_mc"... Oct 04 16:11:12 volumiofr dhcpcd[740]: wlan0: probing address 192.168.254.122/24 Oct 04 16:11:13 volumiofr volumio[25663]: info: Plugin now_playing is not enabled Oct 04 16:11:13 volumiofr volumio[25663]: info: Loading plugin "outputs"... Oct 04 16:11:13 volumiofr volumio[25663]: info: Loading plugin "albumart"... Oct 04 16:11:13 volumiofr volumio[25663]: info: Plugin example_plugin is not enabled Oct 04 16:11:13 volumiofr volumio[25663]: info: Loading plugin "inputs"... Oct 04 16:11:13 volumiofr volumio[25663]: info: Loading plugin "updater_comm"... Oct 04 16:11:13 volumiofr volumio[25663]: info: Plugin mpdemulation is not enabled Oct 04 16:11:13 volumiofr volumio[25663]: info: Loading plugin "rest_api"... Oct 04 16:11:13 volumiofr volumio[25663]: info: Loading plugin "websocket"... Oct 04 16:11:13 volumiofr volumio[25663]: info: Starting Socket.io Server version 2.3.0 Oct 04 16:11:13 volumiofr volumio[25663]: info: Loading plugin "fusiondsp"... Oct 04 16:11:13 volumiofr volumio[25663]: Forking 3 albumart workers Oct 04 16:11:13 volumiofr volumio[25663]: info: Applying required configuration parameters for plugin fusiondsp Oct 04 16:11:13 volumiofr volumio[25663]: info: Loading plugin "RoonBridge"... Oct 04 16:11:14 volumiofr volumio[25663]: info: Applying required configuration parameters for plugin RoonBridge Oct 04 16:11:14 volumiofr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 04 16:11:14 volumiofr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 124. Oct 04 16:11:14 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:11:14 volumiofr volumio[25663]: info: Loading plugin "radio_paradise"... Oct 04 16:11:14 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:11:14 volumiofr go-librespot[25749]: Librespot-go daemon starting... Oct 04 16:11:14 volumiofr go-librespot[25749]: time="2024-10-04T16:11:14-04:00" level=info msg="generated new device id: b08244f33e1d701a45365ae66ba77062074a5567" Oct 04 16:11:14 volumiofr go-librespot[25749]: time="2024-10-04T16:11:14-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:11:14 volumiofr go-librespot[25749]: time="2024-10-04T16:11:14-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:11:14 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:11:14 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:11:14 volumiofr volumio[25663]: info: Applying required configuration parameters for plugin radio_paradise Oct 04 16:11:14 volumiofr volumio[25663]: info: [1728072674524] [RadioParadise] API delay: 5 Oct 04 16:11:14 volumiofr volumio[25663]: info: Plugin touch_display is not enabled Oct 04 16:11:14 volumiofr volumio[25663]: info: Loading i18n strings for locale en Oct 04 16:11:14 volumiofr volumio[25663]: Updating browse sources language Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::initPlayerControls Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: Express server listening on port 3000 Oct 04 16:11:14 volumiofr volumio[25663]: [Metrics] WebUI: 7s 747.25ms Oct 04 16:11:14 volumiofr volumio[25663]: Starting albumart workers Oct 04 16:11:14 volumiofr volumio[25663]: Starting albumart workers Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreStateMachine::resetVolumioState Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreStateMachine::getcurrentVolume Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:11:14 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:14 volumiofr volumio[25663]: Starting albumart workers Oct 04 16:11:14 volumiofr volumio[25663]: info: Cannot mount NAS OpenMediaVault at system boot, trial number 2 ,retrying in 5 seconds Oct 04 16:11:15 volumiofr volumio-remote-updater[639]: [2024-10-04 16:11:15] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1728072670 101 Oct 04 16:11:15 volumiofr volumio[25663]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Oct 04 16:11:15 volumiofr volumio[25663]: info: Reloading queue from file Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreStateMachine::setRepeat null single undefined Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreStateMachine::pushState Oct 04 16:11:15 volumiofr volumio[25663]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreStateMachine::setRandom true Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreStateMachine::pushState Oct 04 16:11:15 volumiofr volumio[25663]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:15 volumiofr volumio[25663]: info: Setting Device type: Raspberry PI Oct 04 16:11:15 volumiofr volumio[25663]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 04 16:11:15 volumiofr volumio[25663]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 04 16:11:15 volumiofr volumio[25663]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 04 16:11:15 volumiofr volumio[25663]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreStateMachine::pushState Oct 04 16:11:15 volumiofr volumio[25663]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreStateMachine::updateTrackBlock Oct 04 16:11:15 volumiofr volumio[25663]: info: CorePlayQueue::getTrackBlock Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:11:15 volumiofr volumio[25663]: info: Completed loading Core Plugins Oct 04 16:11:15 volumiofr volumio[25663]: info: Preparing to generate the ALSA configuration file Oct 04 16:11:15 volumiofr volumio[25663]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 04 16:11:15 volumiofr volumio[25663]: info: Reading ALSA contributions from plugins. Oct 04 16:11:15 volumiofr volumio[25663]: info: Asound.conf file unchanged, so no further update is needed Oct 04 16:11:15 volumiofr volumio[25663]: info: Output device has changed, restarting MPD Oct 04 16:11:15 volumiofr volumio[25663]: info: Output device has changed, restarting Shairport Sync Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:15 volumiofr sudo[25776]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 04 16:11:15 volumiofr sudo[25776]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:15 volumiofr sudo[25776]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:15 volumiofr sudo[25778]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 04 16:11:15 volumiofr sudo[25778]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:15 volumiofr systemd[1]: Stopping Music Player Daemon... Oct 04 16:11:15 volumiofr volumio[25663]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:11:15 volumiofr volumio[25663]: info: ___________ START PLUGINS ___________ Oct 04 16:11:15 volumiofr volumio[25663]: info: ControllerMpd::onStart: Initializing MPD Oct 04 16:11:15 volumiofr volumio[25663]: info: Creating MPD Configuration file Oct 04 16:11:15 volumiofr systemd[1]: mpd.service: Succeeded. Oct 04 16:11:15 volumiofr systemd[1]: Stopped Music Player Daemon. Oct 04 16:11:15 volumiofr sudo[25802]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 04 16:11:15 volumiofr sudo[25802]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:11:15 volumiofr volumio[25663]: info: [1728072675810] CoreMusicLibrary::Adding element Media Servers Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:15 volumiofr sudo[25802]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:15 volumiofr systemd[1]: Starting Music Player Daemon... Oct 04 16:11:15 volumiofr sudo[25805]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 04 16:11:15 volumiofr sudo[25805]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:15 volumiofr systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 04 16:11:15 volumiofr volumio[25663]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:15 volumiofr systemd[1]: mpd.service: Succeeded. Oct 04 16:11:15 volumiofr systemd[1]: Stopped Music Player Daemon. Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:15 volumiofr systemd[1]: Starting Music Player Daemon... Oct 04 16:11:15 volumiofr volumio[25663]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:11:15 volumiofr volumio[25663]: info: [1728072675968] CoreMusicLibrary::Adding element Last_100 Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:11:15 volumiofr volumio[25663]: info: [1728072675973] CoreMusicLibrary::Adding element Webradio Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:15 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:11:15 volumiofr volumio[25663]: info: Initializing BBC Radios Oct 04 16:11:16 volumiofr sudo[25811]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 04 16:11:16 volumiofr sudo[25811]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:16 volumiofr sudo[25811]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: Creating Spotify config file Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: [squeezelite_mc] Starting proxy server... Oct 04 16:11:16 volumiofr volumio[25663]: info: Loading i18n strings for locale en Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: FusionDsp - mixtype--------------------- Hardware Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 04 16:11:16 volumiofr volumio[25663]: info: [1728072676290] CoreMusicLibrary::Adding element Radio Paradise Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 04 16:11:16 volumiofr volumio[25663]: Cannot find translation for source Radio Paradise Oct 04 16:11:16 volumiofr volumio[25663]: info: Volumio Calling Home Oct 04 16:11:16 volumiofr sudo[25828]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Oct 04 16:11:16 volumiofr sudo[25828]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:16 volumiofr sudo[25828]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:16 volumiofr volumio[25663]: info: [squeezelite_mc] Proxy server started on port 34621 Oct 04 16:11:16 volumiofr volumio[25663]: info: Preparing to generate the ALSA configuration file Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::volumioRetrievevolume Oct 04 16:11:16 volumiofr volumio[25663]: Unhandled rejection Error: No sockets available, cannot start. Oct 04 16:11:16 volumiofr volumio[25663]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Oct 04 16:11:16 volumiofr volumio[25663]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Oct 04 16:11:16 volumiofr volumio[25663]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Oct 04 16:11:16 volumiofr volumio[25663]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Oct 04 16:11:16 volumiofr volumio[25663]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Oct 04 16:11:16 volumiofr volumio[25663]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Oct 04 16:11:16 volumiofr volumio[25663]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Oct 04 16:11:16 volumiofr volumio[25663]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Oct 04 16:11:16 volumiofr volumio[25663]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Oct 04 16:11:16 volumiofr volumio[25663]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Oct 04 16:11:16 volumiofr volumio[25663]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Oct 04 16:11:16 volumiofr volumio[25663]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Oct 04 16:11:16 volumiofr volumio[25663]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Oct 04 16:11:16 volumiofr volumio[25663]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Oct 04 16:11:16 volumiofr volumio[25663]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Oct 04 16:11:16 volumiofr volumio[25663]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 04 16:11:16 volumiofr volumio[25663]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.dfs.volumio.org Oct 04 16:11:16 volumiofr volumio[25663]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 04 16:11:16 volumiofr volumio[25663]: info: Reading ALSA contributions from plugins. Oct 04 16:11:16 volumiofr volumio[25663]: info: MPD Permissions set Oct 04 16:11:16 volumiofr volumio[25663]: info: MPD Permissions set Oct 04 16:11:16 volumiofr volumio[25663]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreStateMachine::pushState Oct 04 16:11:16 volumiofr volumio[25663]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:16 volumiofr volumio[25663]: info: Spotify config file written Oct 04 16:11:16 volumiofr sudo[25836]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 04 16:11:16 volumiofr sudo[25836]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 04 16:11:16 volumiofr volumio[25663]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr systemd[1]: Stopped go-librespot Daemon. Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr systemd[1]: Started go-librespot Daemon. Oct 04 16:11:16 volumiofr go-librespot[25838]: Librespot-go daemon starting... Oct 04 16:11:16 volumiofr sudo[25836]: pam_unix(sudo:session): session closed for user root Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 04 16:11:16 volumiofr go-librespot[25838]: time="2024-10-04T16:11:16-04:00" level=info msg="generated new device id: dbf37dd1ca3fe6e8738b55183ca626a433c0d8ee" Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr go-librespot[25838]: time="2024-10-04T16:11:16-04:00" level=debug msg="stored credentials found for kemph1965" Oct 04 16:11:16 volumiofr go-librespot[25838]: time="2024-10-04T16:11:16-04:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Oct 04 16:11:16 volumiofr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 04 16:11:16 volumiofr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 04 16:11:16 volumiofr volumio[25663]: info: VolumeController:: Volume=100 Mute =false Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreStateMachine::pushState Oct 04 16:11:16 volumiofr volumio[25663]: info: CorePlayQueue::getTrack 0 Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::volumioPushState Oct 04 16:11:16 volumiofr volumio[25663]: info: [squeezelite_mc] Server discovery started Oct 04 16:11:16 volumiofr volumio[25663]: info: [squeezelite_mc] Player finder started Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 04 16:11:16 volumiofr volumio[25663]: info: [squeezelite_mc] Executing aplay -D hw:5 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 04 16:11:16 volumiofr volumio[25663]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:11:16 volumiofr volumio[25663]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 04 16:11:16 volumiofr volumio[25663]: at doSend (dgram.js:692:16) Oct 04 16:11:16 volumiofr volumio[25663]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 04 16:11:16 volumiofr volumio[25663]: at afterDns (dgram.js:638:5) Oct 04 16:11:16 volumiofr volumio[25663]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 04 16:11:16 volumiofr volumio[25663]: errno: -101, Oct 04 16:11:16 volumiofr volumio[25663]: code: 'ENETUNREACH', Oct 04 16:11:16 volumiofr volumio[25663]: syscall: 'send', Oct 04 16:11:16 volumiofr volumio[25663]: address: '255.255.255.255', Oct 04 16:11:16 volumiofr volumio[25663]: port: 3483 Oct 04 16:11:16 volumiofr volumio[25663]: } Oct 04 16:11:16 volumiofr volumio[25663]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 16:11:17 volumiofr dhcpcd[740]: wlan0: leased 192.168.254.122 for 86400 seconds Oct 04 16:11:17 volumiofr avahi-daemon[651]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.254.122. Oct 04 16:11:17 volumiofr avahi-daemon[651]: New relevant interface wlan0.IPv4 for mDNS. Oct 04 16:11:17 volumiofr dhcpcd[740]: wlan0: adding route to 192.168.254.0/24 Oct 04 16:11:17 volumiofr avahi-daemon[651]: Registering new address record for 192.168.254.122 on wlan0.IPv4. Oct 04 16:11:17 volumiofr dhcpcd[740]: wlan0: adding default route via 192.168.254.254 Oct 04 16:11:17 volumiofr sudo[25887]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-04 16:10 Oct 04 16:11:17 volumiofr sudo[25887]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 08:41:12 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8e78a6e3f56f1bcbbd1760812129a8e9"